alp と Plack::Middleware::QueryCounter を合わせて使うと捗る

OSS紹介 Advent Calendar 2017 - Qiita 4日目の記事です。

@tkuchiki 氏が作っている alp (Access Log Profiler) は、もはや ISUCON 競技者必須ツールとなった、LTSV 形式のアクセスログをいい感じに集計してくれるツールです。 github.com

通常は alp では reqtime, apptime など、リクエストの処理に要した時間を集計するこのでパフォーマンスチューニングするのですが、実は集計対象は引数 --apptime-label を指定することで、集計時に自由に決めることができます。パフォーマンスに影響するなんらかの数値をログに出力しておけば、それを key にして集計できるということですね。

そこでもうひとつ、@acidlemon 氏作の便利 Plack::Middleware を組み合わせてみました。

metacpan.org

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 の処理中にクエリを大量に発行しているのかが一目瞭然ですね。

ベンチマーク中に大変便利だったのでご紹介でした。