fluentd プラグイン sampling-filter と numeric-monitor を組み合わせて nginx のアクセスログから標本を抽出してパフォーマンス測定を実施する

ログの一部を抽出して計算するには sampling-filter + numeric-monitor の組み合わせがぴったり!

大規模データ収集のログコレクタとして fluentd を使用している場合、全部のログの中から一部を抽出してデータ分析を行いたい場合がないだろうか。例えば、サービスのレスポンスタイムが遅くなったり(早くなったり)していないかを測定することができれば、異常検知に役立つ。つまり、ログ(母集団)をデータベースまで運ぶ間にちょっとつまみ喰い(標本)するといった具合だ。平均や特定のパーセンタイル値を出しておけばパフォーマンス監視としては十分だと思う。こういった要求を満たすのに便利な fluentd プラグインの組み合わせが fluent-plugin-sampling-filterfluent-plugin-numeric-monitor だ。

nginx のアクセスログの一部を抽出してパフォーマンス測定を行う場合

ここでは具体例として nginx のアクセスログを考えてみる。例えば以下のアクセスログから vhost ごとの reqtime をサンプリングしてパフォーマンスの指標として vhost ごとの平均と 99 パーセンタイルを出してみる。

access.log

time:15/Mar/2018:01:00:00 +0900  host:10.0.0.123 forwardedfor:12.123.123.123 req:GET /index.html HTTP/1.1    status:200  size:123    referer:-   ua:-    reqtime:0.001   vhost:blog.ayakumo.net
time:15/Mar/2018:01:00:00 +0900 host:10.0.0.123 forwardedfor:12.123.123.123 req:GET /index.html HTTP/1.1    status:200  size:123    referer:-   ua:-    reqtime:0.001   vhost:www.ayakumo.net
time:15/Mar/2018:01:00:00 +0900 host:10.0.0.123 forwardedfor:12.123.123.123 req:GET /index.html HTTP/1.1    status:200  size:123    referer:-   ua:-    reqtime:0.002   vhost:blog.ayakumo.net
time:15/Mar/2018:01:00:00 +0900 host:10.0.0.123 forwardedfor:12.123.123.123 req:GET /index.html HTTP/1.1    status:200  size:123    referer:-   ua:-    reqtime:0.002   vhost:www.ayakumo.net
time:15/Mar/2018:01:00:00 +0900 host:10.0.0.123 forwardedfor:12.123.123.123 req:GET /index.html HTTP/1.1    status:200  size:123    referer:-   ua:-    reqtime:0.003   vhost:blog.ayakumo.net
time:15/Mar/2018:01:00:02 +0900 host:10.0.0.123 forwardedfor:12.123.123.123 req:GET /index.html HTTP/1.1    status:200  size:123    referer:-   ua:-    reqtime:0.004   vhost:blog.ayakumo.net
time:15/Mar/2018:01:00:03 +0900 host:10.0.0.123 forwardedfor:12.123.123.123 req:GET /index.html HTTP/1.1    status:200  size:123    referer:-   ua:-    reqtime:0.005   vhost:blog.ayakumo.net
time:15/Mar/2018:01:00:05 +0900 host:10.0.0.123 forwardedfor:12.123.123.123 req:GET /index.html HTTP/1.1    status:200  size:123    referer:-   ua:-    reqtime:0.006   vhost:blog.ayakumo.net
time:15/Mar/2018:01:00:06 +0900 host:10.0.0.123 forwardedfor:12.123.123.123 req:GET /index.html HTTP/1.1    status:200  size:123    referer:-   ua:-    reqtime:0.007   vhost:blog.ayakumo.net
time:15/Mar/2018:01:00:08 +0900 host:10.0.0.123 forwardedfor:12.123.123.123 req:GET /index.html HTTP/1.1    status:200  size:123    referer:-   ua:-    reqtime:0.008   vhost:blog.ayakumo.net
time:15/Mar/2018:01:00:08 +0900 host:10.0.0.123 forwardedfor:12.123.123.123 req:GET /index.html HTTP/1.1    status:200  size:123    referer:-   ua:-    reqtime:0.009   vhost:blog.ayakumo.net
time:15/Mar/2018:01:00:08 +0900 host:10.0.0.123 forwardedfor:12.123.123.123 req:GET /index.html HTTP/1.1    status:200  size:123    referer:-   ua:-    reqtime:0.010   vhost:blog.ayakumo.net

fluent プラグインの組み合わせによる実装

以下 4 つのプラグインを組み合わせることによりパフォーマンス測定を実装する。rewrite-tag-filter は昔の rewriteruleN 記法ではなく新しい <rule> ... </rule> 記法を使用することでマッチした部分をタグとして利用できるのが素晴らしい。

sample_td_agent.conf

<source>
  @type forward
  port 88888
</source>

<source>
  @type prometheus
</source>

<match nginx.access>
  @type rewrite_tag_filter
  <rule>
    key vhost
    pattern ^(.*)\.ayakumo\.net$
    tag nginx.access.$1
  </rule>
</match>

<match nginx.access.*>
  @type sampling_filter
  interval 100 # 1/100 sampling
  sample_unit all
  add_prefix sampled
</match>

<match sampled.nginx.access.*>
  @type forest
  subtype numeric_monitor
  <template>
    tag reqtime.${tag_parts[3]}
    unit minute
    aggregate all
    monitor_key reqtime
    percentiles 50,99
  </template>
</match>

<match reqtime.*>
  @type forest
  subtype copy
  <template>
    <store>
      @type prometheus
      <metric>
        name reqtime_percentile_50_${tag_parts[1]}
        type gauge
        desc The 50 percentile of reqtime per minute.
        key  percentile_50
      </metric>
      <metric>
        name reqtime_percentile_99_${tag_parts[1]}
        type gauge
        desc The 99 percentile of reqtime per minute.
        key  percentile_99
      </metric>
    </store>
    <store>
      @type stdout
    </store>
  </template>
</match>

<match **>
  @type null
</match>

nginx のアクセスログを擬似的に発行するために fluent-post を以下のように使用する。reqtime のところは $RANDOM を使う代わりに shuf -i 1-100 -n 1 でもよいかもしれない。

fluent-post.sh

for sld in www blog; do
  for i in `seq 1 100`; do
    r=$(($RANDOM % 100))
    /opt/td-agent/embedded/bin/fluent-post -p 88888 -t nginx.access -v time=time:15/Mar/2018:01:00:01 -v host=10.0.0.123 -v forwardedfor=12.123.123.123 -v req="GET /    index.html HTTP/1.1" -v status=200 -v referer="-" -v ua="-" -v reqtime=0.${r} -v vhost=${sld}.ayakumo.net
  done
done

こうすると @type stdout で td-agent.log に出力している numeric-monitor の基本機能により avg や num は自動的に計算されていることがわかる。www と blog の 2 つの sld(Second Level Domain) に対して 100 回(seq 1 100) 投げているが、サンプリング粒度を 1/100 にしているので(interval 100) 標本のサイズはそれぞれ 10 個づつ("num": 10) となる。

td-agent.log

2018-03-15 01:02:32 +0900 [info]: out_forest plants new output: numeric_monitor for tag 'sampled.nginx.access.www'
2018-03-15 01:02:32 +0900 reqtime.blog: {"num":10,"min":0.1,"max":0.98,"avg":0.587,"sum":5.87,"percentile_50":0.6,"percentile_99":0.94}
2018-03-15 01:02:32 +0900 [info]: out_forest plants new output: copy for tag 'reqtime.www'
2018-03-15 01:02:32 +0900 reqtime.www: {"num":10,"min":0.14,"max":0.79,"avg":0.433,"sum":4.33,"percentile_50":0.36,"percentile_99":0.7}

prometheus のメトリクス名としているパーセンタイル 50, 99 も取得できる。

$ curl -s http://localhost:24231/metrics/ | grep -v '^#'
reqtime_percentile_50_blog 0.6
reqtime_percentile_99_blog 0.94
reqtime_percentile_50_www 0.36
reqtime_percentile_99_www 0.7

fluentd のプラグインは便利なものがたくさんそろっているので、組み合わせ次第でいろいろなことができて本当に助かっている。(^_^)