Hateburo: kazeburo hatenablog

SRE / 運用系小姑 / Goを書くPerl Monger

秒間数千件以上のアクセスログでも高速に集計し、可視化できる mackerel-plugin-axslog の紹介

Mackerelアンバサダーになりました

ということで、新しいmackerel-pluginの紹介です。

mackerel-plugin-axslog とは

Mackerelの公式プラグインに mackerel-plugin-accesslog というとても便利なプラグインがあります。公式のブログに詳しく解説があります。

mackerel.io

これを使うと、アクセスログのファイルサイズを記録しながら差分を読み、ステータスコードごとのアクセス数や割合、レイテンシなどを集計、可視化できます。

mackerel-plugin-accesslog、サーバの可視化のため、とても便利そうでとても使いたかったのですが、ltsvのラベルが ltsv.org でレコメンドされているラベルで固定であり、某所でレスポンス速度を記録しているものと異なるため、使うことができませんでした。

そこで、

  • LTSVのラベルカスタマイズができること
  • JSON形式のログにも対応していること

と言ったあたりを目標にYet Anotherなmackerel-pluginを作りました。

github.com

最初のバージョンを作ってから、それほどパフォーマンスが良くないに気づき、また、大量のアクセスを捌くサーバでは毎時間ログローテートが動作するので、欠損が目立つことにわかったので、

  • 秒間数千以上の環境でも問題なく利用できる動作速度
  • 公式にもあるログローテート対応

あたりを中心に改善に取り組んで、バージョン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に処理を分散するような手法はいまのところとっていません。

まとめ

ぜひ使って見てくださいませ。

また、動作優先で全く綺麗なコードではないですが、さらになにかできそうなことがあれば、教えてください。