【課題 1】計測結果からどこを直すか決める
読了目安 約2分
初期実装のアクセスログとスロークエリログを読んで、最初に手をつける場所を選びます。
この章の目次
初期実装のまま 60 秒走らせて、アクセスログとスロークエリログを集計しました。
アクセスログ（合計時間順）
alp の出力です。
SUM は、そのエンドポイントに費やした時間の合計です。
+-------+--------+-------------------------------------------+-------+--------+----------+
| COUNT | METHOD | URI | AVG | MAX | SUM |
+-------+--------+-------------------------------------------+-------+--------+----------+
| 1987 | GET | /api/player/player/[^/]+ | 0.594 | 6.300 | 1180.979 |
| 1488 | GET | /api/player/competition/[^/]+/ranking | 0.672 | 6.292 | 999.642 |
| 18 | GET | /api/admin/tenants/billing | 5.882 | 12.269 | 105.882 |
| 87 | POST | /api/organizer/competition/[^/]+/score | 1.001 | 6.032 | 87.106 |
| 12 | POST | /api/organizer/players/add | 1.287 | 2.520 | 15.444 |
| 39 | GET | /api/organizer/billing | 0.126 | 1.288 | 4.932 |
| 215 | GET | /api/player/competitions | 0.010 | 0.040 | 2.052 |
+-------+--------+-------------------------------------------+-------+--------+----------+スロークエリログ（合計時間順）
slp の出力です。
SUM(ROWSEXAMINED) は、そのクエリが読んだ行数の合計です。
+-------+----------------+----------------+-------------------+--------------------------------+
| COUNT | SUM(QUERYTIME) | AVG(QUERYTIME) | SUM(ROWSEXAMINED) | QUERY |
+-------+----------------+----------------+-------------------+--------------------------------+
| 2430 | 107.899189 | 0.044403 | 45459630 | SELECT player_id,MIN(created_a |
| | | | | t) FROM visit_history WHERE te |
| | | | | nant_id = N AND competition_id |
| | | | | = 'S' GROUP BY player_id |
| 17914 | 49.106648 | 0.002741 | 0 | REPLACE INTO id_generator (stu |
| | | | | b) VALUES ('S') |
| 1470 | 4.596556 | 0.003127 | 0 | INSERT INTO visit_history (... |
| 4018 | 1.506151 | 0.000375 | 4017 | SELECT * FROM tenant WHERE nam |
| | | | | e = 'S' |
+-------+----------------+----------------+-------------------+--------------------------------+課題
この 2 つの表から、次の 3 つに答えてください。
- 最初に手をつけるべき場所はどこか。数字を根拠に挙げる
/api/admin/tenants/billingは 18 件しか来ていないのに、なぜ無視できないか- この 2 つの表に出てこない処理は何か
解答例
1. visit_history の集計
スロークエリログの 1 位が、他を引き離しています。 2430 回で 108 秒、1 回あたり 44 ミリ秒です。
決め手は SUM(ROWSEXAMINED) です。
4545 万行を 2430 回で割ると、1 回のクエリが約 1 万 9 千行を読んでいます。
返している行数は参加者の数ぶんしかないので、読みすぎです。
2. 1 件あたりが異常に遅いから
/api/admin/tenants/billing は平均 5.9 秒、最大 12.3 秒です。
合計時間では 3 位でも、1 件あたりでは断トツです。
ベンチマーカーはタイムアウトした リクエストを失敗として扱います。 このまま負荷が上がると、失敗が増えて減点されます。
3. SQLite へのクエリ
スロークエリログは MySQL の機能です。
テナント DB は SQLite なので、player_score を何行読もうが 1 行もログに出ません。
アクセスログの /api/player/player/[^/]+ が平均 0.594 秒かかっている理由は、この 2 つの表からは分かりません。
計測に出ないものがあるという前提で読む必要があります。
ログに出ない処理を測る道具が pprof です。この Part では第 6 章で使います。
次の一手
順番は、根拠の強さと直しやすさで決めます。
visit_historyの読みすぎ（根拠が数字ではっきりしている）REPLACE INTO id_generatorの 17914 回（回数が異常）- SQLite 側（計測が無いので、まずコードを読む）
上から順に片付けます。