案件の概要
SQL ServerプロセスのCPU使用率が高いので、何か負荷の高いクエリが実行されているのだろうと思いました。お客様は本番を数か月後に控えていましたが、自由にサーバーを触ることが出来る期間だったので、その場でクエリを書いてCPU使用率の高いクエリを特定することにしました。
怪しいクエリを特定する
select top 10 * from sys.dm_exec_query_stats qs cross apply sys.dm_exec_sql_text(qs.sql_handle) cross apply sys.dm_exec_query_plan(qs.plan_handle) order by last_worker_time desc
問題のクエリはすぐに特定できました。以下のようなクエリです。これは、ワーカーの状態を監視するクエリです。定期的にスパイクすることから、お客様も私も何か監視系のクエリが悪さをしているのだろうというのは予測していました。
select top 50 getdate() as snap_time , start_quantum - wait_resumed_ms_ticks as signal_wait_ms , start_quantum, wait_resumed_ms_ticks , t.session_id , t.task_address , t.scheduler_id , wk.worker_address , wk.state , wk.status , wk.is_sick , wk.is_in_cc_exception , wk.is_fatal_exception , wk.is_inside_catch , wk.is_in_polling_io_completion_routine , wk.exception_num from sys.dm_os_workers wk left join sys.dm_os_waiting_tasks wt on wk.task_address = wt.waiting_task_address left join sys.dm_os_tasks t on wk.task_address = t.task_address where wk.is_preemptive <> 1 and wk.task_address is not null and wt.waiting_task_address is null and t.session_id is not null and start_quantum - wait_resumed_ms_ticks > @signal_wait_limit order by signal_wait_ms desc
このクエリは、定常的に採取してほしい情報のひとつとして私が提供したクエリだったのですが、これまでCPU時間を消費するようなことはなかったのです。なんだか、最近になってCPU使用率が高くなってきているようなのです。
「どうやって調査しようかな。」と問題のクエリを眺めていた時にピンときました。とあるKBのことを思い出したのです。TOP句を使用している時に、オプティマイザがうまく最適化できない場合があるというものです。詳細は割愛しますが、かなりこのKBに合致している可能性が高いなと思いました。
KBの内容を詳しく確認したくなったので、現場での作業を終了しました。会社に戻ってから、KBの内容とソースコード確認して、「今回の問題はやっぱりこれだなぁ、なんでクエリを書いている時に気が付かなかったんだろう。」と思っていたのですが、ふと肝心なことを確認し忘れていたことに気が付きました。
CPU使用率が高いのは、Nested Loops結合プランが選択されていたからです。これは現場で確認しました。Nested Loops結合は、その名の通りネストしたループ処理で行を見つける処理ですから、大量のデータがあるとクルクルとループしてCPU時間を消費します。つまり、本来は少ないデータを処理する場合に向いている処理なのです。
現場でクエリを見ていた時、私はなんでオプティマイザが正しい結合操作を選択しないんだろうとばかり考えていました。Nested Loops結合は最適な選択ではなかったからです。その結果、先のKBを思い出したのですが、重要なことを見過ごしていました。
よくよく考えてみると、問題のクエリが参照しているDMVが返すデータ件数というのはたかが知れているはずです。Table ScanしようがNested Loops結合だろうが、そもそもサーバーに対してそんなに負荷を与えることはないはずです。
つまり、オプティマイザの問題はあるにせよ、根本的な問題として考えられるのは、先のクエリが結合しているDMV、sys.dm_os_workersとsys.dm_os_tasksのどちらかの件数が、異常に増加しているということだったのです。私はこれを確認し忘れていました。
Sys.dm_os_workersやsys.dm_os_tasksは、SQL Serverの内部オブジェクトのインスタンスをほぼそのまま返しているだけです。つまり、ワーカーかタスクのインスタンスが大量に生成されて解放されない状態だと考えられるのです。また、「最近になって発生しだした。」という事象からも、起きている現象は一つしかないと思いました。これはオブジェクトの解放漏れ・メモリリークです。
