mackerel-plugin-axslogを使ってみた

Mackerelでアクセスログを集計したいときに、普段は公式プラグインであるmackerel-plugin-accesslogを使っていた。

そんな中ふと下のエントリーを思い出し、高速であるという点も気になるし、いくつかオプションも異なるということで試しに使ってみることにした。

kazeburo.hatenablog.com

mkr plugin installをすることでインストールできる。*1

mkr plugin install --upgrade kazeburo/mackerel-plugin-axslog@v0.2.1

インストールされたのを見たら、あとは必要なオプションをいくつか入れることですぐ使い始められる。

(mackerel-plugin-accesslogとオプション名が結構異なっているので注意)

[plugin.metrics.axslog]
command = '/opt/mackerel-agent/plugins/bin/mackerel-plugin-axslog --key-prefix=all --format=ltsv --status-key=status --ptime-key=reqtime --logfile=/var/log/nginx/access_log'

これだけで準備完了であとは待っていたらmackerel-plugin-accesslogに似たようなメトリックが表示されるようになる。

アクセス数の数字について

実際にアクセスしてメトリックを確認したところ、このようにアクセス数の数字が小数点以下の数字になった。

f:id:cohalz:20200628002338p:plain

当然1分間に0.0833回アクセスしたわけではないので、どういう実装になっているか見てみたところこのようになっていた。

fmt.Printf("axslog.access_num_%s.2xx_count\t%f\t%d\n", keyPrefix, s.c2xx/s.duration, now)

https://github.com/kazeburo/mackerel-plugin-axslog/blob/v0.2.1/axslog/axslog.go#L200-L206

カウント(s.c2xx)を期間(s.duration)で割っているということがわかる。

計測された数を期間で割っているのでつまりは「平均して1秒あたりにどのくらいのリクエストが来たか」というメトリックになっているということがわかった。 *2

何故こうなっているのか不思議だったけど、おそらく「プラグインの実行が何らかの形で失敗した場合、集計されるべきだった分が次回に加算されてしまい数字が大きく出てしまう」ということを回避するための仕組みなんだろうと思った。*3

一度プラグインの実行に失敗して次回1分後の集計の範囲が倍になったとしても、カウント数も期間も等しく倍になっているためメトリックとしては大きく変わることはないということになる。

このようにメトリック投稿を復帰させたあとのグラフに悪影響を及ぼさない上にメトリック自体も集計タイミングに依存しない、という感じでわかってしまえばなかなか合理的なメトリックになっているということがわかった。

filterについて

Usageにある通り、mackerel-plugin-axslogにはfilterオプションが存在する。

--filter= text for filtering log

このfilterの使い方についても調べてみた。

使い方

コードを見たところ、JSON/LTSVの文字列をパースする直前にbytes.Indexでマッチしているのか見ているようだった。

if len(filter) > 0 {
    if bytes.Index(b, filter) < 0 {
        continue
    }
}
c, pt, st := r.Parse(b)

https://github.com/kazeburo/mackerel-plugin-axslog/blob/v0.2.1/main.go#L50-L55

パースした結果を見るわけではないので、例えばLTSV形式のログでフィルタを使いたい場合は --filter="method:POST" のようにkey:valueの形式で指定するという使い方になる。

使い所

そしてこのフィルタ機能がmackerel-plugin-axslogを選ぶ大きな利点になっていると個人的に思っている。

というのもmackerel-plugin-accesslogではログからすべてのレイテンシとステータスコードを集計するため、ログに傾向の違うリクエストが混ざっている場合に実感とは異なるメトリックの傾向になるということがよくあった。(99パーセンタイル値だけが高い値を示しているなど)

そういう場合に、このフィルタ機能を使うことで重要なエンドポイントに絞ったレイテンシやステータスコードの集計ができるようになりそう。

そしてプラグインは複数実行できるので、confにフィルタを別にしたプラグインを複数書くことでフィルタしたメトリックをいくつも出すことができる。

ただし、並列で何回も同じアクセスログを読み直すので効率は悪く負荷が増え、メトリック数もその分増えるのでその点は考慮して工夫する必要がある。

例えば、本当に重要な条件のみに絞ったり、ログの形式をフィルタに合わせた形に変たりなどして複数実行の数を減らすとか、無理が出たらmackerel-plugin-axslogじゃなくてちゃんとログ集計基盤を作るとかになるとは思う。

とはいえアクセスログから1つ2つ重要な部分のみに絞った集計を少ない手間で可視化できるというのは相当に便利だとは思う。

まとめ

mackerel-plugin-axslogは後発のプラグインということもあり、フィルタのようなmackerel-plugin-accesslogにはない機能もある、ということでかなり面白いプラグインということがわかった。

*1:mkr plugin installでプラグインをインストールする - Mackerel ヘルプ

*2:試しに期間を正確に1分と仮定すると0.0833 * 60 = 4.998となり確かにほぼ整数に近い値になった。

*3:fluent-plugin-mackerelを使ってMackerelにメトリックを投稿する際にも、途中のログ配送が詰まると復旧後に加算されてしまうという現象が起こる。