Mackerelアンバサダーになりました
Mackerelアンバサダーになったので、グッズ頂いた。ありがとうございます pic.twitter.com/UzCmANa84O
— Masahiro 💺 (@kazeburo) March 23, 2019
ということで、新しいmackerel-pluginの紹介です。
mackerel-plugin-axslog とは
Mackerelの公式プラグインに mackerel-plugin-accesslog というとても便利なプラグインがあります。公式のブログに詳しく解説があります。
これを使うと、アクセスログのファイルサイズを記録しながら差分を読み、ステータスコードごとのアクセス数や割合、レイテンシなどを集計、可視化できます。
mackerel-plugin-accesslog、サーバの可視化のため、とても便利そうでとても使いたかったのですが、ltsvのラベルが ltsv.org でレコメンドされているラベルで固定であり、某所でレスポンス速度を記録しているものと異なるため、使うことができませんでした。
そこで、
- LTSVのラベルカスタマイズができること
- JSON形式のログにも対応していること
と言ったあたりを目標にYet Anotherなmackerel-pluginを作りました。
最初のバージョンを作ってから、それほどパフォーマンスが良くないに気づき、また、大量のアクセスを捌くサーバでは毎時間ログローテートが動作するので、欠損が目立つことにわかったので、
- 秒間数千以上の環境でも問題なく利用できる動作速度
- 公式にもあるログローテート対応
あたりを中心に改善に取り組んで、バージョンv0.0.6まできております。
結果としとして、上記2つの課題は解決し、毎秒数千以上のリクエストを捌く環境でもアクセスログの集計と可視化が安定してできるようになりました。
ベンチマーク
秒間2万req、1分間で120万行のログが記録される、よくある環境を想定し、ベンチーマークを行いました。ログファイルのサイズは287MBになりました。
mackerel-plugin-accesslog
$ time ./mackerel-plugin-accesslog --format ltsv demo.log accesslog.access_rate.5xx_percentage 0 1554390519 accesslog.access_rate.4xx_percentage 0 1554390519 accesslog.access_rate.3xx_percentage 0 1554390519 accesslog.access_rate.2xx_percentage 100 1554390519 accesslog.latency.99_percentile 0.030000 1554390519 accesslog.latency.95_percentile 0.030000 1554390519 accesslog.latency.90_percentile 0.030000 1554390519 accesslog.latency.average 0.030000 1554390519 accesslog.access_num.total_count 1200000 1554390519 accesslog.access_num.5xx_count 0 1554390519 accesslog.access_num.4xx_count 0 1554390519 accesslog.access_num.3xx_count 0 1554390519 accesslog.access_num.2xx_count 1200000 1554390519 real 0m7.843s user 0m7.947s sys 0m0.346s
mackerel-plugin-axslog
$ time ../mackerel-plugin-axslog --key-prefix demo --logfile demo.log --ptime-key=reqtime axslog.latency_demo.average 0.030000 1554390518 axslog.latency_demo.99_percentile 0.030000 1554390518 axslog.latency_demo.95_percentile 0.030000 1554390518 axslog.latency_demo.90_percentile 0.030000 1554390518 axslog.access_num_demo.1xx_count 0.000000 1554390518 axslog.access_num_demo.2xx_count 1200000.000000 1554390518 axslog.access_num_demo.3xx_count 0.000000 1554390518 axslog.access_num_demo.4xx_count 0.000000 1554390518 axslog.access_num_demo.499_count 0.000000 1554390518 axslog.access_num_demo.5xx_count 0.000000 1554390518 axslog.access_total_demo.count 1200000.000000 1554390518 axslog.access_ratio_demo.1xx_percentage 0.000000 1554390518 axslog.access_ratio_demo.2xx_percentage 1.000000 1554390518 axslog.access_ratio_demo.3xx_percentage 0.000000 1554390518 axslog.access_ratio_demo.4xx_percentage 0.000000 1554390518 axslog.access_ratio_demo.499_percentage 0.000000 1554390518 axslog.access_ratio_demo.5xx_percentage 0.000000 1554390518 real 0m0.393s user 0m0.279s sys 0m0.126s
ここではaccesslogの7.843sに対して、axslogは0.393sなので、約20倍高速に動作することが確認できました。
benchmarkに利用したscriptは、axslogのrepositoryのdemoディレクトリ以下にあります。なおベンチマークはMacbook Pro上で実行しました。
高速化のためにやったこと
ざっとあげると
- LTSVのパーサの高速化のため、初期バージョンは別のltsvパーサライブラリを利用していたが、必要なことだけを行う独自のパーサを実装
- メモリアロケートをさけるため stringをさけ
[]byteのまま処理を行う - mapも同じ
- JSONに関しては、json-iterator/go を利用。まだ改善の余地がある状態
これくらいです。監視のツールなので、複数のcpuに処理を分散するような手法はいまのところとっていません。
まとめ
ぜひ使って見てくださいませ。
また、動作優先で全く綺麗なコードではないですが、さらになにかできそうなことがあれば、教えてください。
