alpを使ってnginxのログを解析する

はじめに

今年もISUCONの季節がやってきました。
私は去年初めて出場し、今年も出場します。

去年使ってみて便利だった、alpでのnginxのログ解析のやり方を書こうと思います。

alpとは

アクセスログの解析ツールです。
特定のフォーマット形式で吐き出されたログを解析することができます。
ltsv, jsonに加えて正規表現にマッチするログの解析や、解析結果のdumpファイルの比較などもできます。
詳しくはREADMEの「使い方」をご覧ください。

alpでnginxのログ解析をする

前提

今回はnginxでltsv形式のログを吐き出し、解析を行います。

ISUCON13の環境を例に解説をします。
検証・素振りにはISUNARABEがとても便利です。

(※ ISUCON13での素振りの際に、証明書の期限切れが発生する場合はこちらのissueを参照してください)

インストール

最新のリリースであるv1.0.21をダウンロードしてインストールします。

$ wget https://github.com/tkuchiki/alp/releases/download/v1.0.21/alp_linux_amd64.tar.gz
$ tar xzf alp_linux_amd64.tar.gz
$ sudo install alp /usr/local/bin/alp
$ alp -v
# 1.0.21

nginxのログフォーマットの変更

ltsv形式でnginxがログを吐くように、設定ファイルを変更します。

/etc/nginx/nginx.conf

http {
    # ...
    log_format ltsv "time:$time_local\t"
                    "host:$remote_addr\t"
                    "forwardedfor:$http_x_forwarded_for\t"
                    "req:$request\t"
                    "status:$status\t"
                    "method:$request_method\t"
                    "uri:$request_uri\t"
                    "size:$body_bytes_sent\t"
                    "referer:$http_referer\t"
                    "ua:$http_user_agent\t"
                    "reqtime:$request_time\t"
                    "cache:$upstream_http_x_cache\t"
                    "runtime:$upstream_http_x_runtime\t"
                    "apptime:$upstream_response_time\t"
                    "vhost:$host";

    access_log /var/log/nginx/access.log ltsv;
    error_log /var/log/nginx/error.log;

    # ...
}

設定ファイルを変更したので、適用します。

sudo nginx -t # syntax check
sudo systemctl restart nginx # nginxの再起動

ログは、/var/log/nginx/access.logに吐き出されるので、benchmarkを実行し実際にltsv形式で出力されていることを確認します。

alpでのログ解析

$ sudo alp ltsv --file /var/log/nginx/access.log

以下のような出力が得られます。

+-------+-----+-----+-----+-----+-----+--------+----------------------------------------------+--------+--------+---------+--------+--------+--------+--------+--------+-----------+------------+--------------+-----------+
| 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    | /api/user/satomiishii0/theme                 | 0.216  | 0.216  | 0.216   | 0.216  | 0.216  | 0.216  | 0.216  | 0.000  | 38.000    | 38.000     | 38.000       | 38.000    |
| 1     | 0   | 1   | 0   | 0   | 0   | GET    | /api/user/mai270/icon                        | 0.036  | 0.036  | 0.036   | 0.036  | 0.036  | 0.036  | 0.036  | 0.000  | 6969.000  | 6969.000   | 6969.000     | 6969.000  |
| 1     | 0   | 0   | 0   | 1   | 0   | POST   | /api/livestream/7532/moderate                | 0.676  | 0.676  | 0.676   | 0.676  | 0.676  | 0.676  | 0.676  | 0.000  | 0.000     | 0.000      | 0.000        | 0.000     |
| 1     | 0   | 0   | 0   | 1   | 0   | GET    | /api/user/taichi160/icon                     | 0.360  | 0.360  | 0.360   | 0.360  | 0.360  | 0.360  | 0.360  | 0.000  | 0.000     | 0.000      | 0.000        | 0.000     |
# ...

遅いエンドポイントの特定

パスパラメータが異なるだけのリクエストをまとめ、P99の降順で並べます。
以下のようなYAMLファイルを用意し、configオプションに指定します。

alp.yaml

matching_groups:
  - /api/user/[^/]+/statistics
  - /api/user/[^/]+/icon
  - /api/livestream/[^/]+/statistics
  - /api/livestream/[^/]+/moderate
  - /api/livestream/[^/]+/livecomment
  - /api/livestream/[^/]+/reaction
  - /api/livestream/[^/]+/report
  - /api/livestream/[^/]+/ngwords
  - /api/livestream/[^/]+/enter
  - /api/livestream/[^/]+/exit
sort: p99
reverse: true

$ sudo alp ltsv --config alp.yaml --file /var/log/nginx/access.log

+-------+-----+------+-----+-----+-----+--------+-----------------------------------+--------+--------+---------+--------+--------+--------+--------+--------+-----------+------------+--------------+-----------+
| COUNT | 1XX | 2XX  | 3XX | 4XX | 5XX | METHOD |                URI                |  MIN   |  MAX   |   SUM   |  AVG   |  P90   |  P95   |  P99   | STDDEV | MIN(BODY) | MAX(BODY)  |  SUM(BODY)   | AVG(BODY) |
+-------+-----+------+-----+-----+-----+--------+-----------------------------------+--------+--------+---------+--------+--------+--------+--------+--------+-----------+------------+--------------+-----------+
| 6     | 0   | 2    | 0   | 4   | 0   | GET    | /api/user/[^/]+/statistics        | 2.760  | 20.004 | 70.864  | 11.811 | 20.004 | 20.004 | 20.004 | 8.234  | 0.000     | 139.000    | 272.000      | 45.333    |
| 1     | 0   | 1    | 0   | 0   | 0   | POST   | /api/initialize                   | 14.464 | 14.464 | 14.464  | 14.464 | 14.464 | 14.464 | 14.464 | 0.000  | 27.000    | 27.000     | 27.000       | 27.000    |
| 41    | 0   | 40   | 0   | 1   | 0   | GET    | /api/livestream/search            | 0.172  | 7.664  | 125.660 | 3.065  | 4.920  | 7.164  | 7.664  | 1.984  | 0.000     | 126617.000 | 2992778.000  | 72994.585 |
| 2     | 0   | 2    | 0   | 0   | 0   | GET    | /api/livestream/[^/]+/statistics  | 6.212  | 6.268  | 12.480  | 6.240  | 6.268  | 6.268  | 6.268  | 0.028  | 100.000   | 102.000    | 202.000      | 101.000   |
| 19    | 0   | 17   | 0   | 2   | 0   | POST   | /api/livestream/[^/]+/moderate    | 0.248  | 5.224  | 55.724  | 2.933  | 5.080  | 5.224  | 5.224  | 1.331  | 0.000     | 23.000     | 391.000      | 20.579    |
| 187   | 0   | 185  | 0   | 2   | 0   | GET    | /api/livestream/[^/]+/livecomment | 0.008  | 2.600  | 113.988 | 0.610  | 1.424  | 1.624  | 2.156  | 0.522  | 0.000     | 34375.000  | 2013928.000  | 10769.668 |
| 222   | 0   | 218  | 0   | 4   | 0   | GET    | /api/livestream/[^/]+/reaction    | 0.008  | 2.560  | 106.204 | 0.478  | 1.220  | 1.520  | 1.968  | 0.512  | 0.000     | 33256.000  | 1771555.000  | 7979.977  |
| 91    | 0   | 87   | 0   | 4   | 0   | POST   | /api/livestream/reservation       | 0.176  | 1.348  | 48.096  | 0.529  | 1.080  | 1.224  | 1.348  | 0.410  | 0.000     | 1458.000   | 97650.000    | 1073.077  |
| 269   | 0   | 266  | 0   | 2   | 1   | POST   | /api/register                     | 0.036  | 1.412  | 50.436  | 0.187  | 0.372  | 0.556  | 1.160  | 0.192  | 0.000     | 516.000    | 125020.000   | 464.758   |
| 69    | 0   | 69   | 0   | 0   | 0   | GET    | /api/tag                          | 0.004  | 1.004  | 8.452   | 0.122  | 0.348  | 0.600  | 1.004  | 0.200  | 6089.000  | 6095.000   | 420441.000   | 6093.348  |
| 264   | 0   | 261  | 0   | 3   | 0   | POST   | /api/livestream/[^/]+/livecomment | 0.004  | 2.132  | 71.156  | 0.270  | 0.456  | 0.568  | 0.984  | 0.194  | 57.000    | 2714.000   | 527639.000   | 1998.633  |
| 265   | 0   | 265  | 0   | 0   | 0   | POST   | /api/icon                         | 0.012  | 1.096  | 37.212  | 0.140  | 0.336  | 0.480  | 0.972  | 0.167  | 14.000    | 16.000     | 4132.000     | 15.592    |
| 30    | 0   | 30   | 0   | 0   | 0   | GET    | /api/livestream/[^/]+/report      | 0.012  | 0.968  | 5.824   | 0.194  | 0.568  | 0.656  | 0.968  | 0.235  | 3.000     | 21865.000  | 71291.000    | 2376.367  |
| 181   | 0   | 179  | 0   | 2   | 0   | POST   | /api/livestream/[^/]+/reaction    | 0.008  | 1.472  | 32.644  | 0.180  | 0.372  | 0.476  | 0.864  | 0.167  | 0.000     | 2201.000   | 326450.000   | 1803.591  |
| 22    | 0   | 22   | 0   | 0   | 0   | GET    | /api/livestream/[^/]+/ngwords     | 0.004  | 0.768  | 3.972   | 0.181  | 0.340  | 0.404  | 0.768  | 0.160  | 5.000     | 137.000    | 242.000      | 11.000    |
# ...

これで遅いエンドポイントが特定できるようになったので、頑張って潰していきます。

参考文献