Fluentd を利用して、ログから Prometheus メトリクスを生成する (2/2)

前回の投稿の続きです。(すっかり忘れていました...)
予定していたように、WAS Liberty のアクセス・ログからレスポンス時間のメトリクスを生成しますが、レスポンス時間の平均だけではなく、レスポンス時間のパーセンタイル(quantile,分位数)の算出に必要なメトリクスも生成してみます。
また、アクセス・ログのフォーマットとして、WAS Liberty のデフォルトのフォーマットを拡張したものを使用します。

生成するメトリクス

以下のメトリクスをアクセス・ログから生成することにします。

元データ	メトリクス名	メトリクス・タイプ	付加するラベル
レスポンス・サイズ	liberty_response_size	summary	ステータス・コード、パスの一部
レスポンス時間	liberty_response_time	histogram	ステータス・コード、パスの一部

前回は counter タイプのメトリクスを使用しましたが、今回は summary と histogram を使用してみます。
タイプとして summary / histogram を指定すると、以下の情報が生成されます。

• liberty_response_size
  • liberty_response_size_count: レスポンス・サイズの件数 (アクセス数に相当)
  • liberty_response_size_sum: レスポンス・サイズの合計値
• liberty_response_time
  • liberty_response_time_count: レスポンス時間の件数 (アクセス数に相当)
  • liberty_response_time_sum: レスポンス時間の合計値
  • liberty_response_time_bucket: レスポンス時間のパーセンタイル(quantile,分位数)の算出に使用するデータ

WAS Liberty 側の準備

アクセス・ログのフォーマットは、デフォルトのフォーマットの末尾に、マイクロ秒単位のレスポンス時間を追加したフォーマットにします。
前回と同様に、アクセス・ログの出力先 /logs/http_access.log は Fluentd が読み込めるボリューム内にします。

server.xml

<httpEndpoint host="*" httpPort="9080" httpsPort="9443" id="defaultHttpEndpoint">
    <accessLogging enabled="true"
                   filePath="/logs/http_access.log"
                   logFormat='%h %u %{t}W "%r" %s %b %D'/>
</httpEndpoint>

Fluentd 側の準備

イメージのビルド

前回は、Fluentd DaemonSet for Kubernetes のイメージを流用しましたが、今回は必要な機能だけを追加したイメージをビルドして使用することにしました。Prometheus Plugin を追加すればよいので、以下のような簡単な Dockerfile でビルドできます。

Dockerfile

FROM fluent/fluentd:v1.12.4-debian-1.0
USER 0
RUN gem install fluent-plugin-prometheus -v 2.0.0
USER fluent

fluent.conf の定義

上記のメトリクスをアクセス・ログから生成するように、fluent.conf を定義します。
作成した fluent.conf は以下のようになりますが、前回の差異を中心に少し補足しておきます。

• regexp パーサーを使用してアクセス・ログをパースしています。
  • 今回は、WAS Liberty のデフォルトのアクセス・ログのフォーマットを拡張しているので、前回使用した apache2 パーサーが使用できません。
  • apache2 パーサーの実装を参考に、regexp パーサーの定義を作成しました。
• 前述のように、summary / histogram タイプを使用しています。
• histogram タイプの場合、パーセンタイルの計算に使用するバケット(buckets)を定義する必要があります。
  • バケットの範囲が元データの分散にあっていて、バケットの区切りが細かいほど、より正確なパーセンタイルが算出できると考えられます。
  • 今回は、10000マイクロ秒(=10ミリ秒)から500000000マイクロ秒(500秒)の範囲で、倍々の間隔にしました。
• 全てのメトリクスに同じラベルを付与するので、labels の指定個所を移動しました。

fluent.conf

<source>
  @type prometheus
  @id in_prometheus
  bind "0.0.0.0"
  port 24231
  metrics_path "/metrics"
</source>
<source>
  @type prometheus_output_monitor
  @id in_prometheus_output_monitor
</source>
<source>
  @type tail
  follow_inodes
  # read_from_head true
  path     /logs/http_access.log
  pos_file /logs/http_access.log.pos
  tag *
  <parse>
    # @type apache2
    @type regexp
    expression /^(?<host>[^ ]*) (?<user>[^ ]*) \[(?<time>[^\]]*)\] "(?<method>\S+)(?: +(?<path>(?:[^\"]|\\.)*?)(?: +\S*)?)?" (?<code>[^ ]*) (?<res_size>[^ ]*) (?<res_time>[^ ]*)$/
    time_format %d/%b/%Y:%H:%M:%S %z
    types code:integer, res_size:integer, res_time:integer
  </parse>
</source>
<filter logs.http_access.log>
  @type parser
  key_name path
  reserve_data true
  <parse>
    @type regexp
    expression /^(?<path_head>.*\/)(?<path_rest>.*)$/
  </parse>
</filter>
<filter logs.http_access.log>
  @type prometheus
  <metric>
    name liberty_response_size
    desc summary of response size
    type summary
    key res_size
  </metric>
  <metric>
    name liberty_response_time
    desc histogram of response time
    type histogram
    key res_time
    buckets 10000, 50000, 100000, 500000, 1000000, 5000000, 10000000, 50000000, 100000000, 500000000
  </metric>
  <labels>
    code ${code}
    path ${path_head}
  </labels>
</filter>
<match logs.http_access.log>
  @type null
</match>

動作を確認する

WAS Liberty と Fluentd を起動し、WAS Liberty 上のアプリにアクセスします。
curl で Fluentd の Prometheus Plugin のポートにアクセスし、メトリクスを取り出すと、以下のような情報が確認できます。

メトリクス取得

bash-4.4$ curl -s http://localhost:24231/metrics | grep liberty
# TYPE liberty_response_size summary
# HELP liberty_response_size summary of response size
liberty_response_size_sum{code="200",path="/InfraTest/"} 7688.0
liberty_response_size_count{code="200",path="/InfraTest/"} 5.0
liberty_response_size_sum{code="200",path="/ResourceEater/"} 548.0
liberty_response_size_count{code="200",path="/ResourceEater/"} 2.0
liberty_response_size_sum{code="200",path="/ResourceEater/faces/javax.faces.resource/"} 4818.0
liberty_response_size_count{code="200",path="/ResourceEater/faces/javax.faces.resource/"} 2.0
liberty_response_size_sum{code="200",path="/ResourceEater/faces/"} 235822.0
liberty_response_size_count{code="200",path="/ResourceEater/faces/"} 40.0
# TYPE liberty_response_time histogram
# HELP liberty_response_time histogram of response time
liberty_response_time_bucket{code="200",path="/InfraTest/",le="10000.0"} 3.0
liberty_response_time_bucket{code="200",path="/InfraTest/",le="50000.0"} 4.0
liberty_response_time_bucket{code="200",path="/InfraTest/",le="100000.0"} 4.0
liberty_response_time_bucket{code="200",path="/InfraTest/",le="500000.0"} 4.0
liberty_response_time_bucket{code="200",path="/InfraTest/",le="1000000.0"} 5.0
liberty_response_time_bucket{code="200",path="/InfraTest/",le="5000000.0"} 5.0
liberty_response_time_bucket{code="200",path="/InfraTest/",le="10000000.0"} 5.0
liberty_response_time_bucket{code="200",path="/InfraTest/",le="50000000.0"} 5.0
liberty_response_time_bucket{code="200",path="/InfraTest/",le="100000000.0"} 5.0
liberty_response_time_bucket{code="200",path="/InfraTest/",le="500000000.0"} 5.0
liberty_response_time_bucket{code="200",path="/InfraTest/",le="+Inf"} 5.0
liberty_response_time_sum{code="200",path="/InfraTest/"} 587766.0
liberty_response_time_count{code="200",path="/InfraTest/"} 5.0
liberty_response_time_bucket{code="200",path="/ResourceEater/",le="10000.0"} 1.0
liberty_response_time_bucket{code="200",path="/ResourceEater/",le="50000.0"} 2.0
liberty_response_time_bucket{code="200",path="/ResourceEater/",le="100000.0"} 2.0
liberty_response_time_bucket{code="200",path="/ResourceEater/",le="500000.0"} 2.0
liberty_response_time_bucket{code="200",path="/ResourceEater/",le="1000000.0"} 2.0
liberty_response_time_bucket{code="200",path="/ResourceEater/",le="5000000.0"} 2.0
liberty_response_time_bucket{code="200",path="/ResourceEater/",le="10000000.0"} 2.0
liberty_response_time_bucket{code="200",path="/ResourceEater/",le="50000000.0"} 2.0
liberty_response_time_bucket{code="200",path="/ResourceEater/",le="100000000.0"} 2.0
liberty_response_time_bucket{code="200",path="/ResourceEater/",le="500000000.0"} 2.0
liberty_response_time_bucket{code="200",path="/ResourceEater/",le="+Inf"} 2.0
liberty_response_time_sum{code="200",path="/ResourceEater/"} 15154.0
liberty_response_time_count{code="200",path="/ResourceEater/"} 2.0
・・・以下省略・・・

Grafana で表示する

今回は、メトリクスを Prometheus で収集し、Grafana でグラフ表示するところまで念のため確認してみました。

アクセス数のグラフは、liberty_response_time_count を rate() 関数で処理すれば簡単にグラフ化できます。
以下の PromQL は、５分間のアクセス数の１秒当たり件数(アクセス/秒)を取得する例です。

rate(liberty_response_time_count{path!="/"}[5m])

平均のレスポンス時間やレスポンス・サイズも、同様に rate() 関数でグラフ化できます。
次の PromQL は、平均レスポンス時間の例です。

rate(liberty_response_time_sum{path!="/"}[5m]) / rate(liberty_response_time_count{path!="/"}[5m])

レスポンス時間のパーセンタイルは、liberty_response_time_bucket を rate() 関数で処理した結果を histogram_quantile() 関数に渡すことでグラフ化できます。
例えば、90% タイルを計算する場合は、次のような PromQL になります。

histogram_quantile(0.9, rate(liberty_response_time_bucket{path!="/"}[5m]))

終わりに

前回の記事と同じまとめとなりますが、、、
WAS Liberty が出力するログからメトリクスを生成できることが確認できました。

コンテナのログを分析する場合、ログを Elasticsearch などに転送し、Kibana などで分析・表示するというパターンなどが多いと思います。しかし、アクセス・ログのように多量に出力されるログを Elasticsearch などに転送・保存するのは、キャパシティーやパフォーマンスの面から二の足を踏むことがあります。
利用頻度が高そうな定型的な分析を Fluentd で行い、その結果を Prometheus メトリクスとして収集・蓄積し、Grafana で確認できるなら、ちょっと敷居が低くなるかもしれません。

アプリケーションが出力するログからメトリックを生成するなど、いろいろな場面で利用できそうです。

• 参考

• Fluentd: Monitoring by Prometheus
• GitHub: fluent / fluent-plugin-prometheus
• GitHub: fluent / fluentd-docker-image