多段fluentd + mongodb のハマリ所

fluentdを多段構成にして、mongodbに出力するところでハマったのでメモ。

上の構成のように、各サーバにfluentd + out_forwardを置き、集約するログサーバにfluentd + out_mongoでmongodbに出力している場合に、上段のfluentdでbuffer_chunk_limitを10mより大きい値にしていると、エラーになることがあります。

まず、out_mongoでbuffer_chunk_limitを10m以内にしないといけない理由は、fluentdからMongoDBへ連携する際の注意点 #fluentdを参考にしてください。

ここで多段構成の場合、上流の buffer_chunk_limitが大きいと上流から大きなサイズのデータの塊が流れてくることがあります。それを受けとったfluentdはそれをそのままoutput pluginに流す実装となっているようです。そのため、末端のout_mongoだけ buffer_chunk_limit 10m としていても、上流から来たデータの塊をそのままmongodbにinsertしようとして、エラーとなるようです。

ちなみにこの場合のエラーメッセージとしては以下のようなものが出てきます。"next retry will be"といってますが、chunkが分割されるわけではないので、永遠に失敗し続けるわけです。

2013-02-22 13:46:56 +0900 [warn]: temporarily failed to flush the buffer, next retry will be at 2013-02-22 13:46:58 +0900. error="Exceded maximum insert size of 16,000,000 bytes" instance=260250280 time=1361508416

対策としては、末端にout_mongo (や、buffer_chunk_limit に制限を加える必要があるplugin)を使う場合、その上流の全てのfluentdでその上限値(out_mongoの場合 10m)に設定する必要がある、ということになりそうです。

設定を修正した後は、mongodbで8000lines/secぐらいまでの性能は確認できました。ちなみにこの時のIOPSが400〜500ぐらいだったので、IO性能はまだまだいけそう。前の記事でmongodbのinsert性能が低いような話を書きましたが、原因は別のところにあったので訂正します。

修正後の設定は以下のようになります。上流のfluentdのbuffer_chunk_limitもきっちり10mにしておきましょう!

  • 上流サーバ
<source>
  type tail
  format ltsv
  path /var/log/httpd/access_log.ltsv
  tag proxy.access_log
  pos_file /var/tmp/fluent.log.pos
</source>

<match **>
  type forward

  buffer_type memory
  # buffer_chunk_limit must be under 10m if out_mongo is used in downstream.
  buffer_chunk_limit 10m
  buffer_queue_limit 128
  flush_interval 1s
  retry_limit 10
  retry_wait 5s
  send_timeout 5s
  recover_wait 5s
  heartbeat_interval 1s
  phi_threshold 10
  hard_timeout 10s
  <server>
    host fluentd
    port 24224
  </server>
</match>
  • ログサーバ
<source>
  type forward
  port 24224
  bind 0.0.0.0
</source>

<match **>
  type mongo
  tag_mapped

  capped
  capped_size 10m

  nodes mongod
  database fluent
  collection debug

  buffer_type memory
  buffer_chunk_limit 10m
  buffer_queue_limit 1280
  flush_interval 1s
  retry_limit 10
  retry_wait 5s
</match>

fluentd + mongodb+ node.js でリアルタイムにグラフを描く

追記 2/22

毎回微妙に追記していますが、今回も追記です。最後にmongodbのinsert性能について80lines/secで厳しくなった、と書いてますが、環境か設定まわりがあやしいので訂正します。もうすこし検証してみようと思います。 → 検証して fluentd側の設定の問題であることが分かりました。詳しくは、http://blog.stanaka.org/entry/2013/02/22/171053

追記ここまで

最近は、fluentd + mongodb でログを蓄積していろいろ便利に使っているわけですが、数分に一回集計スクリプトを周したり、 GrowthForecast の画面をリロードしまくるのではなく、もっとリアルタイムで見たい! という欲求が募ってきたので、 node.js を使って実装してみました。( https://github.com/stanaka/realtime-log-visualization )

mongodb の Tailable cursor

fluentd からのログを(ほぼ)リアルタイムにブラウザ上に出すという実装は、これまでに mongodb + node.js を使って、 polling して最新のデータの取得を取得したり、 mongo-tail で一旦ファイルに書き出したり、という手法が実装されてきたようです。が、それらの実装では効率が良いとは言えず、またもっとリアルタイムにしたいので、より直接的に繋げたいですよね。

ここで mongodb のドキュメントを良く見てみると Capped collection に対して、 Tailable cursor という仕組みで、その collection への追加レコードを push で受け取ることができる機能があったので、それを利用してみます。そもそもこの Tailable cursor は、Unixコマンドの tail -f にインスパイアされたものとのことで、まさに期待する機能です。

今回は proxy のログを受け取って、ステータスコードごとのrequests/secをグラフ化するツールにしてみました。システム構成は、 となります。proxyからmongodbまでは、当然 proxy のログを LTSV形式 で出力して、そのまま mongodb に突っ込むのが基本ですね。

node.js から mongodb に接続するには mongoose を使います。 node.js からブラウザへデータを push するために WebSocketではなく、 SSE (Sever-sent event) を使ってみました。グラフの描画は、データをどんどん追加していけるグラフ描画ライブラリの Rickshaw を使ってみました。

コードを見る

コードは、 https://github.com/stanaka/realtime-log-visualization にありますが、主要部分を見ていきます。まず、SSEでデータのpushを受け取るエンドポイントは "/update" としています。tailable で最新レコードを追い掛けるためにも、まずはその時点での最新のレコードを取得します。

exports.update = function(req, res) {
  req.socket.setTimeout(Infinity);

  var stream;
  Log.findOne().sort({_id:-1}).slaveOk().exec(function(err, item){

そこから tailable を指定して、 stream を起こします。ここで、 gt で最新のレコードを指定しておかないと、頭から全レコードが push されて悲惨なことになるので注意しましょう。

    stream = Log.find().gt('_id', item._id).sort({'$natural': 1}).tailable().stream();

stream からデータを受け取ったら、 SSE でブラウザに push します。

    var messageCount = 0;

    stream.on('data', function(doc){
      messageCount++;
      res.write('id: ' + messageCount + '\n');
      var msg = JSON.stringify({
        status: doc.status,
        reqtime:  doc.reqtime,
        req:    doc.req
      });
      res.write("data: "+msg+"\n\n");
    });
  });

あとは、SSE コネクションの確立処理と、切断時の対処を書いておきます。

  res.writeHead(200, {
    'Content-Type': 'text/event-stream',
    'Cache-Control': 'no-cache',
    'Connection': 'keep-alive'
  });
  res.write('\n');
 
  req.on("close", function() {
    stream.destroy();
  });
});

クライアント側では、EventSource オブジェクトを作って、 SSE で push されるのを待ち受けます。データが push されたら、グラフに描画します。

script(src='http://ajax.googleapis.com/ajax/libs/jquery/1.4.2/jquery.min.js')
script(src='http://jquery-json.googlecode.com/files/jquery.json-2.2.min.js')
...
script(type='text/javascript')
  var source = new EventSource('/update');
 
  source.addEventListener('message', function(e) {
    var data = JSON.parse(e.data);

    if(s = (data.status.match(/^(\d)/))[0]){
      counter[s] = counter[s] == null ? 0 : counter[s] + 1;
    };
    var now = new Date().getTime() / 1000;
    if(now > last_render + tv){
      var data = {
        "2xx": counter[2],
        "3xx": counter[3],
        "4xx": counter[4],
        "5xx": counter[5]
      };
      counter = new Array();
      last_render = now;

      graph.series.addData(data);
      graph.render();

実行画面はこんな感じです。時間とともに、リアルタイムにグラフが描画されていきます。データは、テスト用データを生成する generate_data.js から mongodbに挿入させています。

もうちょっとちゃんと実装すれば、アプリケーションのデプロイ時や障害発生時など、状況の変化をできるだけ早く把握したい場合に使える技になりそうです。

mongoose の Tailable cursor は、 node.js の stream で実装されているので、 polling に比べて負荷も低く、シンプルで美しい実装ですね。この実装をベースに、 fluentd + mongodb からのリアルタイムビジュアライゼーションをいくつか試してみようと思います。

まとめ

  • fluentd + mongodb + node.js でリアルタイムでグラフを描画させてみました
  • mongodb の tailable を利用した stream による実装でシンプルで効率的です
  • これでサーバーでのLTSVでのログ出力から、手元のブラウザでのグラフ描画まで一気通貫ですね!

このシステムで proxy のログの一部を 800 lines/sec ぐらいの勢いで流したら、 mongodb のところで一瞬で詰 ってしまいました。SSD を搭載したサーバにしておいたのに! 仕方ないので、 fluent-plugin-sampling-filter で流量を10分の1ぐらいにして凌ぎました。やはり mongodb のところがボトルネックになりますね。 ← ここのmongodbのinsert性能上限のところは数字があやしいので、訂正します。詳しくはコメント覧の議論を参照ください。 → 検証して fluentd側の設定の問題であることが分かりました。詳しくは、こちらも参照ください http://blog.stanaka.org/entry/2013/02/22/171053

流量の多いところで使うには、ここのボトルネックの解消が絶対に必要なので、よりパフォーマンスの高い方法を探ろうと思います。

Emacsからオフラインで使えるリファレンスブラウザDashを呼び出す

追記 2/17

現在のmajor-modeに対応して、検索対象のdocsetが絞りこまれるようにしました。以下のようにカスタマイズすることもできます。

(add-to-list 'dash-at-point-mode-alist '(perl-mode . "perl"))

追記ここまで

OSXで開発している時に各言語やライブラリのリファレンスをオフラインで検索したい、とTweetしたところ、

とid:naoyaさんにお勧めしてもらったDashを試してみました。各言語、ライブラリのリファレンスが簡単にダウンロードでき、それをオフラインで高速に検索できて、これは良いですね。

Dashのスクリーンショットはこんな感じです。

f:id:stanaka:20130218134501p:plain

Windows時代のころは、chmという複数のhtmlファイルを一つにまとめた形式があって、各種リファレンスをまとめるのに都合が良いものでした。ただ、OSXでは、良さげなクライアントが見つからず、あきらめて、毎回ググってましたが、相当ストレスでしたからね。それが改善されて、捗ります。

この調子で便利に使っていると、いつも使っているエディタ、Emacsと連携させたくなります。幸いDashでは、

open dash://{query}

とするとコマンドラインから検索できる、とのことです。というわけで、久し振りにEmacs Lispを書いてみました。dash-at-point.elというものです。カーソル下のワードをDashで検索できます。これで、コードを書き/読みながら、リファレンスを引きたくなった時にさくっと引けます。

ソースは https://github.com/stanaka/dash-at-point にあります。以下を".emacs"に書くと使えます。

(add-to-list 'load-path "/path/to/dash-at-point")
(autoload 'dash-at-point "dash-at-point"
          "Search the word at point with Dash." t nil)
(global-set-key "\C-cd" 'dash-at-point)

最近は、EmacsもPackage systemに乗るのが流行りのようなので、MELPAにでもpull requestでも送ってみるのがよいですかね。

ログをLTSVやJSONで保存した場合のサイズ比較

追記(2/17)

変換スクリプトを見せてほしい、という要望があったので、 https://gist.github.com/stanaka/4967403 に上げておきました。ltsvを読み込んでオプションで指定したフォーマット(デフォルト JSON)に変更します。

追記ここまで

LTSVの盛り上りも収束してきていますが、サイズに関する懸念があがっていたので、確認してみました。

手近にあったアクセスログ 186万件ほどを対象に、

  • ssv .. Combined Log Formatの拡張で、ラベルなし (レスポンス時間とか10個ぐらいのフィールドを拡張しています)
  • json .. ラベルあり
  • ltsv .. ラベルあり

の3パターンで試してみました。

まずは行数を確認しておきます。

% wc -l access_log.json
1861706 access_log.json

未圧縮だと、

access_log.ssv    818,729,505 (781M)
access_log.json 1,282,452,709 (1.2G)
access_log.ltsv 1,111,017,347 (1.1G)

でした。1G前後でそれなりのサイズのログですね。ssvとltsvの差は300M程度。jsonにするとさらに150Mぐらいでかくなってます。

最初にgz圧縮してみると、

access_log.ssv.gz  136,835,984 (131M)
access_log.json.gz 152,432,366 (146M)
access_log.ltsv.gz 146,072,000 (140M)

131M〜146Mでだいぶ差が縮まりました。1割程度の差を問題視するかどうかはポリシー次第ですが、最近では1割程度は誤差なんじゃないかと思います。

さらにbz2圧縮してみると、

access_log.ssv.bz2   93,621,212 (90M)
access_log.json.bz2 100,358,979 (96M)
access_log.ltsv.bz2  98,269,135 (94M)

と差は5%とさらに縮まりました。スペースを気にしつつ、bz2の圧縮時間に耐えられるなら、これもアリだと思います。

ついでなので、7z圧縮してみました。manの例にも載ってた推奨(?)のオプションでやってみました。

7z a -t7z -m0=lzma -mx=9 -mfb=64 -md=32m -ms=on access_log.ltsv.7z access_log.ltsv

結果は、

access_log.ssv.7z  71,518,534 (69M)
access_log.json.7z 79,827,214 (77M)
access_log.ltsv.7z 77,032,835 (74M)

という感じで、さらに小さくなりました。差はbzip2に比べると、むしろ広がってますね。

まとめ

伝統的なCombine Log Formatの拡張、JSON, LTSVで比べてみましたが、JSON, LTSVともに圧縮すれば1割程度の増加で済むので、JSONにせよLTSVにせよ、気にせずにラベルを付けて、使い勝手重視で行くのがよいんじゃないでしょうか。