📝

alpの使い方(発展編)

2021/08/07に公開

CLI

ISUCON

tech

基本編はこちら。

主にISUCONで使われているアクセスログ集計ツール alp の使い方を、ISUCON10オンライン予選問題のアクセスログを例に、基本よりも少し発展した使い方を紹介します。

alpは、デフォルトで90,95,99パーセンタイルを出力しますが、それ以外のパーセンタイルを出力したいことがあるかもしれません。そのようなときは--percentilesを使用します。

$ cat /path/to/access.log | alp json -m '/api/estate/[0-9]+,/api/chair/[0-9]+,/api/recommended_estate/[0-9]+' --sort avg -r --show-footers -o count,1xx,2xx,3xx,4xx,5xx,min,max,avg,sum,p50,p75 --percentiles 50,75
+-------+-----+-----+-----+-----+-----+-------+-------+-------+-------+-------+-------+
| COUNT | 1XX | 2XX | 3XX | 4XX | 5XX |  MIN  |  MAX  |  AVG  |  SUM  |  P50  |  P75  |
+-------+-----+-----+-----+-----+-----+-------+-------+-------+-------+-------+-------+
|     1 |   0 |   1 |   0 |   0 |   0 | 7.524 | 7.524 | 7.524 | 7.524 | 7.524 | 7.524 |
|     5 |   0 |   5 |   0 |   0 |   0 | 0.956 | 1.284 | 1.070 | 5.352 | 1.000 | 1.140 |
|    21 |   0 |  21 |   0 |   0 |   0 | 0.040 | 0.708 | 0.232 | 4.880 | 0.116 | 0.176 |
|     5 |   0 |   5 |   0 |   0 |   0 | 0.024 | 0.404 | 0.211 | 1.056 | 0.256 | 0.328 |
|    21 |   0 |  21 |   0 |   0 |   0 | 0.028 | 0.232 | 0.113 | 2.364 | 0.120 | 0.140 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.032 | 0.032 | 0.032 | 0.032 | 0.032 | 0.032 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.020 | 0.020 | 0.020 | 0.020 | 0.020 | 0.020 |
|     9 |   0 |   8 |   0 |   1 |   0 | 0.004 | 0.024 | 0.012 | 0.108 | 0.012 | 0.020 |
|    10 |   0 |   8 |   0 |   2 |   0 | 0.004 | 0.020 | 0.008 | 0.080 | 0.004 | 0.016 |
|     8 |   0 |   8 |   0 |   0 |   0 | 0.000 | 0.016 | 0.005 | 0.036 | 0.004 | 0.004 |
|     8 |   0 |   8 |   0 |   0 |   0 | 0.000 | 0.020 | 0.003 | 0.020 | 0.000 | 0.000 |
|     4 |   0 |   4 |   0 |   0 |   0 | 0.000 | 0.004 | 0.002 | 0.008 | 0.000 | 0.004 |
|     4 |   0 |   4 |   0 |   0 |   0 | 0.000 | 0.004 | 0.001 | 0.004 | 0.000 | 0.000 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 |
+-------+-----+-----+-----+-----+-----+-------+-------+-------+-------+-------+-------+
|   100 |   0 |  97 |   0 |   3 |   0 |
+-------+-----+-----+-----+-----+-----+-------+-------+-------+-------+-------+-------+

--percentiles N(0~100),...のようにカンマ区切りで指定し、それに合わせて-o pN(0~100)も変更することで出力を柔軟に変更できます。

alpには--sortや-r、-oで出力結果を変えることができます。その際に毎回アクセスログを集計していると、ログのサイズによっては時間がかかります。そのようなケースで使うのが--dumpと--loadです。

$ cat /path/to/access.log | alp json -m '/api/estate/[0-9]+,/api/chair/[0-9]+,/api/recommended_estate/[0-9]+' --sort avg -r --show-footers -o count,1xx,2xx,3xx,4xx,5xx,min,max,avg,sum,p99 --dump /tmp/dump.log
+-------+-----+-----+-----+-----+-----+-------+-------+-------+-------+-------+
| COUNT | 1XX | 2XX | 3XX | 4XX | 5XX |  MIN  |  MAX  |  AVG  |  SUM  |  P99  |
+-------+-----+-----+-----+-----+-----+-------+-------+-------+-------+-------+
|     1 |   0 |   1 |   0 |   0 |   0 | 7.524 | 7.524 | 7.524 | 7.524 | 7.524 |
|     5 |   0 |   5 |   0 |   0 |   0 | 0.956 | 1.284 | 1.070 | 5.352 | 1.140 |
|     3 |   0 |   3 |   0 |   0 |   0 | 0.616 | 0.708 | 0.652 | 1.956 | 0.632 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.624 | 0.624 | 0.624 | 0.624 | 0.624 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.612 | 0.612 | 0.612 | 0.612 | 0.612 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.232 | 0.232 | 0.232 | 0.232 | 0.232 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.224 | 0.224 | 0.224 | 0.224 | 0.224 |
|     5 |   0 |   5 |   0 |   0 |   0 | 0.024 | 0.404 | 0.211 | 1.056 | 0.328 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.192 | 0.192 | 0.192 | 0.192 | 0.192 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.184 | 0.184 | 0.184 | 0.184 | 0.184 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.120 | 0.120 | 0.120 | 0.120 | 0.120 |
|     5 |   0 |   5 |   0 |   0 |   0 | 0.092 | 0.168 | 0.114 | 0.568 | 0.168 |
|     9 |   0 |   9 |   0 |   0 |   0 | 0.028 | 0.180 | 0.108 | 0.968 | 0.180 |
|    11 |   0 |  11 |   0 |   0 |   0 | 0.040 | 0.176 | 0.102 | 1.120 | 0.116 |
|     5 |   0 |   5 |   0 |   0 |   0 | 0.056 | 0.084 | 0.071 | 0.356 | 0.056 |
|     2 |   0 |   2 |   0 |   0 |   0 | 0.044 | 0.044 | 0.044 | 0.088 | 0.044 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.032 | 0.032 | 0.032 | 0.032 | 0.032 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.020 | 0.020 | 0.020 | 0.020 | 0.020 |
|     9 |   0 |   8 |   0 |   1 |   0 | 0.004 | 0.024 | 0.012 | 0.108 | 0.004 |
|    10 |   0 |   8 |   0 |   2 |   0 | 0.004 | 0.020 | 0.008 | 0.080 | 0.000 |
|     8 |   0 |   8 |   0 |   0 |   0 | 0.000 | 0.016 | 0.005 | 0.036 | 0.000 |
|     8 |   0 |   8 |   0 |   0 |   0 | 0.000 | 0.020 | 0.003 | 0.020 | 0.000 |
|     4 |   0 |   4 |   0 |   0 |   0 | 0.000 | 0.004 | 0.002 | 0.008 | 0.000 |
|     4 |   0 |   4 |   0 |   0 |   0 | 0.000 | 0.004 | 0.001 | 0.004 | 0.000 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 |
+-------+-----+-----+-----+-----+-----+-------+-------+-------+-------+-------+
|   100 |   0 |  97 |   0 |   3 |   0 |
+-------+-----+-----+-----+-----+-----+-------+-------+-------+-------+-------+

集計結果を出力されるのは今までどおりですが、/tmp/dump.logというファイルが出力されています。このファイルには集計結果が記録されているので、--loadに指定するとログを集計せず結果を出力することができます。出力結果を変えるために-rを削除してみます。

$ alp json -m '/api/estate/[0-9]+,/api/chair/[0-9]+,/api/recommended_estate/[0-9]+' --sort avg --show-footers -o count,1xx,2xx,3xx,4xx,5xx,min,max,avg,sum,p99 --load /tmp/dump.log
+-------+-----+-----+-----+-----+-----+-------+-------+-------+-------+-------+
| COUNT | 1XX | 2XX | 3XX | 4XX | 5XX |  MIN  |  MAX  |  AVG  |  SUM  |  P99  |
+-------+-----+-----+-----+-----+-----+-------+-------+-------+-------+-------+
|     1 |   0 |   1 |   0 |   0 |   0 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 |
|     4 |   0 |   4 |   0 |   0 |   0 | 0.000 | 0.004 | 0.001 | 0.004 | 0.000 |
|     4 |   0 |   4 |   0 |   0 |   0 | 0.000 | 0.004 | 0.002 | 0.008 | 0.000 |
|     8 |   0 |   8 |   0 |   0 |   0 | 0.000 | 0.020 | 0.003 | 0.020 | 0.000 |
|     8 |   0 |   8 |   0 |   0 |   0 | 0.000 | 0.016 | 0.005 | 0.036 | 0.000 |
|    10 |   0 |   8 |   0 |   2 |   0 | 0.004 | 0.020 | 0.008 | 0.080 | 0.000 |
|     9 |   0 |   8 |   0 |   1 |   0 | 0.004 | 0.024 | 0.012 | 0.108 | 0.004 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.020 | 0.020 | 0.020 | 0.020 | 0.020 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.032 | 0.032 | 0.032 | 0.032 | 0.032 |
|     2 |   0 |   2 |   0 |   0 |   0 | 0.044 | 0.044 | 0.044 | 0.088 | 0.044 |
|     5 |   0 |   5 |   0 |   0 |   0 | 0.056 | 0.084 | 0.071 | 0.356 | 0.056 |
|    11 |   0 |  11 |   0 |   0 |   0 | 0.040 | 0.176 | 0.102 | 1.120 | 0.116 |
|     9 |   0 |   9 |   0 |   0 |   0 | 0.028 | 0.180 | 0.108 | 0.968 | 0.180 |
|     5 |   0 |   5 |   0 |   0 |   0 | 0.092 | 0.168 | 0.114 | 0.568 | 0.168 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.120 | 0.120 | 0.120 | 0.120 | 0.120 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.184 | 0.184 | 0.184 | 0.184 | 0.184 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.192 | 0.192 | 0.192 | 0.192 | 0.192 |
|     5 |   0 |   5 |   0 |   0 |   0 | 0.024 | 0.404 | 0.211 | 1.056 | 0.328 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.224 | 0.224 | 0.224 | 0.224 | 0.224 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.232 | 0.232 | 0.232 | 0.232 | 0.232 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.612 | 0.612 | 0.612 | 0.612 | 0.612 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.624 | 0.624 | 0.624 | 0.624 | 0.624 |
|     3 |   0 |   3 |   0 |   0 |   0 | 0.616 | 0.708 | 0.652 | 1.956 | 0.632 |
|     5 |   0 |   5 |   0 |   0 |   0 | 0.956 | 1.284 | 1.070 | 5.352 | 1.140 |
|     1 |   0 |   1 |   0 |   0 |   0 | 7.524 | 7.524 | 7.524 | 7.524 | 7.524 |
+-------+-----+-----+-----+-----+-----+-------+-------+-------+-------+-------+
|   100 |   0 |  97 |   0 |   3 |   0 |
+-------+-----+-----+-----+-----+-----+-------+-------+-------+-------+-------+

結果が変わりました。今回例として使用しているアクセスログファイルは100行しかないので効果はほとんど感じられませんが、ログサイズが大きくなるほど効果を発揮するはずです。

また、2つのアクセスログ解析結果を比較して、リクエスト数の増減やレスポンスタイムがどの程度改善したのか確認したい場合、alp diffが役立ちします。
先述した--dumpで出力した解析結果のファイルを2つ作成し、alp diff source.yaml target.yamlのように実行します。実行例はGitHubのドキュメントを参照してください。

alpのオプションを色々紹介しましたが、オプションが多くなると複数人で作業しているときにオプションを共有するのが面倒なこともあると思います。そのようなケースでは--configが役立ちます。指定できるオプションが多いので説明は割愛しますが、詳細は設定ファイルの例を参照してください。

また、ISUCONでの利用に特化した機能として--posがあります。このオプションはfluentdのpos_fileを真似した機能で、アクセスログファイルを集計する際にどこまで読み込んだか記憶し、以降は続きから集計することができます。この機能を活用すると、ベンチマークを実行するごとにファイルをtruncateする必要がなくなりますし、ファイルの増分だけを集計対象にできるので高速に動作します。

$ cat /path/to/access.log | alp json -m '/api/estate/[0-9]+,/api/chair/[0-9]+,/api/recommended_estate/[0-9]+' --sort avg -r --show-footers -o count,1xx,2xx,3xx,4xx,5xx,min,max,avg,sum,p99 --pos /tmp/alp.pos
+-------+-----+-----+-----+-----+-----+-------+-------+-------+-------+-------+
| COUNT | 1XX | 2XX | 3XX | 4XX | 5XX |  MIN  |  MAX  |  AVG  |  SUM  |  P99  |
+-------+-----+-----+-----+-----+-----+-------+-------+-------+-------+-------+
|     1 |   0 |   1 |   0 |   0 |   0 | 7.524 | 7.524 | 7.524 | 7.524 | 7.524 |
|     5 |   0 |   5 |   0 |   0 |   0 | 0.956 | 1.284 | 1.070 | 5.352 | 1.140 |
|     3 |   0 |   3 |   0 |   0 |   0 | 0.616 | 0.708 | 0.652 | 1.956 | 0.632 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.624 | 0.624 | 0.624 | 0.624 | 0.624 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.612 | 0.612 | 0.612 | 0.612 | 0.612 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.232 | 0.232 | 0.232 | 0.232 | 0.232 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.224 | 0.224 | 0.224 | 0.224 | 0.224 |
|     5 |   0 |   5 |   0 |   0 |   0 | 0.024 | 0.404 | 0.211 | 1.056 | 0.328 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.192 | 0.192 | 0.192 | 0.192 | 0.192 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.184 | 0.184 | 0.184 | 0.184 | 0.184 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.120 | 0.120 | 0.120 | 0.120 | 0.120 |
|     5 |   0 |   5 |   0 |   0 |   0 | 0.092 | 0.168 | 0.114 | 0.568 | 0.168 |
|     9 |   0 |   9 |   0 |   0 |   0 | 0.028 | 0.180 | 0.108 | 0.968 | 0.180 |
|    11 |   0 |  11 |   0 |   0 |   0 | 0.040 | 0.176 | 0.102 | 1.120 | 0.116 |
|     5 |   0 |   5 |   0 |   0 |   0 | 0.056 | 0.084 | 0.071 | 0.356 | 0.056 |
|     2 |   0 |   2 |   0 |   0 |   0 | 0.044 | 0.044 | 0.044 | 0.088 | 0.044 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.032 | 0.032 | 0.032 | 0.032 | 0.032 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.020 | 0.020 | 0.020 | 0.020 | 0.020 |
|     9 |   0 |   8 |   0 |   1 |   0 | 0.004 | 0.024 | 0.012 | 0.108 | 0.004 |
|    10 |   0 |   8 |   0 |   2 |   0 | 0.004 | 0.020 | 0.008 | 0.080 | 0.000 |
|     8 |   0 |   8 |   0 |   0 |   0 | 0.000 | 0.016 | 0.005 | 0.036 | 0.000 |
|     8 |   0 |   8 |   0 |   0 |   0 | 0.000 | 0.020 | 0.003 | 0.020 | 0.000 |
|     4 |   0 |   4 |   0 |   0 |   0 | 0.000 | 0.004 | 0.002 | 0.008 | 0.000 |
|     4 |   0 |   4 |   0 |   0 |   0 | 0.000 | 0.004 | 0.001 | 0.004 | 0.000 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 |
+-------+-----+-----+-----+-----+-----+-------+-------+-------+-------+-------+
|   100 |   0 |  97 |   0 |   3 |   0 |
+-------+-----+-----+-----+-----+-----+-------+-------+-------+-------+-------+

$ cat /tmp/alp.pos
40149

$ cat >> /path/to/access.log
{"time":"12/Sep/2020:11:55:34 +0000","host":"10.162.66.104","forwardedfor":"","req":"GET /api/chair/low_priced HTTP/1.1","status":"200","method":"GET","uri":"/api/chair/low_priced","body_bytes":12153,"referer":"","ua":"ISUCON Edge-aea5877d-df92-4065-a69a-2e7d154fbc41","request_time":0.004,"cache":"","runtime":"","response_time":"0.000","vhost":"10.162.66.103"}
^C

$ cat /path/to/access.log | alp json -m '/api/estate/[0-9]+,/api/chair/[0-9]+,/api/recommended_estate/[0-9]+' --sort avg -r --show-footers -o count,1xx,2xx,3xx,4xx,5xx,min,max,avg,sum,p99 --pos /tmp/alp.pos
+-------+-----+-----+-----+-----+-----+-------+-------+-------+-------+-------+
| COUNT | 1XX | 2XX | 3XX | 4XX | 5XX |  MIN  |  MAX  |  AVG  |  SUM  |  P99  |
+-------+-----+-----+-----+-----+-----+-------+-------+-------+-------+-------+
|     1 |   0 |   1 |   0 |   0 |   0 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 |
+-------+-----+-----+-----+-----+-----+-------+-------+-------+-------+-------+
|     1 |   0 |   1 |   0 |   0 |   0 |
+-------+-----+-----+-----+-----+-----+-------+-------+-------+-------+-------+

$ cat /tmp/alp.pos
40512

/tmp/alp.posにどこまで読み込んだかバイト数が記録されており、1行ログを追加したあとに再度実行すると増分だけが集計されていることがわかります。また、/tmp/alp.posに記録されているバイト数が更新されています。
このように、毎回--posをつけていると読み込んだバイト数はどんどん更新されていきますが、更新したくない場合は--posと一緒に--nosave-posを使えば抑制できます。

フィルタ

alpにはフィルタ機能があり、マッチしたアクセスログだけを集計することができます。詳しく説明すると長くなりすぎるので詳細はドキュメントを参照いただければと思いますが、簡単な例としてHTTPメソッドをGETだけ集計する例を示します。

$ cat /path/to/access.log | alp json -m '/api/estate/[0-9]+,/api/chair/[0-9]+,/api/recommended_estate/[0-9]+' --sort avg -r --show-footers -o count,1xx,2xx,3xx,4xx,5xx,min,max,avg,sum,p99 --filters 'Method == "GET"'
+-------+-----+-----+-----+-----+-----+-------+-------+-------+-------+-------+
| COUNT | 1XX | 2XX | 3XX | 4XX | 5XX |  MIN  |  MAX  |  AVG  |  SUM  |  P99  |
+-------+-----+-----+-----+-----+-----+-------+-------+-------+-------+-------+
|     5 |   0 |   5 |   0 |   0 |   0 | 0.956 | 1.284 | 1.070 | 5.352 | 1.140 |
|     3 |   0 |   3 |   0 |   0 |   0 | 0.616 | 0.708 | 0.652 | 1.956 | 0.632 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.624 | 0.624 | 0.624 | 0.624 | 0.624 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.612 | 0.612 | 0.612 | 0.612 | 0.612 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.232 | 0.232 | 0.232 | 0.232 | 0.232 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.224 | 0.224 | 0.224 | 0.224 | 0.224 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.192 | 0.192 | 0.192 | 0.192 | 0.192 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.184 | 0.184 | 0.184 | 0.184 | 0.184 |
|     1 |   0 |   1 |   0 |   0 |   0 | 0.120 | 0.120 | 0.120 | 0.120 | 0.120 |
|     5 |   0 |   5 |   0 |   0 |   0 | 0.092 | 0.168 | 0.114 | 0.568 | 0.168 |
|     9 |   0 |   9 |   0 |   0 |   0 | 0.028 | 0.180 | 0.108 | 0.968 | 0.180 |
|    11 |   0 |  11 |   0 |   0 |   0 | 0.040 | 0.176 | 0.102 | 1.120 | 0.116 |
|     5 |   0 |   5 |   0 |   0 |   0 | 0.056 | 0.084 | 0.071 | 0.356 | 0.056 |
|     2 |   0 |   2 |   0 |   0 |   0 | 0.044 | 0.044 | 0.044 | 0.088 | 0.044 |
|     9 |   0 |   8 |   0 |   1 |   0 | 0.004 | 0.024 | 0.012 | 0.108 | 0.004 |
|    10 |   0 |   8 |   0 |   2 |   0 | 0.004 | 0.020 | 0.008 | 0.080 | 0.000 |
|     8 |   0 |   8 |   0 |   0 |   0 | 0.000 | 0.016 | 0.005 | 0.036 | 0.000 |
|     8 |   0 |   8 |   0 |   0 |   0 | 0.000 | 0.020 | 0.003 | 0.020 | 0.000 |
|     4 |   0 |   4 |   0 |   0 |   0 | 0.000 | 0.004 | 0.002 | 0.008 | 0.000 |
|     4 |   0 |   4 |   0 |   0 |   0 | 0.000 | 0.004 | 0.001 | 0.004 | 0.000 |
+-------+-----+-----+-----+-----+-----+-------+-------+-------+-------+-------+
|    90 |   0 |  87 |   0 |   3 |   0 |
+-------+-----+-----+-----+-----+-----+-------+-------+-------+-------+-------+

まとめ

ISUCON10オンライン予選問題のアクセスログを例に、alpの基本よりも少し発展した使い方を紹介しました。
ISUCONに参加する方もそうでない方にも役立てば幸いです。

要望があればGitHub Issueか本記事にコメントお願いします。また、PullRequestも歓迎しています！

基本編はこちら

おまけ

ISUCON用にアクセスログやスロークエリログを自動で集計するツールも作成しているのでそちらも紹介します。

https://github.com/tkuchiki/watchcat

watchcatは、ファイルサイズ・更新日時を監視して、ファイルがしばらく更新されなくなり、かつ指定したバイト数以上増加したときに増分を任意のコマンドにpipeで渡すことができます。

alpを例に使い方を説明します。以下のようなshellscriptを用意しておき(ファイルはcommand.shとします)、

#!/bin/bash

cat - | alp json

以下のように実行します。

$ watchcat --interval 5s --no-changes=10 --filesize=1024 --file /path/to/access.log --command command.sh

このとき、watchcatは以下のように動作します。

5秒ごとに/path/to/access.logのファイルサイズと更新日時をチェック
最終更新日時から10秒以上経過
かつ、1024バイト以上ファイルが増加していたら
ファイルの増分をcommand.shにpipeで渡す
コマンドを実行したあとは、ファイルをどこまで読み込んだか記憶

--filesizeを適切に設定すると、ベンチマークを実行する前に少しアプリを触ってみたときのログなどを集計対象から除外できる想定で、--no-changesで指定した時間(秒)以上ファイルが更新されておらず、--filesizeで指定したバイト数未満しか更新されていないと、ファイルをどこまで読み込んだかの情報を更新して、次回の集計の対象外にします。

これを使うと、ベンチマーク実行中は常にログファイルが更新されているのでalpで集計されず、ベンチマークが完了してログファイルが更新されなくなったらalpで集計する、けれどアプリを少し触ったときのログは集計対象から除外する、ということができます(アプリを触って即ベンチマークを実行した場合はその限りではありません)。
上記の例ではcommand.shでalpを実行するだけなので意味はないですが、その結果をSlackやGitHub Issueにpostすると便利です。alpは--output mdを指定することで出力をテーブル形式からmarkdownのテーブル形式に変更することができますので、私はGitHub Issueにpostするときにこのオプションを使っています。

アクセスログやスロークエリログを自動集計するようにしたいけれど、まだその仕組を持っていない方は是非使ってみていただけると幸いです。

フィルタ

まとめ

おまけ

Discussion