fluentdで、1つのログから複数のメトリクスを得る。

ウィークリーFluentdユースケースエントリリレーの記事です。

「1つのログから複数のメトリクスを得る」という目的主眼の記事です。
各プラグインの仕様や紹介していないオプションについては、他の方が書かれる記事や、作者様のブログやGitHubをご参照ください。

WEBのレスポンスタイムをグラフ化する

fluentd casual talks で、fujiwaraさんが発表されたfluentdでWebサイト運用を楽にするがきっかけで、WEBのレスポンスタイムを可視化し始めた方、多いと思います。

(かなり極端な例ですが)こんなふうにグラフが出ることによって、「14:30頃からレスポンスが著しく悪くなっている！」ということが見て取れるようになります。

これによって"14:30から遅い応答が増え始めた"ということはわかるようになるのですが、「じゃあどこが遅いの？」となって結局生のログを漁ったりすることになる場合も少なくないでしょう。

リクエストパス毎にレスポンスタイムを可視化する

全体的に応答が遅くなっているのか、もしくは一部のパスへのみのリクエストが遅いだけなのかわかるようになれば、生のログを漁るにしてもある程度の目処を立てた上で挑むことができるようになるはずです。

nginxのアクセスログ(combined + レスポンスタイム)を例に、構成を記します。

利用するプラグイン

前述しましたが、各プラグインについての詳細は他の方のウィークリーFluentdユースケースエントリリレーの記事などをご参照ください。

fluent-plugin-rewrite
fluent-plugin-numeric-counter
fluent-plugin-growthforecast
fluent-plugin-forest

構成例

例です。複数ホストで構成していますが、単一のホストに全てやらせてしまうことも出来ます。

nginxのアクセスログがパースされます。in_tailに関してはfluentd tailプラグインの仕様について - iをgに変えるとorangeになることに気づいたoranieの日記をご参照ください。
パースされたログが転送されます。
タグの書き換えが行われます。タグの末尾にアクセスされたパスがくっつきます。(例: nginx.access.host01.foo)
タグ毎にレスポンスタイムを集計します。
集計されたデータをGrowthForecastに投げます。

設定例

送信側。シンプルにtailしてforwardするのみ。

<source>
  type        tail
  time_format %d/%b/%Y:%H:%M:%S %z
  path        /var/log/nginx/access.log
  tag         nginx.access.studio3104
  format      /^(?<host>[^ ]*) [^ ]* (?<user>[^ ]*) \[(?<time>[^\]]*)\] "(?<method>\S+)(?: +(?<path>[^ ]*) +\S*)?" (?<code>[^ ]*) (?<size>[^ ]*)(?: "(?<referer>[^\"]*)" "(?<agent>[^\"]*)" (?<response>[^ ]*))?$/
</source>
<match nginx.access>
  type forward
  host reciever
  flush_interval 1s
</match>

受信、ゴニョゴニョ側。
rewriteの設定は、ほとんどantipopさんのBLOGに書かれた設定例通りであるが、最後のruleセクションがポイント。
「pattern ^\/([^\/]+)」としておくことによって、パスを明示する必要がなく、URLが増えたとしても設定変更の必要がない。

<source>
  type forward
</source>
<match nginx.access.**>
  type       rewrite
  add_prefix rewrited
  <rule>
    key     status
    pattern ^(?!200)\\d+$
    ignore  true
  </rule>
  <rule>
    key     method
    pattern ^(?!GET).+$
    ignore  true
  </rule>
  <rule>
    key     path
    pattern ^/$
    replace /top
  </rule>
  <rule>
    key           path
    pattern       ^\/([^\/]+)
    fallback      others
    append_to_tag true
  </rule>
</match>  
  
<match rewrited.nginx.access.**>
  type          forest
  subtype       numeric_counter
  remove_prefix rewrited.nginx.access
  <template>
    tag numcnt.nginx.access.__TAG__
    aggregate tag
    count_key response
    pattern1 -10ms         0    10000
    pattern2 -100ms    10000   100000
    pattern3 -1s      100000  1000000
    pattern4 -3s     1000000  3000000
    pattern5 3s-              3000000
  </template>
</match>

<match numcnt.nginx.access.**>
  type      growthforecast
  gfapi_url http://192.168.1.100:5125/api/
  service   Every_Path
  tag_for   section
  remove_prefix numcount.nginx.access
  name_key_pattern .*_percentage$
</match>

アウトプット例

このような感じで、パス毎にレスポンスタイムを可視化することが出来るようになりました。

最後に

全体のレスポンスタイムや、リクエストパスの割合なども可視化しておいて、比較して参照出来るようにしておくとなお捗るかと思います。(派生デザインパターンとして別に記事にします。誰かが書いてくれても構いませんが。)
ちなみに自分は、送信側はfluent-agent-liteを用いているので、受信側でout_parserを介してからout_rewriteに処理させています。