読者です 読者をやめる 読者になる 読者になる

たごもりすメモ

コードとかその他の話とか。

ruby 2.1.0-preview1 を fluentd で試してみた (追記あり) (再度追記あり)

2.1.0-preview1 が出た。RGenGCはそのロジックがいかにもFluentdにジャストフィットしそうなので期待していた。あとGCまわりも含めあれこれ変わってるので、使うと事故るなら早めに確認しておこうかな、という感じ。
確認したノードは以下の2種類で1台ずつ。

  • fluentd + out_exec_filter (+perlの外部プロセス) でログをparseするworker
  • fluentd で大量のクライアント(fluent-agent-liteなど)から接続を受け付け、fluentdクラスタの各ノードへロードバランスするdeliver

で、本日の12:40くらいに変更したと思いねえ。そのグラフがこれ。トラフィックCPU使用率、メモリ使用量。

worker



起動するrubyのバージョンを変えてからぐんぐんメモリ使用量が伸びはじめ、見てるうちに物理メモリ量を突破しそうになったのであわてて戻した。
CPU使用率には特に変化なし。

deliver



こっちはメモリには影響なし、なんかのアクセスパターンの違いかなあ。msgpackほぼそのまま右から左に動かしてるだけだからかな。
CPU使用率も変化なし。

結論

なんか問題がありそうなので直るのを待ちたい。これが直ったという話があるまで 2.1.x は厳しいなあ。

本当は自分であれこれ調査すべきなんだけど、ちょっと他にも手元の作業があれこれあるので必要なら後から……。誰かこれとこれを調べろ! と指定してくださると調査がしやすいですが。

追記(9/26)

hsbtさんから助言をいただいたので試してみました。メモリ使用量の増大が見られたworkerでの結果です。

以下のグラフで16:30頃に ruby 2.1.0-preview1 w/o RGenGC なものに入れ替えてます。

結果として RGenGC を切ったものを再ビルドして試したところメモリ使用量の急激な増大は見られず、おおむね問題のない状況になってます。載せてませんがCPU使用率も 2.0.0 と変わらず。
ふーむ。

再度追記(9/27)

そのまま翌朝まで動かしてみたらやっぱりダメっぽい感じでした……。 Ruby 2.1.0-preview1 without RGenGC on worker node。

まあ RGenGC にたぶん問題があって、それ以外にもなんかありそうだね、という感じです。
Fluentd側のログはこんなで、どうにもならなくてFluentd supervisor processから SIGKILL だけですね。べつにバッファが食ってるとかいうわけじゃない*1

2013-09-26 19:37:06 +0900 [info]: out_forest plants new output: sampling_filter for tag '....'
2013-09-27 06:34:33 +0900 [info]: process finished code=9
2013-09-27 06:34:33 +0900 [error]: fluentd main process died unexpectedly. restarting.
2013-09-27 06:34:33 +0900 [info]: starting fluentd-0.10.39
2013-09-27 06:34:33 +0900 [info]: reading config file path="run/serializer.conf"
2013-09-27 06:34:34 +0900 [info]: using configuration file: <ROOT>
  <source>
    type forward
    ....

なおメモリを食ってるのはこのノード上にある serializer プロセス*2のみで、workerプロセス*3では同じ問題は起きてないようです。きっかけは今のところ不明。

### ps axuww の結果
# これがserializer
username 24191  0.0  0.0 119020  2536 ?        Sl   Sep26   0:00 ruby /home/username/local/ruby-2.1.0pre1patched/bin/fluentd -c run/serializer.conf --emit-error-log-interval 60
username 15219 21.7 45.0 11071856 7338252 ?    Sl   06:34  71:28 ruby /home/username/local/ruby-2.1.0pre1patched/bin/fluentd -c run/serializer.conf --emit-error-log-interval 60

# こっちは worker ひとセット
username 23743  0.0  0.0 118960  1716 ?        Sl   Sep26   0:00 ruby /home/username/local/ruby-2.1.0pre1patched/bin/fluentd -c run/worker.24211.conf --emit-error-log-interval 60
username 23746  7.1  0.5 914992 89708 ?        Sl   Sep26  83:20 ruby /home/username/local/ruby-2.1.0pre1patched/bin/fluentd -c run/worker.24211.conf --emit-error-log-interval 60
username 23757 11.7  0.0  36956  3488 ?        S    Sep26 137:29 perl -Iextlib/lib/perl5 -Ilib /home/username/secret_log_converter/bin/convert.pl

ロングランで分かることというのもあるなあ。

*1:そうなら emit transaction failed が残る

*2:WebHDFSへの送信などを行うプロセス

*3:out_exec_filterで外部プロセス(perl)を起動してパイプでやりとりするプロセス