fluent-logger について
こんにちは。Fluentd Advent Calendar 11日目担当の @komamitsu です。ワイワイ。
Fluentd Advent Calendarにノリで登録したもののfluentd本体やプラグインに余り関わっていないので途方に暮れていましたが、fluent/fluent-logger-java のメンテナンスをしていることもあり、fluent-logger周りのことを書いてやりすごしたいと思います。
fluent-logger-javaの一年
地味な見出しですね。自分でも書いてみて素でちょっと引きましたが、とりあえずfluent-logger-javaに関連した出来事などを...
いくつか細かいバグの修正や改善を入れていますが、その中でもTCP切断後の再接続処理やタイムアウトの問題が改善されているので、地味に使いやすくなっていると思います。
MLより。複数のfluentdに対して障害時のfailover、またはメモリバッファが一杯になったらファイル書き出し出来ないの?fluentdのメンテ中にメモリバッファがあふれちゃうよ的な話。確かに一理ある要望(まだ対応できてませんが...)
実のところ、TDでは全てのサーバーにfluentdがいて、アプリからは自サーバーのfluentdに投げているのであまり接続周りで困ったことがないんですよね... なので違う構成で利用されている方で困っているケースがあれば色々と知りたいなぁと思ってる次第です。
あとJavaのlog frameworkとの連携に関する要望とかもたまに目にしますねぇ。需要がどの程度あるのか気になります。
他のfluent-loggerとの比較
fluent-logger-javaは万一送信先のfluentdに送信出来なくてもメモリ上でバッファリングを行い、次回以降の送信成功時にまとめて送るようになっています。しかし、前述の "じゃあメモリバッファに書ききれなくなったらどうするの?ディスクに書き出すの?fluentdの接続先を変えてくれるの?" という要望には答えきれてないように思いました。そこで、他のfluent-loggerはどんな感じなのか気になったのでざっとコードを眺めてみました。
切断後の再接続の有無 | 再接続がexponential backoff? | 送信失敗時のデータ保持 | socket domain | ||
---|---|---|---|---|---|
Java | fluent/fluent-logger-java | yes | yes | yes | INET |
Ruby | fluent/fluent-logger-ruby | yes | yes | yes | INET |
Python | fluent/fluent-logger-python | yes | no | yes | INET,UNIX |
Perl | fluent/fluent-logger-perl | yes | yes | yes | INET,UNIX |
PHP | fluent/fluent-logger-php | yes | yes | no | INET,UNIX |
Node.js | fluent/fluent-logger-node | yes | no | yes | INET |
D | fluent/fluent-logger-d | yes | yes | yes | INET |
Scala | oza/fluent-logger-scala | yes | yes | yes | INET |
Haskell | notogawa/fluent-logger-haskell | yes | no | yes | INET |
OCaml | fluent/fluent-logger-ocaml | yes | yes | yes | INET,UNIX |
C | roadman/fluent-logger-c | no | - | no | INET |
C++ | todayman/fluent-logger-cpp | no | - | yes | INET |
C# | zoetrope/fluent-logger-csharp | yes | no | yes | INET |
Lua | ngigroup-developer/fluent-logger-lua | no | - | no | INET |
# Haskellもあったけど眠気の限界。気力があったら後で追加します...notogawaさんから教えて頂きHaskell版追記しました。thanks!
# 全体的にざっと眺めただけ&上記全ての言語についてちゃんと理解しているかというとそうではないので、間違っていたらご指摘頂けると幸いです。
全てのfluent-loggerでfluentdとの接続を保持しており、毎回接続しなおさないようになっていますが、それ以外は結構違いがあって面白いです。fluent-loggerのほうでどこまで頑張るか、呼び元のほうで頑張るかなど思想の違いもありそうです。(2013-12-11 思い出したので追記 ->) それ以外にも、Perl版ではfork()されたプロセスではsocketを共有せずに自分で開き直すような処理があったりして、そういう渋い工夫を見るのも楽しいですね。
ちなみに、複数のfluentdに接続してfailoverしたり、メモリバッファが溢れたらディスクに書き込む機能はどれもありませんでした。意外とそれで困るケースはすくないのかな。
一点気になったのが、いくつかのfluent-loggerではsocketへの書き込みのみを続けているっぽいので、fluentdが万一落ちたときにFINパケットが飛んで来ても気がつかないケースがありそうかなと。select()的なことをしてread()して0byteであったら切断を検知, またはnon-blockingでread()してEAGAINを期待する、ということが必要な気がしました。fluent-logger-rubyだと毎回別socketで接続しているようで、これであればFINを送る間もなく切断した場合でも検知出来るなー、でもちょっとコストが心配だなーと色々面白いです。
あと、自分では計測していないのですが、UNIX domainソケットのほうが性能が出るっぽい話も聞くので、優位な差がありそうであればJava版も対応してみても良いかな、などなど。
OCatraをLwt使うようにした
OCatraをいろいろ直したり、ベンチマークとってみたり - komamitsu.log で作っていたOCamlのおもちゃ的Webサーバー OCatraをLwtを使うように修正してみた。
1st | 2nd | 3rd | 4th | Ave. | |
---|---|---|---|---|---|
OCatra (byte) | 4238 | 4424 | 4299 | 4285 | 4311 |
OCatra (opt) | 11806 | 12384 | 12381 | 12063 | 12158 |
bytecode版で1.5倍程度、native版で3倍程度高速になってうれしい。
nginxもついでに測ってみたのだけど、nginxのほうが倍近く速くて悔しい...
Androidでのnew String(byte[])とCharsetDecoder.decode()の違い
byte[] -> String 変換のパフォーマンス、とAndroidでCharsetDecoder#decode(ByteBuffer in).toString()が遅い件 - komamitsu.log でAndroidではnew String(byte)の方が速い結果が出たので[https://github.com/OESF/OHA-Android-4.0.3_r1.0:title=コード]を見てみた。
すると、CharsetDecoder.decode()ではICU Library(IBMの人が作ったunicode用ライブラリ)を使っているが、new String(byte, "UTF-8")の方は自前で手抜きしつつガリガリconvertしていた。なので、new String(byte)の方が高速で低機能なのではないかと思われ。
追記:
OpenJDK6のコードを見たら、CharsetDecoderの方はICUを使わずに自前でガリガリ。new String(byte)の方はCharsetDecoder#decodeを使ってた。
byte[] -> String 変換のパフォーマンス、とAndroidでCharsetDecoder#decode(ByteBuffer in).toString()が遅い件
Android上でMessagePackのベンチマークコードを動かしつつprofile取ってみたら、msgpack-java/src/main/java/org/msgpack/unpacker/StringAccept.java at master · msgpack/msgpack-java · GitHub辺り(CharsetDecoder#decode(ByteBuffer in).toString())でほとんどの時間が掛かっているなぁ、という感じ。
で、そもそも new String(byte[] byte, String charsetName) と CharsetDecoder#decode(ByteBuffer in).toString() でどれくらい性能があるのか気になったので計測してみた。確か、new String(...) の内部で CharsetDecoder#decode() してるというのは以前調べたことがあったので、今回はどの位違ってくるのか?という点に着目。
public static void main(String[] args) throws IOException { String src = "あいうえおアイウエオアイウエオaiueoAIUEO"; byte[] raw = src.getBytes(); ByteBuffer byteBuffer = ByteBuffer.wrap(raw); Charset cs = Charset.forName("UTF-8"); int until = 10000000; long start = System.currentTimeMillis(); for (int i = 0; i < until; i++) { cs.newDecoder().decode(byteBuffer).toString(); } System.out.println("CharsetDecoder.decode(): " + (System.currentTimeMillis() - start)); start = System.currentTimeMillis(); for (int i = 0; i < until; i++) { new String(raw, "UTF-8"); } System.out.println("String(byte[]): " + (System.currentTimeMillis() - start)); }
こんなのを書いて動かして見たところ...
CharsetDecoder.decode(): 720 String(byte[]): 2367
ざっと3倍位new String(byte[] byte, String charsetName)のほうが遅かった。OpenJDK 1.6でも大体同じ。
- Android OS 4.2
I/XXXX (28542): CharsetDecoder.decode(): 4366 I/XXXX (28542): String(byte[]): 1471
同等のコードをDalvik VM上で動かしたら(ループの回数は1/100に減らした)、結果が逆転した。ちょうど三倍程度、CharsetDecoder.decodeの方が遅くなった。
型変換テンプレートで変換する際、中間オブジェクトを生成しないようにした
Android上でJSONとMessagePackの簡単なベンチマークをとってみた - komamitsu.log の続き。
http://syuki.skr.jp/files/201204041/furuhashi-master-last-iso-pdfa.pdf を読んだところ、Unpacker.read(Class
use unpacker.read(Class<T>) · ea24660 · komamitsu/AndroidMsgpackBenchmark · GitHub
Android2.2 | Android4.2 | ||
Array S | JSON | 6421 | 2818 |
Msgpack | 14636 | 1121 | |
Array D | JSON | 1423 | 597 |
Msgpack | 16284 | 6300 | |
Msgpack: Unpacker.read(Class |
7458 | 4167 | |
Map S | JSON | 3282 | 1894 |
Msgpack | 19394 | 1117 | |
Map D | JSON | 1044 | 614 |
Msgpack | 17350 | 7754 | |
Msgpack: Unpacker.read(Class |
8676 | 5223 |
結果は、デシリアライズの速度が前回のJSON:Msgpack=10~17:1という結果から, JSON:Msgpack=8:1と改善。
Android上でJSONとMessagePackの簡単なベンチマークをとってみた
ベンチの概要としては、100byte x 50000の配列、100byte(value) x 30000の辞書をJSON, MessagePackでシリアライズ・デシリアライズしてどんなもんか見てみようかと。
- Android2.2(IS06)の場合
I/MsgpackExampleActivity ( 8963): benchmarkJsonArray: serialize start I/MsgpackExampleActivity ( 8963): benchmarkJsonArray: serialize end :6421 I/MsgpackExampleActivity ( 8963): benchmarkJsonArray: deserialize start D/MsgpackExampleActivity ( 8963): benchmarkJsonArray: size=50000 I/MsgpackExampleActivity ( 8963): benchmarkJsonArray: deserialize end :1423 I/MsgpackExampleActivity ( 8963): benchmarkJsonMap: serialize start I/MsgpackExampleActivity ( 8963): benchmarkJsonMap: serialize end :3282 I/MsgpackExampleActivity ( 8963): benchmarkJsonMap: deserialize start D/MsgpackExampleActivity ( 8963): benchmarkJsonMap: size=30000 I/MsgpackExampleActivity ( 8963): benchmarkJsonMap: deserialize end :1044 I/MsgpackExampleActivity ( 8963): benchmarkMsgpackDynamicArray: serialize start I/MsgpackExampleActivity ( 8963): benchmarkMsgpackDynamicArray: serialize end :14636 I/MsgpackExampleActivity ( 8963): benchmarkMsgpackDynamicArray: deserialize start I/MsgpackExampleActivity ( 8963): benchmarkMsgpackDynamicArray: deserialize end :16284 I/MsgpackExampleActivity ( 8963): benchmarkMsgpackDynamicMap: serialize start I/MsgpackExampleActivity ( 8963): benchmarkMsgpackDynamicMap: serialize end :19394 I/MsgpackExampleActivity ( 8963): benchmarkMsgpackDynamicMap: deserialize start I/MsgpackExampleActivity ( 8963): benchmarkMsgpackDynamicMap: deserialize end :17350
- Android 4.2 (Nexus7)
I/MsgpackExampleActivity (20424): benchmarkJsonArray: serialize start I/MsgpackExampleActivity (20424): benchmarkJsonArray: serialize end :2818 I/MsgpackExampleActivity (20424): benchmarkJsonArray: deserialize start D/MsgpackExampleActivity (20424): benchmarkJsonArray: size=50000 I/MsgpackExampleActivity (20424): benchmarkJsonArray: deserialize end :597 I/MsgpackExampleActivity (20424): benchmarkJsonMap: serialize start I/MsgpackExampleActivity (20424): benchmarkJsonMap: serialize end :1897 I/MsgpackExampleActivity (20424): benchmarkJsonMap: deserialize start D/MsgpackExampleActivity (20424): benchmarkJsonMap: size=30000 I/MsgpackExampleActivity (20424): benchmarkJsonMap: deserialize end :614 I/MsgpackExampleActivity (20424): benchmarkMsgpackDynamicArray: serialize start I/MsgpackExampleActivity (20424): benchmarkMsgpackDynamicArray: serialize end :1121 I/MsgpackExampleActivity (20424): benchmarkMsgpackDynamicArray: deserialize start I/MsgpackExampleActivity (20424): benchmarkMsgpackDynamicArray: deserialize end :6300 I/MsgpackExampleActivity (20424): benchmarkMsgpackDynamicMap: serialize start I/MsgpackExampleActivity (20424): benchmarkMsgpackDynamicMap: serialize end :1117 I/MsgpackExampleActivity (20424): benchmarkMsgpackDynamicMap: deserialize start I/MsgpackExampleActivity (20424): benchmarkMsgpackDynamicMap: deserialize end :7754
眠いので結果に関しては整形して見やすくしたりしない方向で....
自分でも見づらかったので整形 (単位はmsec)。
Android2.2 | Android4.2 | ||
Array S | JSON | 6421 | 2818 |
Msgpack | 14636 | 1121 | |
Array D | JSON | 1423 | 597 |
Msgpack | 16284 | 6300 | |
Map S | JSON | 3282 | 1894 |
Msgpack | 19394 | 1117 | |
Map D | JSON | 1044 | 614 |
Msgpack | 17350 | 7754 |
あと、三回程度繰り替えしても大体同じ結果。
結果の概要:
- Android2.2かつ低スペックのIS06ではJSONの方が総じて速かった。シリアライズが2.5〜6倍程度、デシリアライズが10〜16倍程度。
- Android4.2で高スペックのNexus7ではシリアライズに関してはmsgpackのほうが2倍程度速く、デシリアライズに関してはJSONのほうが10倍程度速かった。
- MessagePack on Androidはデシリアライズが結構遅め?
まだあんまりMessagePackの仕様について把握して無いので、もうちょっと原理を抑えてから再度試みてみたい(そして眠りたい)。あと、別の要因がからんでいるかも、とか。