iscsi initiator+gjournalが固まるからの続き。
カーネルデバッグは敷居が高すぎて早々に諦めつつ、iSCSI+ZFSは使いたいので調査継続。
どうやらiSCSI TargetであるQNAP NAS、中身はLinux LIOが怪しい気がする。
8/8追記: iSCSIのCmdSNとInitiator Task Tagに関して誤りがあったので訂正。
まずは問題点を整理しておく。
手順と現象は以下の通り。
- FreeBSDのiSCSI InitiatorでQNAP NASのiSCSI Targetに接続する。
- 接続したiSCSI Target上にzpoolを作る。gnopでセクタサイズを4096にしてもしなくてもいい。
- 作成したzpool(zfs)にsync=alwaysを指定する。
- ddでがりがり書き込む。
元がアクセス速度調査なので、dd if=/dev/zero of=/dev/da1 bs=65536 count=4096とか。 - gstatで監視する。そんなに待たずにL(q)が1になって固まる。
詳しい現象は以下。
- ddはCtrl-Cで止められない。I/Oのsyscall中なので当たり前。
ちなみに下手なI/Oを発生させるとどんどん巻き添えになる。 - ハマったデバイスに読み込み要求を出すと(つぎにまたハマるまでの数秒から数十秒)復活する。
たとえばdd if=/dev/da1 of=/dev/null bs=512 count=1とか。 - iscsictl(引数なし)が固まる。これはFreeBSDのバグであろう。(興味が無いのでとりあえずスルー)
- rebootしようとするとどこかで固まる。(ディスプレイをつないでいないので分からないが、iscsidの停止か、Syncing Disksとかその辺であろう)
- QNAP NASのWeb管理コンソールから再起動させようとすると応答が無くなる。電源OFF→ONしかない。
最後の項目があるのでQNAP NASがダメになっているのは想像に難くない。
が、OpenIndiana(illumos)から同じ構成・パターンでテストすると起きないから困る。
そして、ついに (ぶちきれて)パケットキャプチャを取ってみたところ、はっきりとQNAP側が応答を返していないことが見えた。
まずは現象発生時のThroughput Graphから。
これはハマった状態から初めて、ちょこっと読み込みをさせて復活させて、少ししてやっぱりハマって、という流れ。
ここで解析するに当たっての事前知識も整理しておく。
iSCSIは要求-応答ペアを識別するために32-bitの数値を使う。RFC 3720では3.2.2.1節でCommand Sequence Numberと呼んでいるが、WiresharkはInitiator Task Tagと呼んでいる模様。
表示でEndianがひっくり返っているようだが、誰が悪いのかは知らない。とりあえずペアが識別できればよいので放っておこう。
8/8 編集:
iSCSIでは要求/応答にCmdSNやInitiator Task Tagをつけて識別している。何を使ってペアを識別しているのかはきちんと読んでいないので分からないが、Initiator Task Tagのほうが「それっぽい」のでとりあえずこっちを見てみることにする。
詳しく知りたい人はRFC 3720を読めばきっと15分くらいで分かる。
各パケットのTask Tagを見たいので、Column Configurationで追加しておく。
Customを選んで、Filterに入力するような式を投げ込めばいい。今回だとiscsi.initatortasktagになる。
これで見えるようになった。
さて、2つ目のThroughput Graphの復活しているところをクリックして、大体近くまで飛び、あとは少しずつ戻ってデータ転送が復活しているところを探す。(1つ目だと元の要求がキャプチャされてないから2つ目を選ぶ)
時間を見ると、どうやら13403フレームがたたき起こした読み込み要求で、13404フレームが今更な書き込み応答だ。
絞り込んでみると、いかにひどいことが起きているかがわかる。
これだけを見るとFreeBSDのInitiatorに非はないが、どうなんだろうか。
とりあえず、gnopでセクタサイズを8192にすると発生頻度が低くなる(というか今のところ起きていない)ので、それで凌ぐつもり。
またハマったり、気になったらどうにかしよう。