alpとは

alp(Access Log Profiler) はWebサーバーのアクセスログの集計ツール。

所定の形式で出力されたアクセスログを解析してレスポンスタイムを集計できる。

準備

alpのインストール

Releases · tkuchiki/alp から対応するOS向けの最新版をダウンロードして解凍する。

$ curl -L -O https://github.com/tkuchiki/alp/releases/download/v1.0.21/alp_linux_amd64.zip
$ unzip alp_linux_amd64.zip
$ sudo mv alp /usr/local/bin/
$ alp --version
1.0.21

nginxのアクセスログの設定

nginxのアクセスログの設定は以下の通り。/etc/nginx/nginx.confなどの設定ファイルのhttpブロックに追加する。
alpはltsvやjsonなどに対応しているがここではltsv形式で出力する。

log_format ltsv "time:$time_local"
                "\thost:$remote_addr"
                "\tforwardedfor:$http_x_forwarded_for"
                "\treq:$request"
                "\tstatus:$status"
                "\tmethod:$request_method"
                "\turi:$request_uri"
                "\tsize:$body_bytes_sent"
                "\treferer:$http_referer"
                "\tua:$http_user_agent"
                "\treqtime:$request_time"
                "\tcache:$upstream_http_x_cache"
                "\truntime:$upstream_http_x_runtime"
                "\tapptime:$upstream_response_time"
                "\tvhost:$host";
access_log /var/log/nginx/access.log ltsv;

alpコマンドで集計

基本

alpコマンドは標準入力からアクセスログを受け、以下のように実行する。

$ cat /var/log/nginx/access.log | alp ltsv --sort sum -o count,2xx,3xx,4xx,5xx,method,uri,avg,sum

alpコマンドの引数の意味は以下の通り。

  • ltsv: 第一引数にログのフォーマットを指定する。今回はLTSVでアクセスログを出力しているのでltsvを指定する。JSONの場合はjsonを指定する。
  • –sort: 集計結果をどの項目でソートするかを指定する。今回はレスポンスタイムの合計値であるsumを指定する。-oオプションを指定せずに出力するとすべての項目が出力されるのでそこから選択するとよい。
  • -o: 集計結果の出力項目を指定する。今回はcount(アクセス数)、2xx(2xxのアクセス数)、3xx(3xxのアクセス数)、4xx(4xxのアクセス数)、5xx(5xxのアクセス数)、method(メソッド)、uri(URI)、avg(平均レスポンスタイム)、sum(レスポンスタイムの合計)を指定する。-oオプションを指定せずに出力するとすべての項目が出力されるのでそこから選択するとよい。

Too many URI’s (5000 or less)

デフォルトでは5000行を超える場合は以下のエラーが発生する。

$ cat /var/log/nginx/access.log | alp ltsv -o count,2xx,3xx,4xx,5xx,method,uri,avg,sum
2023/10/14 06:33:50 Too many URI's (5000 or less)

上記のエラーが発生する場合は--limitオプションを指定して上限を変更する。

$ cat /var/log/nginx/access.log | alp ltsv --limit 10000 -o count,2xx,3xx,4xx,5xx,method,uri,avg,sum
------+-----+------+-----+-----+-----+--------+---------------------------------------------+--------+--------+---------+--------+--------+--------+--------+--------+------------+------------+-------------+------------+
| 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 | POST   | /initialize                                 | 27.756 | 27.756 |  27.756 | 27.756 | 27.756 | 27.756 | 27.756 |  0.000 |     19.000 |     19.000 |      19.000 |     19.000 |
|     1 |   0 |    1 |   0 |   0 |   0 | GET    | /.env                                       |  0.000 |  0.000 |   0.000 |  0.000 |  0.000 |  0.000 |  0.000 |  0.000 |    396.000 |    396.000 |     396.000 |    396.000 |
|     1 |   0 |    0 |   0 |   1 |   0 | POST   | /user/2000095052/gacha/draw/37/10           |  0.288 |  0.288 |   0.288 |  0.288 |  0.288 |  0.288 |  0.288 |  0.000 |      0.000 |      0.000 |       0.000 |      0.000 |
|     1 |   0 |    1 |   0 |   0 |   0 | GET    | /admin/user/372207341                       |  0.124 |  0.124 |   0.124 |  0.124 |  0.124 |  0.124 |  0.124 |  0.000 |  42018.000 |  42018.000 |   42018.000 |  42018.000 |
|     1 |   0 |    0 |   0 |   1 |   0 | POST   | /user/368435786/gacha/draw/37/10            |  0.284 |  0.284 |   0.284 |  0.284 |  0.284 |  0.284 |  0.284 |  0.000 |      0.000 |      0.000 |       0.000 |      0.000 |
・
・
・

10000で足りなければさらに数値を増やす。

後述でURIパターンごとにまとめるとそれほど多くならないので不要になるが、alpコマンド自害が正常に実行できるかを確認するために実行している。
不要であれば飛ばしてよい。

URIパターンごとにまとめる

上記のコマンドでは、/user/822516924/home,/user/368435786/home、…、のようにパスパラメータが異なるだけで同じURIパターンのURLが異なるURIとして集計される。
通常これらは同じルーティングで処理されるので、URIパターンごとにまとめて集計したい。

URIパターンをまとめて集計するには-mを指定して以下のように実行する。

$ cat /var/log/nginx/access.log | alp ltsv -m "/user/.+/home" --limit 100000 -o count,2xx,3xx,4xx,5xx,method,uri,avg,sum
(省略)
|  2826 | 2799 |   0 |  27 |   0 | GET    | /user/.+/home                               |  0.144 | 406.708 |
(省略)

上記のように/user/.+/homeのように正規表現でパターンを指定すると/user/.+/homeの形式のURIが1行にまとめて集計される。

複数のURIパターンを指定する場合はカンマ(,)で区切って指定する。

$ cat /var/log/nginx/access.log | alp ltsv -m "/user/.+/home,/user/.+/reward" --limit 100000 -o count,2xx,3xx,4xx,5xx,method,uri,avg,sum
(省略)
|  2326 | 2321 |   0 |   5 |   0 | POST   | /user/.+/reward                             |  0.096 | 222.604 |
|  2826 | 2799 |   0 |  27 |   0 | GET    | /user/.+/home                               |  0.144 | 406.708 |
(省略)

繰り返し実行してURIパターンを追加していくとよい。

表示項目

alpコマンドの表示項目は以下の通り。

  • COUNT: アクセス回数
  • 1XX: 1xxのアクセス回数
  • 2XX: 2xxのアクセス回数
  • 3XX: 3xxのアクセス回数
  • 4XX: 4xxのアクセス回数
  • 5XX: 5xxのアクセス回数
  • METHOD: HTTPメソッド
  • URI: URI
  • MIN: レスポンスタイムの最小値
  • MAX: レスポンスタイムの最大値
  • SUM: レスポンスタイムの合計
  • AVG: レスポンスタイムの平均値
  • P90: レスポンスタイムの90パーセンタイル
  • P95: レスポンスタイムの95パーセンタイル
  • P99: レスポンスタイムの99パーセンタイル
  • STDDEV: レスポンスタイムの標準偏差
  • MIN(BODY): レスポンスボディサイズの最小値
  • MAX(BODY): レスポンスボディサイズの最大値
  • SUM(BODY): レスポンスボディサイズの合計
  • AVG(BODY): レスポンスボディサイズの平均値

逆順で表示

--reverseオプションで指定するとソートの逆順で表示される。

$ cat /var/log/nginx/access.log | alp ltsv --sort sum --reverse -o count,2xx,3xx,4xx,5xx,method,uri,avg,sum

よく見る項目

sumが大きい順に表示するとレスポンスタイムが長い順に表示される。
つぎにそのcountを確認し、小さい場合は1回のリクエストの処理に時間がかかっているのでその処理を見直す。
countが大きい場合はリクエスト数が多いのでそのリクエストを減らすか、処理を高速化する。

＼第一線のプログラマーの行動原理を学べる！／

プログラマが知るべき97のこと

Amazonで見る