CPU 0% で固まったプロセスの原因を cdb と handle64 で追ってみた
はじめに
長時間の処理があるところでぴたりと止まる。ログにエラーは出ていない。タスクマネージャーを見ると CPU 使用率は 0% で、プロセスは生きているのに何もしていない……こうした静かな固着は、例外もスタックトレースも残らないぶん原因がつかみにくく、調査が長引きがちです。
本記事では、実際にこの固着を追ってみた体験を紹介します。先に結論を書いておくと、原因は「読み手がいない名前付きパイプへの書き込みが返ってこない」ことでした。Process Monitor での空振りから、cdb と handle64 でこの正体にたどり着くまでを順に追っていきます。
Process Monitor とは
Process Monitor (以下、procmon) とは、プロセスが発行するファイル・レジストリ・ネットワークの操作をリアルタイムに記録する Sysinternals のツールです。固着の直前に何を触っていたかを時系列で追えるため、まず当たりを付ける道具として使えます。
cdb とは
cdb とは、Windows SDK の Debugging Tools に含まれるコマンドラインデバッガです。固着中のプロセスへ noninvasive attach すれば、対象を止めずにその瞬間のスタックとレジスタを読み取れます。
対象読者
- プロセスがエラーなく固まる事象の調査で手が止まっている方
- Windows のネイティブプロセスの固着を、ユーザーモードの範囲で切り分けたい方
- Process Monitor は使うが、cdb はまだ触っていないという方
参考
- Debugging Tools for Windows (cdb) の入手
- FlushFileBuffers (Win32 API)
- Sysinternals: Process Monitor
- Sysinternals: Handle (handle64)
- 名前付きパイプ (Named Pipes)
課題: procmon には固着中の操作が写らない
CPU 0% での固着は、プロセスが何かを待っている状態です。ビジーループなら CPU を消費するので、0% はカーネルの中で入出力や同期オブジェクトの完了を待って眠っている、と考えられます。
つまり調べるべきは「どのスレッドが」「どのシステムコールで」「何を待っているか」の 3 点です。これを外から確かめる道具として、まず procmon を試しました。
ところが、procmon の限界にぶつかりました。procmon が記録するのは完了した操作です。固着中のプロセスは、多くの場合すでに発行済みの入出力の完了を待っている状態なので、その待っている操作そのものは記録に現れません。固着してからキャプチャを始めても、肝心の操作は捕まえられないということです。
実際に固着区間を含むはずの 200 万行を超えるキャプチャを精査しても、原因であるはずのフラッシュ操作は 1 件も記録されていませんでした。待ちっぱなしの操作は完了イベントを生まないので、原理的に写らないのです。
なお、固着より前からキャプチャを回しておく手もあります。procmon の常駐起動で、処理の開始前から記録を仕込めます。
Procmon64.exe /AcceptEula /Quiet /Minimized /BackingFile C:\temp\capture.pml
ただ、それでも待っている操作自体は残りません。procmon は原因を絞る道具と割り切り、待っている相手の確定は cdb に任せることにしました。
調査: cdb と handle64 でハンドルの正体を突き止める
ここからは cdb でプロセスの中を直接のぞき、待っている相手を名前まで突き止めていきます。
cdb でスタックを確認する
実際に固着中のプロセスへ noninvasive attach し、スタックを kb (cdb でコールスタックと各フレームの先頭 3 引数を表示するコマンド) で表示すると、固着していたスレッドは次のような並びになっていました。
ntdll!NtFlushBuffersFile
KERNELBASE!FlushFileBuffers
...
FlushFileBuffers は、あるハンドルに対して書き込み内容をディスクなどへ確実に送り出す関数です。その下に NtFlushBuffersFile があるので「このスレッドはあるハンドルへのフラッシュ完了をカーネルの中で待っている」と読み取れます。そこで、このハンドルの値を確定しにいきました。
ハンドルの値を確定する
FlushFileBuffers の第 1 引数はハンドルです。ところが、その引数がどのレジスタに乗っているかは、呼び出し規約とコンパイル結果次第です。x64 では第 1 引数は通常 rcx に乗りますが、関数の中でレジスタが上書きされていないとは限りません。そこで、FlushFileBuffers を逆アセンブルして、引数のレジスタがシステムコールに渡るまで書き換えられずに保たれることを目で確認してから、その値を読むのが確実です。
handle64 でハンドルを名前に変える
ハンドルの値そのものは数字にすぎないので、名前に変換します。ここで使ったのが Sysinternals の handle64 です。プロセスが握っているハンドルの一覧と、それぞれが指すオブジェクトの名前 (ファイルパスや名前付きパイプ名) を得られます。
ハンドルのアクセスマスクも手がかりになります。対象のハンドルは書き込み専用 (読み取りなし、マスク 0x120196) で開かれていました。これはローカルのログファイルというより、一方向の名前付きパイプの書き込み端に合う特徴です。名前を確認すると、実際に \Device\NamedPipe\<pipe-name> の形をしており、相手が名前付きパイプの書き込み端だと確定しました。
ローカルファイルへのフラッシュが無限に返らないのは、本来不自然です。一方で名前付きパイプは、読み手がドレインしない限り書き込み側のフラッシュが永久にブロックするという性質があります。今回の症状はこちらと整合します。
つまり、プロセス A のフラッシュが返らないのは、パイプの向こう側にいる本来の読み手 (プロセス B) が中身を読み出していないからでした。なぜローカルファイルのフラッシュが返らないのかと悩む前に、まずハンドルの正体を名前まで割り出すのが近道だったわけです。
調査の結果と対応
cdb と handle64 で、固着していたスレッドが待っていた相手が、読み手のドレインしない名前付きパイプだと名前まで分かりました。原因はプロセス A ではなく、プロセス B の側にありました。
調査の場をプロセス B へ移すと、パイプを読むはずのスレッドが 1 つ静かに終了していて、これが読み手がいない状態を作っていました。このスレッドの終了問題を解消したところ、CPU 0% の固着は再現しなくなりました。
まとめ
cdb と handle64 を重ねることで、CPU 0% で固まったプロセスが待っていた相手を、読み手のいない名前付きパイプだと名前まで突き止められました。procmon は原因を絞るのに役立ちますが、固着中の未完了 I/O は記録されないため、確定には対象を止めない cdb の attach と、推測に頼らない逆アセンブル、そして handle64 でのハンドル名前解決が必要でした。固着調査で手が止まったとき、本記事が参考になれば幸いです。
