推測するな、計測せよ

読了目安約3分

alp とスロークエリログの集計を読み、どこを直すかを決める練習をします。

この章の目次

「遅い気がする場所」と「実際に遅い場所」は、ほぼ一致しません。遅さを決めるのは「1 回あたりの時間 × 実行回数」で、実行回数はコードには書かれていないからです。

直す場所は計測で決めます。見るべき計測は 2 つです。

リクエスト単位の計測（アクセスログ）
クエリ単位の計測（スロークエリログ）

アクセスログを集計する（alp）

アクセスログは、Web サーバーが受けたリクエストを 1 行ずつ記録したログで、どの URL に何秒かかったかが残ります。集計の定番ツールが alp で、エンドポイントごとに回数と処理時間の統計を出します。出力はこんな形です（列は一部、数値は例）。

テキスト

+-------+--------+----------------+-------+-------+---------+
| COUNT | METHOD | URI            |  AVG  |  MAX  |   SUM   |
+-------+--------+----------------+-------+-------+---------+
|  1200 | GET    | /posts         | 0.180 | 0.520 | 216.000 |
|  3500 | GET    | /image/[0-9]+  | 0.040 | 0.110 | 140.000 |
|   900 | GET    | /posts/[0-9]+  | 0.090 | 0.300 |  81.000 |
|    40 | POST   | /login         | 0.900 | 2.100 |  36.000 |
|  2000 | GET    | /css/style.css | 0.002 | 0.010 |   4.000 |
+-------+--------+----------------+-------+-------+---------+

COUNT は回数、AVG は平均秒数、SUM は合計秒数です。 URI の [0-9]+ は、/image/123 などを 1 つのエンドポイントにまとめた印です。

合計時間で並べるのが読み方の基本です。 SUM = COUNT × AVG なので、合計が大きい理由は 2 通りに分かれます。

1 行目 /posts：平均 0.18 秒と 1 回が重い。エンドポイントの中身（クエリやコード）を軽くする
2 行目 /image/[0-9]+：1 回 0.04 秒と軽いのに 3500 回で積み上げている。同じ結果を毎回作らずに済ませる（後の章で扱うキャッシュ）

いちばん「遅い」のは平均 0.9 秒の /login ですが、合計では 4 位です。スコアへの寄与で見れば、/posts を直すほうが先です。

スロークエリログを集計する（pt-query-digest）

どの SQL が遅いのかは、2 つ目の計測、スロークエリログで見ます。実行に時間がかかったクエリを記録する MySQL の機能で、ISUCON では閾値を 0 秒にして全クエリを記録するのが定番です。

定番ツールは pt-query-digest です。値だけが違う同じ形のクエリを 1 つにまとめ、合計時間の順位表（先頭の Profile）を出します（数値は例です）。

テキスト

# Profile
# Rank Query ID           Response time  Calls R/Call V/M
# ==== ================== ============== ===== ====== =====
#    1 0x4E61B1...         120.4s 54.7%  48200 0.0025  0.00 SELECT comments
#    2 0x8FA23C...          61.3s 27.8%    600 0.1022  0.01 SELECT posts
#    3 0xC01377...          21.5s  9.8%   9400 0.0023  0.00 SELECT users
# MISC 0xMISC               16.9s  7.7%  12000 0.0014   0.0 <12 ITEMS>

Response time は合計時間と割合、Calls は回数、R/Call は 1 回あたりの秒数です。読み方は alp と同じで、まず合計時間、次に「回数と 1 回あたりのどちらが効いているか」です。

Rank 1：1 回 2.5 ミリ秒と軽いのに 4 万 8 千回。次章で扱う N+1 問題の典型的な見え方
Rank 2：600 回しか呼ばれていないのに 1 回 0.1 秒。インデックス不足の匂いで、第 4 章で扱う

合計時間が最大のものだけを直す

直すのは順位表の 1 位だけです。全体の 55% を占めるクエリを半分の速さにすれば全体は 27% ほど速くなりますが、1% のクエリはゼロにしても 1% です。「気づいた悪い箇所」ではなく「合計時間が最大の箇所」を直すのが、この Part 全体を貫く規律です。

改善のループ

中盤の 6 時間は、このループを回し続けます。

テキスト

ログをリセットしてベンチを回す
        ↓
alp とスロークエリログの集計を読む
        ↓
合計時間が最大のものを 1 つ選んで直す
        ↓
ベンチを回してスコアと計測を確かめる
        ↓
      先頭に戻る

1 つ直すと順位表は入れ替わるので、毎回ログをリセットして計り直します。

次章から、順位表の上位に来る典型パターンを潰します。最初は、ISUCON 最頻出の N+1 問題です。