発端
とある毎日1回実行するCronの処理時間が、ある日を境に倍以上に跳ね上がってしまいました。
表にすると以下のような感じです。
| 実行時間(min) | |
|---|---|
| 2/28 | 21 |
| 3/1 | 21 |
| 3/2 | 22 |
| 3/3 | 22 |
| 3/4 | 55 |
| 3/5 | 55 |
| 3/6 | 55 |
| ※ いずれも午前9時ちょうどに実行 |
このシステムは個人的に動かしてるデータ最適化用のもので、特に3月3日または3月4日に大量のデータを流したりはしていません（ALTER TABLEで後述のContentsテーブルにカラムを1個追加したくらいです）。
また、他にも10個ほどの前後するCronが動いていましたが、こちらについてはこのような実行時間の変動は見られませんでした。
このCronがたまたま直列実行するCron群の最後のものであり他のCronに影響を及ぼすことはありませんでしたが、非常に不安なため、すぐさま原因の調査に取り掛かりました。
原因
当該Cronでは、以下のようなクエリを約1万5千回に渡って実行していました。
SELECT count(DISTINCT ac.id) as count FROM Contents as ct
INNER JOIN Actions AS ac ON ac.id = ct.Action_id
INNER JOIN Places AS p ON p.id = ac.Place_id AND p.valid = 1
INNER JOIN Cities AS c ON c.id = p.City_id
LEFT JOIN Actions_Categories AS ac_c ON ac.id = ac_c.Action_id
WHERE c.Prefecture_id = {PREFECTURE_ID}
AND CAST(p.openedAt as DATE) <= {TODAY}
AND ac.valid = 1
AND c.valid = 1
AND (ac.Category_id = {CATEGORY_ID} OR ac_c.Category_id = {CATEGORY_ID});
このクエリ自体についてまずこんな面倒くさい結合付きSELECTを1万5千回もやること自体がナンセンスという問題はさておきます。
おそらくクエリ最適化の結果が何か変わっていないかと思い実行計画をみると、フルテーブルスキャンをかける先のテーブルは Contents となっていました。
MySQLがクエリ最適化をするにあたり、フルテーブルスキャン先を決める要素になるのはテーブルのインデックスカーディナリティの数であると以前公式ドキュメントで読んだため、結合する各テーブルのカラム数とインデックスカーディナリティ値を調べたところ、以下の通りとなっていました。
| 行数 | インデックスカーディナリティ | |
|---|---|---|
| Contents | 51984 | 50438 |
| Actions | 49842 | 51901 |
| Places | 6313 | 6313 |
| Cities | 1375 | 1375 |
| Actions_Categories | 66555 | 65022 |
なんということでしょう。今回フルテーブルスキャンをかけうる対象となるContentsとActionsの各テーブルの行数とインデックスカーディナリティがそれぞれ異なっているばかりか、大小まで逆転しているのです。
なんじゃこりゃと思って公式ドキュメントを読んでみたところ、これまで見落としていた以下の文章を発見しました。
各インデックスツリーにランダムダイブを行い、それに従ってインデックスカーディナリティーの見積もりを更新すると、(SHOW INDEX 出力の「Cardinality」カラムに表示されるように) ANALYZE TABLE でインデックスカーディナリティーが決定されます。これらは単なる見積もりであるため、ANALYZE TABLE を繰り返し実行すると、別の数値が生成される可能性があります。これによって ANALYZE TABLE の InnoDB テーブル上での速度は速くなりますが、すべての行が考慮されているわけではないため、100% 正確とは言えません。
えっ
単なる見積もりである
単なる見積もりである
単なる見積もりである
おま
ANALYZE TABLE を繰り返し実行すると、別の数値が生成される可能性があります
ANALYZE TABLE を繰り返し実行すると、別の数値が生成される可能性があります
ANALYZE TABLE を繰り返し実行すると、別の数値が生成される可能性があります
ちょっと・・・なんかとんでもないことをさらっと言っていました。
要約すると、『インデックスカーディナリティはすぐ変わるからな。しかも別に正確じゃねえから。高速化するには仕方なかったんだぜ』なんて感じです。
しかしこれ、イラッとする以上にスッキリしました。完全に辻褄が合ったからです。
公式ドキュメントを追ってみると、インデックスカーディナリティの再集計のトリガーにはざっと以下のものがありました。
- ANALYZE TABLE （完全再集計=実質ランダムで変わる）
- ALTER TABLE（完全再集計=実質ランダムで変わる）
- INSERT（加算）
- DELETE（減算）
そして僕が冒頭にさらっと記述したこの部分に注目です。
（ALTER TABLEで後述のContentsテーブルにカラムを1個追加したくらいです）
そう、3月3日の午後に1個ALTER TABLEでカラムを追加したせいでContentsテーブルのインデックスカーディナリティの統計情報が変更され、フルテーブルスキャン先がActionsからContentsに切り替わってしまい、実行計画が入れ替わってしまったために実行時間が跳ね上がってしまったのではないか、という仮説が完成しました。
そして仮説の検証は簡単でした。ANALYZE TABLEを双方に数回かけてActionsにフルテーブルスキャンがかかるようになった時点でクエリの実行時間を計測したところ、フルテーブルスキャン先がActionsに変わると1件あたりの実行時間がほぼ半減し、Cron全体の実行時間も平均55分から22分へと半減しました。
ちなみに行数もインデックスカーディナリティも近いActionsとContentsの両テーブルですが、後者はテキストフィールドが2箇所あり、テーブル実体の大きさもそれぞれ17MB及び39MBとちょうど2倍の差が開いていました。このこともまた仮説を裏付けていました。
なお、ActionsとContentsの両テーブルの関係ですが、システムの構造上では必ず『1対多』となるため、行数が近接することは想定していても逆転することは絶対に有り得ない構造となっていました。しかし行数は逆転せずともインデックスカーディナリティはかなりばらつくため逆転の恐れがあったという事実を知ったのは、作ってから3年目にした今回の事件を調査してのこととなってしまいました・・・。
まとめというか反省点
今後多重結合をする場合は、インデックスカーディナリティの入れ替わりに注意します。
特に、設計上行数が入れ替わらないからと言って必ずしも想定通りの実行計画が保証されているというわけではないということを、再度強く認識しておきたいと思います。
というか、そもそも数万行レベルのテーブルを安易に多重結合すんなって話ですけどね・・・。今回のCronも、上記の問題クエリの多重結合をアプリケーションのループの最適化で解消した結果、20分かかっていたものを数秒で終わらせるようにもできました。
つくづく事前設計というのは重要だと考えさせられた事件でした。