はじめに こんにちは。プラットフォームエンジニアリングチームに所属している徳富( @yannKazu1 )です。 MySQL が遅いとき、まず EXPLAIN で計画を見る。見積もりが怪しければ EXPLAIN ANALYZE で実測と突き合わせる。たいていのケースはこの二つで十分で、実際自分もそれで困ったことはほとんどありませんでした。 ところが先日、この二つをいくら眺めても答えが出ない場面に当たりました。最後に頼ったのが Optimizer Trace でした。普段のチューニングではまず使わないので、すっかり引き出しの奥にしまっていた手札です。そこに至るまでの経緯も含めて書いておきます。 まず、何が起きていたか Aurora MySQL を 3.04.2(8.0.28 互換)から 3.10.3(8.0.42 互換)にアップグレードしたら、通知配信バッチの特定クエリが 4,000〜5,000 秒 滞留するようになりました。アップグレード前は同じクエリが全体コスト 18.27 で、何事もなく一瞬で返ってきていたクエリです(なお、通知配信そのものへの影響は限定的でした)。 クエリは NOT EXISTS の中に IN サブクエリがネストされた構造でした(テーブル名は適当に置き換えています)。 SELECT users.id FROM users INNER JOIN notification_settings ON notification_settings.user_id = users.id WHERE ... AND NOT EXISTS ( SELECT * FROM user_events WHERE event_id IN ( SELECT id FROM events WHERE start_at BETWEEN ? AND ?) AND user_id = users.id) EXPLAIN を見て「?」となる events テーブル(5,000 万行くらい)が type: ALL でフルスキャンされていました。 possible_keys: PRIMARY, idx_events_start_at key: NULL 使えるインデックスが候補に挙がっているのに、使っていない。Datadog DBM の実行計画履歴を見ると、アップグレード前は idx_events_start_at を使った range でした。 試しに SET optimizer_switch='semijoin=off' にしてみると range に戻って見積もり 89,078 行に絞られたので、「semijoin へのフラット化まわりが怪しい」ことはわかりました(後述しますが、犯人はフラット化そのものではありませんでした)。わかったんですが、 なぜこうなるとインデックスが使えなくなるのか はまったくわからない。 EXPLAIN ANALYZE で統計情報の線を消す 次に疑ったのは統計情報です。今回は Blue/Green でアップグレードしてクラスターが丸ごと入れ替わっているので、統計情報がずれている可能性は十分にありそうだと思ったためです。 結果、テーブル行数の見積もりは 5,060 万に対して実測 5,300 万で 1.05 倍。インデックス経由の range も 89,078 に対して 52,129 で 1.7 倍。 どっちも妥当 でした。 一方で、フルスキャン経路だけが明らかにおかしかった。 -> Filter: (events.start_at between ? and ?) (cost=2.64e+9 rows=50.6e+6) (actual rows=52,129) -> Table scan on events (cost=2.64e+9 rows=50.6e+6) (actual rows=53e+6) 同じ BETWEEN 述語なのに、インデックス経由では 89,078 行と正しく見積もるのに、テーブルスキャン経路では選択率がまったく効かず 5,060 万行。実測の約 971 倍です。この誤差が上位ノードでどんどん増幅していました。 ここまでで「統計の問題じゃない、アクセスパス評価のほうがおかしい」とは言えるようになりました。 つまり、 EXPLAIN 系だけだと「変な計画が選ばれている」までしか言えない 。ここで手札が尽きました。 EXPLAIN / EXPLAIN ANALYZE / Optimizer Trace の使い分け Optimizer Trace の話に入る前に、三つの違いを整理しておきます。ここが曖昧だと Trace を出すタイミングが判断できないので。 EXPLAIN でわかるのは決まった計画だけ EXPLAIN SELECT ...; EXPLAIN FORMAT=JSON SELECT ...; -- コスト値も見たいときはこっち 結合順序、各テーブルのアクセス方法、使われたインデックス、推定行数。 FORMAT=JSON にすればコスト値も出ます。基本的にクエリは実行されないので(実体化される派生テーブルなど、一部内部的に実行が走る例外はあります)、重いクエリでも本番で気軽に打てます。日常的なチューニングはこれで十分です。 ただ、EXPLAIN が返してくれるのは、オプティマイザが検討を終えて定めた「こう実行するつもりです」という計画だけです。そこに至るまでに何を検討して、何を却下したのかは出てきません。 だから possible_keys にインデックスが並んでいるのに key: NULL という出力を見ても、「使えるはずのものを使わなかった」という事実がわかるだけで、理由はさっぱりわからない。まさに今回詰まったところです。 EXPLAIN ANALYZE は見積もりと実測を突き合わせる EXPLAIN ANALYZE SELECT ...; MySQL 8.0.18 以降。クエリを実際に走らせて、どう実行したのかと、実行計画の見積もりが実測とどれだけズレていたかを並べてくれます。 -> Filter: (events.start_at between ? and ?) (cost=2.64e+9 rows=50.6e+6) (actual time=22733..27300 rows=52129 loops=1) rows= が見積もり、 actual ... rows= が実測です。これが効くのは「 統計情報がずれているのでは? 」という仮説を切り分けたいとき。推定行数が実測とほぼ一致していれば統計は問題なし、逆に大きくズレていればそこが怪しい、という判断ができます。今回もこれで統計の線を消しました。 ただしこれも、見積もりが合っていたかしかわかりません。なぜその計画を選んだのかは、EXPLAIN と同様に出てきません。また、実行を伴うため、数千秒かかるクエリには気軽に打てません。 Optimizer Trace は「なぜその計画を選んだのか」 MySQL 5.6 から標準で入っている機能で、追加インストールも要りません。オプティマイザが何を検討して何を却下したのかを丸ごと吐き出してくれます。 「なぜその計画になったのか」を知りたいときはこれ一択でした。これも クエリの実行は不要 で、 EXPLAIN に対して取れば中身が出ます(後述)。 三つの違い 雑にまとめると、こうなります。 EXPLAIN … どう実行するつもりか(クエリ実行:不要) EXPLAIN ANALYZE … その見積もりは実測と合っていたか(クエリ実行: 必要 ) Optimizer Trace … なぜその計画を選んだのか(クエリ実行:不要。 EXPLAIN で取れる) 前の二つは「変な計画だ」で止まり、その計画を選んだ理由まで踏み込めるのが Trace です。 今回も、テーブル全体の行数見積もりは妥当なのに、 フルスキャン経路の行数見積もりだけ が実測の約 971 倍に崩れていました。そこまでは EXPLAIN 系で追えたのですが、なぜそうなるのかはどこにも出てきません。そこで Optimizer Trace を開くことにしました。 Optimizer Trace の出し方 拍子抜けするくらい簡単です。セッション変数を on にして、クエリを投げて、 information_schema から読む。それだけ。 SET SESSION optimizer_trace = ' enabled=on ' ; SET SESSION optimizer_trace_max_mem_size = 16777216 ; -- 16MB EXPLAIN SELECT ... ; SELECT * FROM information_schema.OPTIMIZER_TRACE\G SET SESSION optimizer_trace = ' enabled=off ' ; ファイルに落とすなら、後で jq に食わせる前提で JSON として保存します。 TRACE カラムの中身は JSON なので、ヘッダや罫線が入らないよう -N --raw --batch で出します。 mysql --comments -N --raw --batch -u user -p -e " SET SESSION optimizer_trace='enabled=on'; SET SESSION optimizer_trace_max_mem_size=16777216; EXPLAIN SELECT ... ; SELECT TRACE FROM information_schema.OPTIMIZER_TRACE; " | awk '/^\{/{found=1} found' > trace.json EXPLAIN の結果行も同じ標準出力に流れてくるので、 awk で JSON が始まる行以降だけを拾っています。対話シェルで目で見たいだけなら \G でもいいですが、 \G 付きの出力は *** 1. row *** や TRACE: といった装飾が付くので、そのまま jq には渡せません。 本番で打つときに安心できる点を二つ。Trace はオプティマイザの動きの記録なので、 実行を伴わない EXPLAIN でも中身が出ます 。数千秒かかるクエリを本番で流す必要はありません。そして SET SESSION で有効化した Trace は その接続にしか効かない ので、他のセッションを巻き込まず本番でも打てます。 Optimizer Trace を読む 最初に Trace を開いたときの感想は「うわ」でした。数 MB の JSON が出てきて、どこから見ればいいのか見当もつかない。 先に言っておくと、 全部読む必要はありません。 見るべき場所は数箇所です。以下、それぞれのステップが何を記録しているのかと、今回のTraceで何が見えたのかを並べて見ていきます。 全体の構造 トップレベルは三つに分かれています。 { " steps ": [ { " join_preparation ": { ... } } , { " join_optimization ": { ... } } , // 9割ここ { " join_explain ": { ... } } // 実行した場合は join_execution ] } 三つ目は、 EXPLAIN で取ると join_explain 、実行を伴うと join_execution になります。どちらにしても、読むのはほぼ join_optimization です。まずはどんなステップがあるかを一覧します。 # 最適化フェーズのステップ一覧 jq '.steps[] | select(.join_optimization) | .join_optimization.steps[] | keys' trace.json # 前処理(サブクエリ変換など)はこちら jq '.steps[] | select(.join_preparation) | .join_preparation.steps[] | keys' trace.json select() を挟んでいるのは、 .steps[] が上記三つの要素を全部回すためです。そのまま .join_optimization.steps[] と書くと、 join_preparation の要素で null に当たって Cannot iterate over null で止まります。 jq '.steps[].join_optimization?.steps[]? | keys' と ? を付ける書き方でも同じです。 これでどんなステップが並んでいるかがわかります。その中で見るのは、実質この四つでした。 transformations_to_nested_joins … サブクエリがどう変換されたか(これだけ join_preparation 配下) rows_estimation … 各テーブルで range が使えるかの判定 considered_execution_plans … 候補とそのコスト。一番ボリュームがある attaching_conditions_to_tables … 条件の割り当て。ここで計画が書き換わることがある transformations_to_nested_joins :サブクエリがどう変換されたか join_preparation 配下にあり、 IN や EXISTS のサブクエリが semijoin / antijoin にフラット化されたかどうかが記録されています。フラット化されるとサブクエリという単位は消え、通常の結合として最適化されるので、計画が大きく変わる出発点になります。 今回の Trace はこうなっていました。 { " select# ": 5 ," from ":" IN (SELECT) "," to ":" semijoin "," chosen ": true } { " select# ": 4 ," from ":" IN (SELECT) "," to ":" antijoin "," chosen ": true } 変換自体は起きていました。ただ、旧バージョンの EXPLAIN JSON にも is_not_null_compl が出ていたので、旧版でも同じように変換されていたと見てよさそうです(後に AWS サポートも両バージョンで同一と確認)。 semijoin=off で直ったので真っ先に疑っていた「フラット化そのものが犯人」という仮説は、ここで消えました。 rows_estimation :range が使えるかどうか テーブルごとに、range スキャンが使えるかを評価した結果が入っています。 " range_analysis ": { " table_scan ": { " rows ": 50628522 , " cost ": 5887250 } , " potential_range_indexes ": [ { " index ": " PRIMARY ", " usable ": false , " cause ": " not_applicable " } , { " index ": " idx_events_start_at ", " usable ": true , " key_parts ": [ " start_at ", " id " ] } ] , " analyzing_range_alternatives ": { " range_scan_alternatives ": [ { " index ": " idx_events_start_at ", " rows ": 89078 , " cost ": 10450 , " chosen ": true } ] } } ありがたいのは、 usable: false に多くの場合 cause が付いてくるところです。「なぜ候補から外れたか」がここで一段階わかります。 今回の events を見ると、 idx_events_start_at は usable: true 。range の見積もりも 89,078 行・cost 10,450 と妙なところはなく、この時点ではインデックスがちゃんと候補に挙がっていました。 もう一つ大事なのは、ここで chosen: true (そのステップの比較でベストだと判断された、という印)になっていても最終的に使われないケースがあることです。今回はまさにそれでした。 considered_execution_plans :候補の比較 一番量が多いところです。結合順序の組み合わせごとに、各テーブルの best_access_path が延々と記録されています。 { " plan_prefix ": [ " users ", " user_events " ] , " table ": " events ", " best_access_path ": { " considered_access_paths ": [ { " access_type ": " ref ", " index ": " PRIMARY ", " usable ": false , " chosen ": false } , { " access_type ": " range ", " range_details ": { " used_index ": " idx_events_start_at " } , " rows_to_scan ": 89078 , " resulting_rows ": 89078 , " cost ": 308026000 , " chosen ": true } ] } } 候補とコストが横に並ぶので、「どれがいくらで、なぜ選ばれたのか」が数字で見えます。今回の Trace では、この段階では range が chosen: true でした。つまりコスト計算の上ではインデックスを使うつもりだった、ということになります。 よく使う jq: # 特定テーブルのアクセスパス候補だけ jq '.. | objects | select(.table? == "events") | .best_access_path' trace.json # chosen になったものだけ拾う jq '.. | objects | select(.chosen? == true)' trace.json attaching_conditions_to_tables :ここで計画が書き換わる 名前からすると地味な後処理に見えるし、自分も最初は読み飛ばしていました。ところが今回の原因はここでした。 見るべきは rechecking_index_usage です。「条件を割り当て直したので、インデックスの使い方をもう一度検討する」という処理で、結合の内側に回ったテーブルについてはここで range を組み直します。今回の Trace はこうでした。 " rechecking_index_usage ": { " recheck_reason ": " not_first_table ", " range_analysis ": { " table_scan ": { " rows ": 50628522 , " cost ": 5887250 } , " best_covering_index_scan ": { " index ": " idx_events_start_at ", " cost ": 5143080 , " chosen ": true } , " setup_range_conditions ": [] } } setup_range_conditions が空になっています。組み直すための BETWEEN が渡ってきていません。range アクセスは「どこからどこまで読むか」という範囲条件とセットでしか成立しないので、条件がなければ range は候補として再構成されません。残るのは table_scan とカバリングインデックスの全スキャンだけで、安いほう(cost 5,143,080)が選ばれる。つまり、 range が負けたのではなく、range が候補として作られなかった わけです。 これで、 possible_keys にインデックスがあるのに key: NULL になる現象も、EXPLAIN ANALYZE で見えていた「テーブルスキャン経路だけ選択率が効かず約 971 倍ズレる」現象も説明がつきました。オプティマイザはインデックスを使うつもりでコストを計算していて、最後の工程でその手段を失っていただけでした。 AWS サポートに投げたら、バグだった 「コスト計算で選ばれた range が確定処理で消えている」というのは、どう考えても正常な最適化には見えません。Trace の該当箇所を添えて AWS サポートに問い合わせたところ、実体化経路については MySQL の既知バグに該当することが確認できました。 Bug #117770 : rechecking_index_usage causes the materialized table to be generated using table scan in Materialize semijoin strategy(問い合わせ時点で Status: Verified、修正バージョンなし) フラット化(FirstMatch)経路のほうは該当する公開バグ報告が見つかっていないものの、同じ機構で range が失われることを再現確認した、とのことでした。 回避策としては、対象クエリ 1 文に限定して、オプティマイザヒントで events に使うインデックスを明示する方針にしました。ステージングで EXPLAIN を取り、 events が idx_events_start_at の range に戻ることを確認してから入れています。 SELECT /*+ INDEX(events idx_events_start_at) */ users.id FROM users ... 振り返って この件で Trace が役に立ったのは、原因を具体的に書けるようになったからだと思っています。 EXPLAIN 系だけだと「変な計画が選ばれる」までしか言えませんが、Trace を読んだことで「確定処理の再チェックで range が捨てられている」と書けるようになりました。おかげで、最適化の結果ではなくバグではないかと疑えたし、問い合わせるときも該当箇所を貼るだけで話が通じました。 ここで Trace を思い出せなかったら、「アップグレードしたら遅くなったので戻します」で終わっていたと思います。 まとめ Optimizer Trace は毎回出すものではないです。順番としては、 EXPLAIN で変な計画を見つける EXPLAIN ANALYZE で見積もりのズレ方を見て、統計情報が原因かを見極める それでも「なぜこの計画なんだ」が説明できないとき、 Trace を開く EXPLAIN でわかるのは何が起きたかで、Trace でわかるのはなぜ起きたかです。 Trace を取るのに必要なのは SET SESSION optimizer_trace='enabled=on' の一行だけです。使う頻度は低いですが、詰まったときの選択肢として覚えておくと便利だと思います。