DataNodeで大量のINFOレベルメッセージが・・・

パッケージでインストールしていたCDH4.4から,新たにCloudera Manager Standard(以下CM)管理のクラスタ(CDH4.5)に切り替え,以前同様fluentdのwebhdfsプラグインからHDFSヘログをappendしたところ,予期せぬ現象が・・・。以前も出ていたのだろうか。。

WebHDFSの有効化

CDH4.5でwebhdfsを利用可能にするため,以下のように設定した。dfs.support.appendについては,デフォルトでtrueとなっているようだった。CM経由では,hdfsサービス > サービス全体 > WebHDFS の有効化にチェックがついていることを確認する。CMの場合,実際の設定ファイルを確認するには,/var/run/cloudera-scm-agent/process下のxxx-hdfs-(NAME|DATA)NODE/hdfs-site.xmlで確認できる。

<property>
  <name>dfs.webhdfs.enabled</name>
  <value>true</value>
</property>

その後,fluentdのwebhdfsプラグインを使ってWebHDFS API経由でHDFSへappendしたが,以下のようなINFOレベルのログが大量に出力されてしまう事態に遭遇。初めは,許容範囲かと思う程度だったけれど,段々と高頻度でメッセージが出力され,最終的にはtailでコンソールがログで埋め尽くされたしまう状態だった。INFOなので基本的には関与せずで問題ないかと思っていたが,ここまでくるとさすがに目をつぶってはいられない。しかも同じブロックIDっぽい。終了条件が満足されず無限ループから脱することができなくなっているように見える。

2013-12-14 19:43:27,315 INFO org.apache.hadoop.hdfs.server.datanode.BlockPoolSliceScanner: Verification failed for BP-1884185756-192.168.56.61-1386868289000:blk_6767085826644652312_3227 - may be due to race with write
2013-12-14 19:43:27,315 INFO org.apache.hadoop.hdfs.server.datanode.BlockPoolSliceScanner: Verification failed for BP-1884185756-192.168.56.61-1386868289000:blk_6767085826644652312_3227 - may be due to race with write
2013-12-14 19:43:27,315 INFO org.apache.hadoop.hdfs.server.datanode.BlockPoolSliceScanner: Verification failed for BP-1884185756-192.168.56.61-1386868289000:blk_6767085826644652312_3227 - may be due to race with write
2013-12-14 19:43:27,315 INFO org.apache.hadoop.hdfs.server.datanode.BlockPoolSliceScanner: Verification failed for BP-1884185756-192.168.56.61-1386868289000:blk_6767085826644652312_3227 - may be due to race with write
2013-12-14 19:43:27,315 INFO org.apache.hadoop.hdfs.server.datanode.BlockPoolSliceScanner: Verification failed for BP-1884185756-192.168.56.61-1386868289000:blk_6767085826644652312_3227 - may be due to race with write
...endless

HDFSサービスを再起動すると,

2013-12-14 19:47:48,196 INFO org.apache.hadoop.hdfs.server.datanode.BlockPoolSliceScanner: Verification succeeded for BP-1884185756-192.168.56.61-1386868289000:blk_-3356347841025830775_3014
2013-12-14 19:47:48,197 INFO org.apache.hadoop.hdfs.server.datanode.BlockPoolSliceScanner: Verification succeeded for BP-1884185756-192.168.56.61-1386868289000:blk_4628874247189544628_2090
2013-12-14 19:47:48,198 INFO org.apache.hadoop.hdfs.server.datanode.BlockPoolSliceScanner: Verification succeeded for BP-1884185756-192.168.56.61-1386868289000:blk_-4604910670704378034_2410
2013-12-14 19:47:48,198 INFO org.apache.hadoop.hdfs.server.datanode.BlockPoolSliceScanner: Verification succeeded for BP-1884185756-192.168.56.61-1386868289000:blk_-7109164516120744359_1972
2013-12-14 19:47:48,199 INFO org.apache.hadoop.hdfs.server.datanode.BlockPoolSliceScanner: Verification succeeded for BP-1884185756-192.168.56.61-1386868289000:blk_8643939950933092824_2738
2013-12-14 19:47:48,199 INFO org.apache.hadoop.hdfs.server.datanode.BlockPoolSliceScanner: Verification succeeded for BP-1884185756-192.168.56.61-1386868289000:blk_6253862976873385023_2476
2013-12-14 19:47:48,390 INFO org.apache.hadoop.hdfs.server.datanode.BlockPoolSliceScanner: Verification succeeded for BP-1884185756-192.168.56.61-1386868289000:blk_3109528374396350160_1968
2013-12-14 19:47:48,391 INFO org.apache.hadoop.hdfs.server.datanode.BlockPoolSliceScanner: Verification succeeded for BP-1884185756-192.168.56.61-1386868289000:blk_5513034803968839722_2388
2013-12-14 19:47:48,391 INFO org.apache.hadoop.hdfs.server.datanode.BlockPoolSliceScanner: Verification succeeded for BP-1884185756-192.168.56.61-1386868289000:blk_8992144293701346152_2344
2013-12-14 19:47:48,391 INFO org.apache.hadoop.hdfs.server.datanode.BlockPoolSliceScanner: Verification succeeded for BP-1884185756-192.168.56.61-1386868289000:blk_5242944229150517124_2678
...

のようなメッセージがつらつらと出力される。念のためブロック状態を確認するためhdfs fsckを実行したところHEALTHYと表示され,不良ブロックらしきも報告されない。それから,ファイルのappend自体は成功しているように見える。

なんとくWebHDFS経由でのファイルappendに関連していると思われるので,fluentd側を1 collector,1 webhdfsで設定しHDFSへの書き込みの状況を観察する。

まず,appendをすべてcreateのみにしてみる。fluentdのwebhdfsプラグインの設定で,append noにしてみたところ,Verification failed for xxxxのようなメッセージは確認されなかった(テスト条件にもよると思うので一概には言えないかもしれないが)ので,appendに起因すると推測する。append noなので,毎回新しいファイルが作成される。ここでは,chunk_idごとに一意なファイルとなる。

次に,単一のcollectorからのappendでのHDFSへの書き込みを行ない様子を見る。flush_intervalを20sで設定してみたところ,上記ほどのレベルでないが同メッセージの出力が確認されることがある。flush_intervalを短くするとその頻度は高くなるようだった。

CDH4.4でも同様だったかダウングレードして同様な条件で試してみたところ,少なくともINFOレベルでの上記のようなメッセージが見られなかったので,CDH4.5へのアップグレードによるものか?ソースを見てみたが,さすがに簡単に特定はできなさそうだ。。

結局,今回はCDH4.4にダウングレードして様子を見ることとしたが,メッセージが出力されないだけで根本的な解決には至っていない気がするが。。

参考

byebyehaikikyou

日記やIT系関連のネタ、WordPressに関することなど様々な事柄を書き付けた雑記です。ITエンジニア経験があるのでプログラミングに関することなどが多いです。

シェアする

コメントを残す

メールアドレスが公開されることはありません。 * が付いている欄は必須項目です

コメントする

Translate »