fluentdでは、v0.10.45から複数行にまたがるログをparseするための機能 multiline parser が実装されているようです。multiline parserを使えば、railsやその他様々なアプリケーションで複数行にまたがるログを１つのイベントとして扱うことができます。ここでは、in_tailプラグインでformatにmultilineを指定してrailsアプリケーションのログのパースを試してみたいと思います。
tailプラグインでrailsアプリケーションのログをパースして見る
tailプラグインでは、multilineの指定をformatオプションを使って指定します。
|
1 |
format multiline |
multiline parser[1]https://github.com/fluent/fluentd/blob/master/lib/fluent/parser.rbでは、formatNとformat_firstlineというオプションを指定することができます。formatNのNは、1〜20の範囲で指定可能となっています。format_firstlineは、複数行のログの開始位置を示す表現を指定することになっています。
公式のドキュメントのRailsアプリケーションのformat例を参照しながら設定を書いて見ると以下のようになりました。長く複雑な正規表現指定となっているので、私のように自信のない方は公式のサンプルを参照しながらカスタマイズした方が良いかもしれません。
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 |
<source> type tail format multiline format_firstline /^Started/ format1 /Started (?<method>[^ ]+) "(?<path>[^"]+)" for (?<host>[^ ]+) at (?<time>[^ ]+ [^ ]+ [^ ]+)\n/ format2 /Processing by (?<controller>[^\u0023]+)\u0023(?<controller_method>[^ ]+) as (?<format>[^ ]+?)\n/ format3 /( Parameters: (?<parameters>[^ ]+)\n)?/ format4 / Rendering .+\n/ format5 / Rendered (?<template>[^ ]+) within (?<layout>[^ ]+) \([\d\.]+ms\)\n/ format6 /Completed (?<code>[^ ]+) [^ ]+ in (?<runtime>[\d\.]+)ms \(Views: (?<view_runtime>[\d\.]+)ms \| ActiveRecord: (?<ar_runtime>[\d\.]+)ms\)/ path /workspace/railsapp/log/development.log pos_file /data/tmp/rails.pos tag rails.development.log read_from_head true </source> |
この設定を送信側のfluentdに加えた上でrailsアプリケーションを起動しアクセスしてみます。この時、development.logに出力されるログは例えば以下のようになります。
|
1 2 3 4 5 6 |
Started GET "/hello?hoge=foo" for 127.0.0.1 at 2016-11-04 23:24:10 +0900 Processing by HelloController#index as HTML Parameters: {"hoge"=>"foo"} Rendering hello/index.erb within layouts/application Rendered hello/index.erb within layouts/application (0.3ms) Completed 200 OK in 13ms (Views: 11.4ms | ActiveRecord: 0.0ms) |
送信側で正しくパースされていれば、受信側のfluentdで以下のようなイベントを受信できているのを確認できます。複数行にわたるログを１つのメッセージとして受信できているのがわかります。どうやら上手くいっているようです。
|
1 |
2016-11-04T23:24:10+09:00 rails.development.log {"method":"GET","path":"/hello?hoge=foo","host":"127.0.0.1","controller":"HelloController","controller_method":"index","format":"HTML","parameters":"{\"hoge\"=>\"foo\"}","template":"hello/index.erb","layout":"layouts/application","code":"200","runtime":"13","view_runtime":"11.4","ar_runtime":"0.0"} |
norikraでViewのレンダリングに最も時間のかかったテンプレートを探す
norikra[2]http://norikra.github.ioは、ストリームデータをSQLライクな問い合わせ言語で処理することができるソフトウェアです。ストリームデータを一定時間ごとに集計したり、ある閾値を超えるデータをチェックしたりといった処理を馴染みのあるSQLライクに記述することができるので大変便利です。また、スキーマレスでデータを柔軟に扱うことができるといった特徴もあります。
早速、norikraをインストールして試してみます。
|
1 2 3 |
rbenv install jruby-9.1.2.0 rbenv shell jruby-9.1.2.0 gem install norikra |
続いて起動してみます。
|
1 |
norikra start |
無事起動できていれば、Webブラウザでhttp://localhost:26578/にアクセスすると以下のようなWebUIを確認できます。以下の画面では、すでに私がクエリを登録しているのでQueriesにクエリが表示されています。
続いてnorikraにクエリを登録します。ここでは、1 minuteごとにViewのレンダリングで15.0 msecを超えるtemplateを抽出し、レンダリングにかかった最大時間と共に取り出すよう設定してみます。
fluentdのデータストリームでnorikraとやりとりするように、fluent-plugin-norikra[3]https://github.com/norikra/fluent-plugin-norikraをインストールします。続いて、norikraにイベントを送信し、結果を取り出す設定を追記します。
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 |
<match rails.**> @type norikra norikra localhost:26571 target_map_tag true # tag rails.log -> target rails_log in norikra </match> # Gets results from norikra via norikra api <source> @type norikra norikra localhost:26571 <fetch> method event target Slow rendered view tag string slow_rendered_view.1minute interval 60s </fetch> </source> |
railsアプリケーションに何回かアクセスしてみると、以下のようなnorikraの実行結果をfluentdで確認することができます。
|
1 |
2016-11-05T05:20:39Z slow_rendered_view.1minute {"template":"hello/index.erb","max_view_runtime":"20.2"} |
参考リンク
- fluentd tail Input plugin
- fluentd parser
- fluent-plugin-norikra
- http://hase.hateblo.jp/entry/2014/12/16/142250
脚注
| ↑1 | https://github.com/fluent/fluentd/blob/master/lib/fluent/parser.rb |
|---|---|
| ↑2 | http://norikra.github.io |
| ↑3 | https://github.com/norikra/fluent-plugin-norikra |
コメント