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