OSS紹介 Advent Calendar 2017 - Qiita 4日目の記事です。
@tkuchiki 氏が作っている alp (Access Log Profiler) は、もはや ISUCON 競技者必須ツールとなった、LTSV 形式のアクセスログをいい感じに集計してくれるツールです。 github.com
通常は alp では reqtime, apptime など、リクエストの処理に要した時間を集計するこのでパフォーマンスチューニングするのですが、実は集計対象は引数 --apptime-label を指定することで、集計時に自由に決めることができます。パフォーマンスに影響するなんらかの数値をログに出力しておけば、それを key にして集計できるということですね。
そこでもうひとつ、@acidlemon 氏作の便利 Plack::Middleware を組み合わせてみました。
Plack::Middleware::QueryCounter::DBI は enable するだけで、DBIx::Tracer を使ってそのリクエスト中の DBI でのクエリ発行数を計測し、レスポンスヘッダに出力してくれます。
log_format ltsv 'host:$remote_addr\t'
# (snip)
'query_total:$upstream_http_x_querylog_total\t'
'query_read:$upstream_http_x_querylog_read\t'
'query_write:$upstream_http_x_querylog_write\t'
'query_other:$upstream_http_x_querylog_other\t'
ということで、nginx ではそのヘッダを LTSV 形式でログに残すようにすれば…
$ alp -r --avg --apptime-label="query_total" < access.log +-------+--------+---------+----------+--------+-----------+-----------+------------+-----------+--------+-------------------------------------------------------+ | COUNT | MIN | MAX | SUM | AVG | MAX(BODY) | MIN(BODY) | SUM(BODY) | AVG(BODY) | METHOD | URI | +-------+--------+---------+----------+--------+-----------+-----------+------------+-----------+--------+-------------------------------------------------------+ | 5 | 35.000 | 35.000 | 175.000 | 35.000 | 2119.000 | 2430.000 | 11479.000 | 2295.800 | POST | /api/xxxxxxx/top | | 51 | 6.000 | 474.000 | 1765.000 | 34.608 | 38.000 | 656.000 | 3741.000 | 73.353 | POST | /api/yyyyyy/action | | 1 | 19.000 | 19.000 | 19.000 | 19.000 | 2825.000 | 2825.000 | 2825.000 | 2825.000 | GET | /api/user | | 5 | 17.000 | 18.000 | 87.000 | 17.400 | 1527.000 | 1588.000 | 7807.000 | 1561.400 | POST | /api/zzzzzz/info | ....
どこの path の処理中にクエリを大量に発行しているのかが一目瞭然ですね。
ベンチマーク中に大変便利だったのでご紹介でした。
