「なんとなく遅い」から「ここが遅い」へ。alpでログ分析

# はじめに

APIのパフォーマンスを改善するうえで、「どのエンドポイントがボトルネックになっているか」「アクセスが集中しているURIはどれか」「ステータスコードの分布はどうか」といった情報の把握は欠かせません。とは言え、パパっとボトルネックを見つけるのは（きっと）大変だったりします。

alp（Access Log Profiler）は、こうしたアクセスログの分析を簡単に行えるツールです。NginxなどのWebサーバが出力するログを集計・可視化することで、パフォーマンス課題の解決を助けてくれます！

本記事では alp の導入から使い方や活用例までを紹介します。特に開発中のプロジェクトで「なんとなくAPIが重そう」と感じたときや、ボトルネック調査のきっかけが欲しいときに役立つと信じています。

# alpとは

`alp` は Nginx や Apache のアクセスログを集計・可視化するツールです。  
JSON形式にも対応しており、カスタマイズしたログでも扱えます。

**主な特徴**

- パス単位でリクエストを集計（パラメータはマスキング）
- ステータスコード別の集計
- レスポンスタイムの min / avg / max / sum を出せる
- jsonログにも対応（←重要！）

## インストール方法

### Macの場合

```bash
brew install alp
```

### Linuxの場合

```bash
$ 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` の例

```nginx
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;
```

※カスタマイズは良い感じに出来るので、お好みで調整してください

https://isucon-workshop.trap.show/text/chapter-3/2-AccessLog.html

Nginxを再起動して反映

```bash
nginx -t && systemctl reload nginx
```

---

# 使い方

READMEを読むのが良いとは思います。分かりやすく丁寧に書かれています！

https://github.com/tkuchiki/alp

sampleはこっち

https://github.com/tkuchiki/alp/blob/main/docs/usage_samples.ja.md

とは言え少しだけ。
下記を実行すればそれっぽいのが出てきます。
```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
```

###  出力例

```
+-------+--------+---------------------------------------------------+-------+-------+-------+-------+-----+-----+-----+-----+
| 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をマスキングしたいとき

```bash
perl -pE 's{/users/[^/]+}{/users/***}'
```

■これは何をしているのか
- /users/12345 や /users/abcde のようなURLを
→ /users/*** に変換します。

■なぜ必要か
例えば、下記のようなログがあるとします。

```bash
/users/123
/users/456
/users/789
```

これらはすべて「ユーザー詳細ページ」なのに、alpでは 別々のエンドポイントとしてカウントされてしまいます。しかし、マスキングすれば

```bash
/users/***
```
のように、一つのルートとして集約され、アクセス数や処理時間が見やすくなります。

### 静的ファイルアクセスをまとめたいとき

```bash
perl -pE 's{/(assets|images)/.*"}{/$1/***"}'
```

■これは何をしているのか
- /assets/logo.png や /images/profile/123.jpg のようなURLを
→ /assets/*** や /images/*** に変換します。

■なぜ必要か
静的ファイルは大量にアクセスされますが、分析対象としては「パス単位」ではなく「カテゴリ単位」で見たいケースもあると思います。

元のログが下記のようになっている場合
```bash
/assets/style.css
/assets/app.js
/images/user1.png
/images/user2.png
```

そのままだと1アクセスずつの別カウントされますが、マスキングすれば

```bash
/assets/***
/images/***
```

となるので、カテゴリごとに集約して頻度や負荷を把握するのに役立ちます。

こんな具合で好き勝手分析しやすいようにカスタマイズできるので、正規表現でゴリ押してみてください！

### 実行ファイルにまとめる
`alp.sh`みたいなファイル作って、実行できるようにしておくと便利かもしれないです！

```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が重いのかな？
- クエリが最適化されていないのかな？

…といった探検が始まると思います。

「なんとなく遅い」から「ここが遅い」になっていくヒントになれば嬉しいです！


### 参考リンク

https://github.com/tkuchiki/alp