アクセスログの集計ツールのalpが良い

新年あけましておめでとうございます。 年末にかかった風邪がようやく治りかけてきたので、isucon本で気になるところを手元で試したりしています。

達人が教えるWebパフォーマンスチューニング 〜ISUCONから学ぶ高速化の実践

達人が教えるWebパフォーマンスチューニング 〜ISUCONから学ぶ高速化の実践

Amazon
こちらの本、トップレビューは酷評されてますが、isucon対策本として読むには面白かったです。
　

alp

本書で紹介されているalpが非常に良いです。
アクセスログをコマンド1発で集計してくれる優れものです。
昔はawkとか使って集計してましたよね。便利。

使い方

# nginx の log_formatをjsonで出力
log_format json escape=json '{"time": "$time_iso8601",'
  '"host": "$remote_addr",'
  '"port": "$remote_port",'
  '"method": "$request_method",'
  '"uri": "$request_uri",'
  '"status": "$status",'
  '"body_bytes": "$body_bytes_sent",'
  '"referer": "$http_referer",'
  '"ua": "$http_user_agent",'
  '"request_time": "$request_time",'
  '"apptime": "$upstream_response_time"}';

# ログの例
{"time": "2023-01-01T11:48:37+00:00","host": "172.18.0.1","port": "61388","method": "GET","uri": "/","status": "200","body_bytes": "35624","referer": "","ua": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/107.0.0.0 Safari/537.36","request_time": "10.961","apptime": "10.963"}
...

こんな感じで簡単に解析してくれます。

$ cat logs/nginx/access.log | alp json
+-------+-----+-----+-----+-----+-----+--------+------------------+--------+--------+--------+--------+--------+--------+--------+--------+-------------+-------------+-------------+-------------+
| COUNT | 1XX | 2XX | 3XX | 4XX | 5XX | METHOD |       URI        |  MIN   |  MAX   |  SUM   |  AVG   |  P90   |  P95   |  P99   | STDDEV |  MIN(BODY)  |  MAX(BODY)  |  SUM(BODY)  |  AVG(BODY)  |
+-------+-----+-----+-----+-----+-----+--------+------------------+--------+--------+--------+--------+--------+--------+--------+--------+-------------+-------------+-------------+-------------+
| 1     | 0   | 1   | 0   | 0   | 0   | GET    | /                | 10.961 | 10.961 | 10.961 | 10.961 | 10.961 | 10.961 | 10.961 | 0.000  | 35624.000   | 35624.000   | 35624.000   | 35624.000   |
| 1     | 0   | 1   | 0   | 0   | 0   | GET    | /image/10000.png | 0.088  | 0.088  | 0.088  | 0.088  | 0.088  | 0.088  | 0.088  | 0.000  | 1056749.000 | 1056749.000 | 1056749.000 | 1056749.000 |
| 1     | 0   | 1   | 0   | 0   | 0   | GET    | /image/9998.jpg  | 0.082  | 0.082  | 0.082  | 0.082  | 0.082  | 0.082  | 0.082  | 0.000  | 61656.000   | 61656.000   | 61656.000   | 61656.000   |
| 1     | 0   | 1   | 0   | 0   | 0   | GET    | /image/9995.jpg  | 0.101  | 0.101  | 0.101  | 0.101  | 0.101  | 0.101  | 0.101  | 0.000  | 123364.000  | 123364.000  | 123364.000  | 123364.000  |
| 1     | 0   | 1   | 0   | 0   | 0   | GET    | /image/9997.jpg  | 0.116  | 0.116  | 0.116  | 0.116  | 0.116  | 0.116  | 0.116  | 0.000  | 176404.000  | 176404.000  | 176404.000  | 176404.000  |
| 1     | 0   | 1   | 0   | 0   | 0   | GET    | /image/9996.jpg  | 0.138  | 0.138  | 0.138  | 0.138  | 0.138  | 0.138  | 0.138  | 0.000  | 374805.000  | 374805.000  | 374805.000  | 374805.000  |
| 1     | 0   | 1   | 0   | 0   | 0   | GET    | /image/9999.jpg  | 0.146  | 0.146  | 0.146  | 0.146  | 0.146  | 0.146  | 0.146  | 0.000  | 89928.000   | 89928.000   | 89928.000   | 89928.000   |
| 1     | 0   | 1   | 0   | 0   | 0   | GET    | /image/9994.jpg  | 0.068  | 0.068  | 0.068  | 0.068  | 0.068  | 0.068  | 0.068  | 0.000  | 105154.000  | 105154.000  | 105154.000  | 105154.000  |
| 1     | 0   | 1   | 0   | 0   | 0   | GET    | /image/9993.jpg  | 0.055  | 0.055  | 0.055  | 0.055  | 0.055  | 0.055  | 0.055  | 0.000  | 85546.000   | 85546.000   | 85546.000   | 85546.000   |
| 1     | 0   | 1   | 0   | 0   | 0   | GET    | /image/9991.jpg  | 0.067  | 0.067  | 0.067  | 0.067  | 0.067  | 0.067  | 0.067  | 0.000  | 153465.000  | 153465.000  | 153465.000  | 153465.000  |
| 1     | 0   | 1   | 0   | 0   | 0   | GET    | /image/9990.jpg  | 0.066  | 0.066  | 0.066  | 0.066  | 0.066  | 0.066  | 0.066  | 0.000  | 102371.000  | 102371.000  | 102371.000  | 102371.000  |
| 1     | 0   | 1   | 0   | 0   | 0   | GET    | /image/9989.jpg  | 0.048  | 0.048  | 0.048  | 0.048  | 0.048  | 0.048  | 0.048  | 0.000  | 107460.000  | 107460.000  | 107460.000  | 107460.000  |
| 1     | 0   | 1   | 0   | 0   | 0   | GET    | /image/9988.jpg  | 0.063  | 0.063  | 0.063  | 0.063  | 0.063  | 0.063  | 0.063  | 0.000  | 111515.000  | 111515.000  | 111515.000  | 111515.000  |
| 1     | 0   | 1   | 0   | 0   | 0   | GET    | /image/9987.jpg  | 0.086  | 0.086  | 0.086  | 0.086  | 0.086  | 0.086  | 0.086  | 0.000  | 367388.000  | 367388.000  | 367388.000  | 367388.000  |
| 1     | 0   | 1   | 0   | 0   | 0   | GET    | /image/9986.jpg  | 0.094  | 0.094  | 0.094  | 0.094  | 0.094  | 0.094  | 0.094  | 0.000  | 86624.000   | 86624.000   | 86624.000   | 86624.000   |
| 1     | 0   | 1   | 0   | 0   | 0   | GET    | /image/9985.jpg  | 0.093  | 0.093  | 0.093  | 0.093  | 0.093  | 0.093  | 0.093  | 0.000  | 83264.000   | 83264.000   | 83264.000   | 83264.000   |
| 1     | 0   | 1   | 0   | 0   | 0   | GET    | /image/9983.jpg  | 0.093  | 0.093  | 0.093  | 0.093  | 0.093  | 0.093  | 0.093  | 0.000  | 98082.000   | 98082.000   | 98082.000   | 98082.000   |
| 1     | 0   | 1   | 0   | 0   | 0   | GET    | /image/9982.jpg  | 0.087  | 0.087  | 0.087  | 0.087  | 0.087  | 0.087  | 0.087  | 0.000  | 149874.000  | 149874.000  | 149874.000  | 149874.000  |
| 1     | 0   | 1   | 0   | 0   | 0   | GET    | /image/9981.jpg  | 0.077  | 0.077  | 0.077  | 0.077  | 0.077  | 0.077  | 0.077  | 0.000  | 81386.000   | 81386.000   | 81386.000   | 81386.000   |
| 1     | 0   | 1   | 0   | 0   | 0   | GET    | /image/9980.jpg  | 0.037  | 0.037  | 0.037  | 0.037  | 0.037  | 0.037  | 0.037  | 0.000  | 95919.000   | 95919.000   | 95919.000   | 95919.000   |
| 1     | 0   | 1   | 0   | 0   | 0   | GET    | /image/9979.jpg  | 0.040  | 0.040  | 0.040  | 0.040  | 0.040  | 0.040  | 0.040  | 0.000  | 66941.000   | 66941.000   | 66941.000   | 66941.000   |
+-------+-----+-----+-----+-----+-----+--------+------------------+--------+--------+--------+--------+--------+--------+--------+--------+-------------+-------------+-------------+-------------+

使い方の詳細

ここに詳細が記載されていますが、フィルターやマージも可能です。GETだけとか、特定日以降とかでも絞れます。
alp/usage_samples.md at main · tkuchiki/alp

以下、日時でフィルターして、画像をひとまとめにする例。

$ cat logs/nginx/access.log | alp json -m "/image/*" --filters "Time > '2023-01-01T11:48:36+00:00'"
+-------+-----+-----+-----+-----+-----+--------+----------+--------+--------+--------+--------+--------+--------+--------+--------+-----------+-------------+-------------+------------+
| COUNT | 1XX | 2XX | 3XX | 4XX | 5XX | METHOD |   URI    |  MIN   |  MAX   |  SUM   |  AVG   |  P90   |  P95   |  P99   | STDDEV | MIN(BODY) |  MAX(BODY)  |  SUM(BODY)  | AVG(BODY)  |
+-------+-----+-----+-----+-----+-----+--------+----------+--------+--------+--------+--------+--------+--------+--------+--------+-----------+-------------+-------------+------------+
| 1     | 0   | 1   | 0   | 0   | 0   | GET    | /        | 10.961 | 10.961 | 10.961 | 10.961 | 10.961 | 10.961 | 10.961 | 0.000  | 35624.000 | 35624.000   | 35624.000   | 35624.000  |
| 20    | 0   | 20  | 0   | 0   | 0   | GET    | /image/* | 0.037  | 0.146  | 1.645  | 0.082  | 0.116  | 0.138  | 0.146  | 0.028  | 61656.000 | 1056749.000 | 3577895.000 | 178894.750 |
+-------+-----+-----+-----+-----+-----+--------+----------+--------+--------+--------+--------+--------+--------+--------+--------+-----------+-------------+-------------+------------+

補足

本書には、集計に利用するJSONキーとして、以下が必要と記載されてました。
method, uri, status, body_bytes, response_time
キー名が異なる場合は、optionで設定可能です。

ただ、ドキュメントのどこにも見当たらなかったので、ソースを見てみると、確かにそれっぽいことをやっていました。
alp/alp.go at main · tkuchiki/alp