fluent-logger について

fluentd

こんにちは。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版も対応してみても良いかな、などなど。

fluent-logger-ocaml

前述のfluent-logger軍団を見ていたらOCaml版が無いことに気がついたので、枠を埋める意味合いで作ってみました。

komamitsu/fluent-logger-ocaml

再接続の間隔をよろしくやってくれる機能はまだ付けてない（送信の度に毎回再接続を試みてしまう）のですが、それ以外はそれっぽく動くような気がします。あとテストが無くて意識の低さを露呈した感じになっています。MessagePackのシリアライズには mzp さんの msgpack/msgpack-ocaml を使わせて頂きました。型！


明日は katzchang さんです。

OCatraをLwt使うようにした

OCaml

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()の違い

Java Android

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()が遅い件

Java andriod

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でも大体同じ。

I/XXXX    (28542): CharsetDecoder.decode(): 4366
I/XXXX    (28542): String(byte[]): 1471

同等のコードをDalvik VM上で動かしたら（ループの回数は1/100に減らした）、結果が逆転した。ちょうど三倍程度、CharsetDecoder.decodeの方が遅くなった。

この辺がmsgpack-javaをAndroid上で動かすと遅くなる件と関係あるのかも。ないのかも。

型変換テンプレートで変換する際、中間オブジェクトを生成しないようにした

MessagePack Android

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の簡単なベンチマークをとってみた

MessagePack Android

使ったコードはこちら => https://github.com/komamitsu/AndroidMsgpackBenchmark/blob/master/src/com/komamitsu/android/msgpackexample/MsgpackExampleActivity.java

ベンチの概要としては、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
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

あと、三回程度繰り替えしても大体同じ結果。



結果の概要：

まだあんまりMessagePackの仕様について把握して無いので、もうちょっと原理を抑えてから再度試みてみたい（そして眠りたい）。あと、別の要因がからんでいるかも、とか。