!htrace コマンドを利用したハンドルリークのデバッグ方法

このページでは !htrace デバッグコマンドを用いて、ハンドルリークを発生させている箇所を特定する方法をご紹介します。

ハンドルリークの概要はこちらをご覧ください。

準備

リークするプログラムの準備

ここではページレベル HTTP モジュールを利用しハンドルリークを発生させて、調査方法について具体的に解説しています。 テスト用プログラムの作成方法は ハンドルリークテスト用 HTTP モジュールの作成 を見てください。

もちろん、本番環境で調査するときはこんなプログラムを仕掛けちゃダメですよ！

準備 ～ Debugging Windows for Windows のインストールとシンボルパスの設定

マイクロソフトのサイトからダウンロード可能な Debugging Tools for Windows をインストールし、シンボルパスを設定してください。

現象の確認

パフォーマンスモニタで、w3wp.exe プロセスの Handle Count 値をモニターしつつ、HTTP リクエストを送信すると、 下図のように Handle Count 値が上がり続けることが確認できます。(本番環境の場合はもう少し長期で確認すべきですが)


問題のあるプログラムを仕掛けてある場合

上図のハンドル数の遷移は、問題のあるプログラムを仕掛けていない場合と比較して明らかに増加傾向が見られます。


問題のあるプログラムを仕掛けていない場合
～リクエストを送信してもハンドル数に大きな変化は見られない

調査方法

ワーカープロセスのプロセス ID (PID) の特定

IIS のワーカープロセス (w3wp.exe) のプロセス ID (PID) を特定します。IIS 7.0 では appcmd コマンドが利用可能です。 (以前のバージョンでは iisapp.vbs が使えます) 

C:\Windows\System32\inetsrv> appcmd list wp
WP "4140" (applicationPool:DefaultAppPool)

私の例では、上記の出力から DefaultAppPool の PID は 4140 であることがわかりました。

デバッガのアタッチ

W3WP.EXE にデバッガをアタッチします。 

C:\Debuggers> cdb -p 4140

4140 は上で探し出した W3WP.EXE の PID です。これはその都度変ります。 

...
ModLoad: 60060000 60067000   C:\Windows\Microsoft.NET\Framework\v2.0.5072...
ModLoad: 68360000 6836a000   C:\Windows\system32\inetsrv\gzip.dll
(102c.138c): Break instruction exception - code 80000003 (first chance)
eax=7ffda000 ebx=00000000 ecx=00000000 edx=775dd094 esi=00000000 edi=00000000
eip=77597dfe esp=00ebfcd8 ebp=00ebfd04 iopl=0         nv up ei pl zr na pe nc
cs=001b  ss=0023  ds=0023  es=0023  fs=003b  gs=0000             efl=00000246
ntdll!DbgBreakPoint:
77597dfe cc              int     3
0:015>

これで W3WP.EXE にデバッガがアタッチした状態となり、一時停止しています。

ハンドルトレースの有効化

!htrace コマンドでハンドルトレースを有効にします。-enable オプションを指定してください。 

0:015> !htrace -enable
Handle tracing enabled.
Handle tracing information snapshot successfully taken.
0:015>

上記の出力からわかるように、このコマンドはハンドルトレースを有効にすると同時に、 一回目のスナップショットを作成します。この時点のスナップショットと後ほどの状態を比較することにより、問題点を突き止めるのです。

現象を再現させる

g コマンドで、停止させていたプログラムを再開します。

IIS に HTTP リクエストを送信して、ハンドルリークを再現させます。 

0:015> g
MyHttpModuleFactory::GetHttpModuleMyHttpModule::MyHttpModule...
tpModuleFactory::GetHttpModuleMyHttpModule::MyHttpModuleMyHt..
...

ある程度実行したら、Ctrl + C でデバッガをブレークします。 

...
Break instruction exception - code 80000003 (first chance)
eax=7ffa4000 ebx=00000000 ecx=00000000 edx=775dd094 esi=00000000 edi=00000000
eip=77597dfe esp=0212fac4 ebp=0212faf0 iopl=0         nv up ei pl zr na pe nc
cs=001b  ss=0023  ds=0023  es=0023  fs=003b  gs=0000             efl=00000246
ntdll!DbgBreakPoint:
77597dfe cc              int     3
0:016>

ハンドルの状態を比較

!htrace -diff で直前のスナップショットと現在の状態を比較することができます。 

0:016> !htrace -diff
Handle tracing information snapshot successfully taken.
0x106 new stack traces since the previous snapshot.
Ignoring handles that were already closed...
Outstanding handles opened since the previous snapshot:
--------------------------------------
Handle = 0x00000548 - OPEN
Thread ID = 0x0000094c, Process ID = 0x0000102c

0x775a7ff4: ntdll!ZwCreateEvent+0x0000000c
0x766446a1: kernel32!CreateEventExW+0x0000006e
0x7664428a: kernel32!CreateEventW+0x00000027
0x72ee214d: IISUTIL!IPM_MESSAGE_IMP::CreateMessage+0x00000085
0x72ee26f4: IISUTIL!IPM_MESSAGE_PIPE::ReadMessage+0x00000051
0x72ee2275: IISUTIL!IPM_MESSAGE_PIPE::MessagePipeCompletion+0x000003f9
0x7758d7cd: ntdll!RtlpTpWaitCallback+0x0000008f
0x7758c68c: ntdll!TppWaitpExecuteCallback+0x000000fe
0x7758de3f: ntdll!TppWorkerThread+0x00000545
0x76644911: kernel32!BaseThreadInitThunk+0x0000000e
0x7758e4b6: ntdll!__RtlUserThreadStart+0x00000023
0x7758e489: ntdll!_RtlUserThreadStart+0x0000001b
--------------------------------------
Handle = 0x00000540 - OPEN
Thread ID = 0x0000157c, Process ID = 0x0000102c

0x775a8014: ntdll!ZwCreateFile+0x0000000c
0x7664ce0b: kernel32!CreateFileW+0x00000379
0x10001223: rhttpmod!MyHttpModule::OnBeginRequest+0x00000063
0x719637e9: iiscore!NOTIFICATION_CONTEXT::RequestDoWork+0x000000d5
0x71963696: iiscore!NOTIFICATION_CONTEXT::CallModulesInternal+0x000002ec
0x7196aa4c: iiscore!NOTIFICATION_CONTEXT::CallModules+0x00000028
0x71965db5: iiscore!W3_CONTEXT::DoStateRequestStart+0x00000063
0x71962108: iiscore!W3_CONTEXT::DoWork+0x0000008d
0x71964eef: iiscore!W3_MAIN_CONTEXT::StartNotificationLoop+0x00000049
0x7196c6b8: iiscore!W3_MAIN_CONTEXT::OnNewRequest+0x0000004c
0x728513b3: w3dt!UL_NATIVE_REQUEST::DoStateProcess+0x00000026
0x728511da: w3dt!OverlappedCompletionRoutine+0x0000001a
--------------------------------------
Handle = 0x00000538 - OPEN
Thread ID = 0x0000163c, Process ID = 0x0000102c

0x775a8014: ntdll!ZwCreateFile+0x0000000c
0x7664ce0b: kernel32!CreateFileW+0x00000379
0x10001223: rhttpmod!MyHttpModule::OnBeginRequest+0x00000063
0x719637e9: iiscore!NOTIFICATION_CONTEXT::RequestDoWork+0x000000d5
0x71963696: iiscore!NOTIFICATION_CONTEXT::CallModulesInternal+0x000002ec
0x7196aa4c: iiscore!NOTIFICATION_CONTEXT::CallModules+0x00000028
0x71965db5: iiscore!W3_CONTEXT::DoStateRequestStart+0x00000063
0x71962108: iiscore!W3_CONTEXT::DoWork+0x0000008d
0x71964eef: iiscore!W3_MAIN_CONTEXT::StartNotificationLoop+0x00000049
0x7196c6b8: iiscore!W3_MAIN_CONTEXT::OnNewRequest+0x0000004c
0x728513b3: w3dt!UL_NATIVE_REQUEST::DoStateProcess+0x00000026
0x728511da: w3dt!OverlappedCompletionRoutine+0x0000001a
--------------------------------------
Handle = 0x00000530 - OPEN
Thread ID = 0x0000163c, Process ID = 0x0000102c

0x775a8014: ntdll!ZwCreateFile+0x0000000c
0x7664ce0b: kernel32!CreateFileW+0x00000379
0x10001223: rhttpmod!MyHttpModule::OnBeginRequest+0x00000063
0x719637e9: iiscore!NOTIFICATION_CONTEXT::RequestDoWork+0x000000d5
0x71963696: iiscore!NOTIFICATION_CONTEXT::CallModulesInternal+0x000002ec
0x7196aa4c: iiscore!NOTIFICATION_CONTEXT::CallModules+0x00000028
0x71965db5: iiscore!W3_CONTEXT::DoStateRequestStart+0x00000063
0x71962108: iiscore!W3_CONTEXT::DoWork+0x0000008d
0x71964eef: iiscore!W3_MAIN_CONTEXT::StartNotificationLoop+0x00000049
0x7196c6b8: iiscore!W3_MAIN_CONTEXT::OnNewRequest+0x0000004c
0x728513b3: w3dt!UL_NATIVE_REQUEST::DoStateProcess+0x00000026
0x728511da: w3dt!OverlappedCompletionRoutine+0x0000001a
--------------------------------------

...

(省略)

...

--------------------------------------
Handle = 0x000002b0 - OPEN
Thread ID = 0x0000163c, Process ID = 0x0000102c

0x775a8014: ntdll!ZwCreateFile+0x0000000c
0x7664ce0b: kernel32!CreateFileW+0x00000379
0x10001223: rhttpmod!MyHttpModule::OnBeginRequest+0x00000063
0x719637e9: iiscore!NOTIFICATION_CONTEXT::RequestDoWork+0x000000d5
0x71963696: iiscore!NOTIFICATION_CONTEXT::CallModulesInternal+0x000002ec
0x7196aa4c: iiscore!NOTIFICATION_CONTEXT::CallModules+0x00000028
0x71965db5: iiscore!W3_CONTEXT::DoStateRequestStart+0x00000063
0x71962108: iiscore!W3_CONTEXT::DoWork+0x0000008d
0x71964eef: iiscore!W3_MAIN_CONTEXT::StartNotificationLoop+0x00000049
0x7196c6b8: iiscore!W3_MAIN_CONTEXT::OnNewRequest+0x0000004c
0x728513b3: w3dt!UL_NATIVE_REQUEST::DoStateProcess+0x00000026
0x728511da: w3dt!OverlappedCompletionRoutine+0x0000001a
--------------------------------------
Handle = 0x000002ac - OPEN
Thread ID = 0x0000163c, Process ID = 0x0000102c

0x775a7ff4: ntdll!ZwCreateEvent+0x0000000c
0x766446a1: kernel32!CreateEventExW+0x0000006e
0x7664428a: kernel32!CreateEventW+0x00000027
0x7196d596: iiscore!NOTIFICATION_CONTEXT::SetupSynchronousCall+0x0000003b
0x71966a0e: iiscore!W3_CONTEXT::MapPath+0x000003d1
0x71964e56: iiscore!W3_CONTEXT::GetScriptTranslated+0x00000033
0x71968a5b: iiscore!W3_CONTEXT::SetupStateMachine+0x00000342
0x71964ee5: iiscore!W3_MAIN_CONTEXT::StartNotificationLoop+0x0000003f
0x7196c6b8: iiscore!W3_MAIN_CONTEXT::OnNewRequest+0x0000004c
0x728513b3: w3dt!UL_NATIVE_REQUEST::DoStateProcess+0x00000026
0x728511da: w3dt!OverlappedCompletionRoutine+0x0000001a
0x72862611: W3TP!THREAD_POOL_DATA::ThreadPoolThread+0x00000089
0x72862812: W3TP!THREAD_POOL_DATA::ThreadPoolThread+0x00000024
--------------------------------------
Displayed 0x55 stack traces for outstanding handles opened since 
the previous snapshot.
0:016>

上記の結果より、前回のスナップショット取得時と比べて多数のハンドルがOPEN となっていることがわかります。 そのうち、次のスタックから開かれたハンドルが大多数を占めています。 

0x775a8014: ntdll!ZwCreateFile+0x0000000c
0x7664ce0b: kernel32!CreateFileW+0x00000379
0x10001223: rhttpmod!MyHttpModule::OnBeginRequest+0x00000063
0x719637e9: iiscore!NOTIFICATION_CONTEXT::RequestDoWork+0x000000d5
0x71963696: iiscore!NOTIFICATION_CONTEXT::CallModulesInternal+0x000002ec
0x7196aa4c: iiscore!NOTIFICATION_CONTEXT::CallModules+0x00000028
0x71965db5: iiscore!W3_CONTEXT::DoStateRequestStart+0x00000063
0x71962108: iiscore!W3_CONTEXT::DoWork+0x0000008d
0x71964eef: iiscore!W3_MAIN_CONTEXT::StartNotificationLoop+0x00000049
0x7196c6b8: iiscore!W3_MAIN_CONTEXT::OnNewRequest+0x0000004c
0x728513b3: w3dt!UL_NATIVE_REQUEST::DoStateProcess+0x00000026
0x728511da: w3dt!OverlappedCompletionRoutine+0x0000001a

このことから、この箇所でハンドルリークを発生させている可能性が高いと考えることができます。

この結果は確かに、テスト用に作成した HTTP モジュールで閉じないようにしたファイルハンドルの作成場所に一致します。 このようにスタックが特定できると、デバッグに役立てることが大変容易になります。

ここまでお読みいただき、誠にありがとうございます。SNS 等でこの記事をシェアしていただけますと、大変励みになります。どうぞよろしくお願いします。

© 2025 Web/DB プログラミング徹底解説