はじめに
APIのパフォーマンスを改善するうえで、「どのエンドポイントがボトルネックになっているか」「アクセスが集中しているURIはどれか」「ステータスコードの分布はどうか」といった情報の把握は欠かせません。とは言え、パパっとボトルネックを見つけるのは（きっと）大変だったりします。
alp（Access Log Profiler）は、こうしたアクセスログの分析を簡単に行えるツールです。NginxなどのWebサーバが出力するログを集計・可視化することで、パフォーマンス課題の解決を助けてくれます！
本記事では alp の導入から使い方や活用例までを紹介します。特に開発中のプロジェクトで「なんとなくAPIが重そう」と感じたときや、ボトルネック調査のきっかけが欲しいときに役立つと信じています。
alpとは
alp は Nginx や Apache のアクセスログを集計・可視化するツールです。
JSON形式にも対応しており、カスタマイズしたログでも扱えます。
主な特徴
- パス単位でリクエストを集計（パラメータはマスキング）
- ステータスコード別の集計
- レスポンスタイムの min / avg / max / sum を出せる
- jsonログにも対応（←重要！）
インストール方法
Macの場合
brew install alp
Linuxの場合
$ 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
# バージョンが出力されればOK
NginxログをJSON形式で出力する
alp を活かすためにも、NginxのログをJSON形式にすると便利です。
nginx.conf の例
log_format json_log escape=json '{'
'"time":"$time_iso8601",'
'"host":"$remote_addr",'
'"method":"$request_method",'
'"uri":"$request_uri",'
'"status":"$status",'
'"body_bytes":"$body_bytes_sent",'
'"referer":"$http_referer",'
'"ua":"$http_user_agent",'
'"request_time":"$request_time",'
'"response_time":"$upstream_response_time"'
'}';
access_log /var/log/nginx/access.log json_log;
※カスタマイズは良い感じに出来るので、お好みで調整してください
Nginxを再起動して反映
nginx -t && systemctl reload nginx
使い方
READMEを読むのが良いとは思います。分かりやすく丁寧に書かれています！
sampleはこっち
とは言え少しだけ。
下記を実行すればそれっぽいのが出てきます。
cat /var/log/nginx/access.log \
| perl -pE 's{/users/[^/]+}{/users/***}' \
| perl -pE 's{/(assets|images)/.*"}{/$1/***"}' \
| alp json -o count,method,uri,min,avg,max,sum,2xx,3xx,4xx,5xx -r
出力例
+-------+--------+---------------------------------------------------+-------+-------+-------+-------+-----+-----+-----+-----+
| COUNT | METHOD | URI | MIN | AVG | MAX | SUM | 2XX | 3XX | 4XX | 5XX |
+-------+--------+---------------------------------------------------+-------+-------+-------+-------+-----+-----+-----+-----+
| 3 | GET | /api/users/*** | 0.104 | 0.134 | 0.221 | 0.403 | 3 | 0 | 0 | 0 |
| 2 | POST | /api/posts/***/like | 0.214 | 0.316 | 0.418 | 0.632 | 2 | 0 | 0 | 0 |
| 5 | GET | /api/projects/***/tasks/***/comments | 0.215 | 0.328 | 0.764 | 1.642 | 5 | 0 | 0 | 0 |
+-------+--------+---------------------------------------------------+-------+-------+-------+-------+-----+-----+-----+-----+
各列の意味
| 列名 | 説明 |
|---|---|
| COUNT | 該当エンドポイントの呼び出し回数 |
| METHOD | HTTPメソッド（GET/POSTなど） |
| URI | 正規化されたURLパス |
| MIN | 最小レスポンスタイム（秒） |
| AVG | 平均レスポンスタイム（秒） |
| MAX | 最大レスポンスタイム（秒） |
| SUM | 合計レスポンスタイム（秒） |
| 2xx〜 | 各HTTPステータスコードの件数 |
工夫について解説
Nginxのアクセスログを alp で分析する際、ログをそのまま扱うと細かすぎて分析に不向きなことがあります。
たとえば、ユーザーIDや静的ファイルのファイル名がURIに含まれていると、同じ機能へのアクセスなのに別々のエントリとしてカウントされてしまうからです。
そのため、特定パターンをマスキングしてまとめることで、分析がしやすくなります。
数字IDをマスキングしたいとき
perl -pE 's{/users/[^/]+}{/users/***}'
■これは何をしているのか
- /users/12345 や /users/abcde のようなURLを
→ /users/*** に変換します。
■なぜ必要か
例えば、下記のようなログがあるとします。
/users/123
/users/456
/users/789
これらはすべて「ユーザー詳細ページ」なのに、alpでは 別々のエンドポイントとしてカウントされてしまいます。しかし、マスキングすれば
/users/***
のように、一つのルートとして集約され、アクセス数や処理時間が見やすくなります。
静的ファイルアクセスをまとめたいとき
perl -pE 's{/(assets|images)/.*"}{/$1/***"}'
■これは何をしているのか
- /assets/logo.png や /images/profile/123.jpg のようなURLを
→ /assets/*** や /images/*** に変換します。
■なぜ必要か
静的ファイルは大量にアクセスされますが、分析対象としては「パス単位」ではなく「カテゴリ単位」で見たいケースもあると思います。
元のログが下記のようになっている場合
/assets/style.css
/assets/app.js
/images/user1.png
/images/user2.png
そのままだと1アクセスずつの別カウントされますが、マスキングすれば
/assets/***
/images/***
となるので、カテゴリごとに集約して頻度や負荷を把握するのに役立ちます。
こんな具合で好き勝手分析しやすいようにカスタマイズできるので、正規表現でゴリ押してみてください！
実行ファイルにまとめる
alp.shみたいなファイル作って、実行できるようにしておくと便利かもしれないです！
#!/bin/bash
cat /var/log/nginx/access.log \
| perl -pE 's{/users/[^/]+}{/users/***}' \
| perl -pE 's{/(assets|images)/.*"}{/$1/***"}' \
| alp json -o count,method,uri,min,avg,max,sum,2xx,3xx,4xx,5xx -r
まとめ
割と簡単なセットアップでログの分析ができます。
より定量的にパフォーマンス改善のアプローチを行う手段として、alp を使うのも良いと思います！
特に sum（総レスポンスタイム）や count（リクエスト数）を見て、大きいものから順番に手を付けていくと、より効果的な改善に繋がると思います！
そこから対象のAPIを見に行って、
- アプリケーション側に問題があるのかな？
- DBが重いのかな？
- クエリが最適化されていないのかな？
…といった探検が始まると思います。
「なんとなく遅い」から「ここが遅い」になっていくヒントになれば嬉しいです！
参考リンク