ハングアップ

IIS のサービス自体が突然クラッシュして実行できない場合と異なり、単に応答が返らなくなる場合があります。応答が遅いか、あるいは、全く反応しないような場合です。このような状態をハングアップした、と言います。

ハングアップしているときの状態は、次のようなパターンが主なものです。

何かの処理を待っている
デッドロック状態となり同期オブジェクトの待ちで停止している
(この場合は待っていても回復しません)
負荷が高くなり応答が遅い
通常は予期せぬビジーループ等で CPU 時間を 100% 占有するなどする。(遅いが応答がある)

上記のうち、ここでは処理を待つ場合、あるいはデッドロックしている場合を取り上げます。

この場合は、問題が発生している時点の情報 (ログファイル、IIS 関連プロセスのメモリダンプ) を採取してそれを解析することで、原因が特定できる場合が少なくありません。

情報を採取するには Debug Diagnostic Tool を利用するのが最も簡単です。

以下の例は非常に典型的なハングアップ問題に対処する方法です。

実験用の aspx ページ

ここでは、次のページを hang_test.aspx として作成し、ハングアップを模倣します。このページでは Page_Load にて 120 秒間スレッドをスリープさせています。

<%@ Page Language="C#" %>
<!DOCTYPE html PUBLIC 
"-//W3C//DTD XHTML 1.0 Transitional//EN" 
"http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd">
<script runat="server">
	protected void Page_Load( object sender , EventArgs e ) {

		System.Threading.Thread.Sleep( 120 * 1000 );
		
	}
</script>
<html xmlns="http://www.w3.org/1999/xhtml">
<head runat="server">
    <title></title>
</head>
<body>
<form id="form1" runat="server">
</form>
</body>
</html>

このスクリプトを用いて、ハングアップ時の情報の採取方法及び原因調査方法を示します。

Debug Diagnostic Tool を利用したハングアップ問題の調査と原因究明

Debug Diagnostic Tool を利用して、ハングアップ時の情報を採取する

Debug Diagnostic Tool を起動して、Add Rule... をクリックするとウィザードが開始します。

IIS Hang を選択します。

次の画面でモニターする、URL を入力します。この URL からの応答の有無によって、ハングアップの検出を行います。

サーバーのチェック間隔と、ハングアップが発生した、と検出するまでの待ち時間を指定します。

次の画面で Add Dump Target をクリックして、ダンプを採取するプロセスを指定します。通常は All active IIS/COM+ related processes を指定します。 (ドロップダウンから他の項目を選んでから、再度選びなおすと指定できます)

エントリが追加されました。

ルールの名前を決めます。既存のルールと名前が重なると、どれがどの情報かわかりにくいので、ユニークな名前を指定してください。

最後に、Activate the rule now (直ちにルールを有効化する) を選択して、Finish をクリックします。

以上で IIS にツールを仕掛けることが出来ました。

ログの採取～自動採取

Debug Diagnostic Tool がハングアップを検出した場合、その時点の情報 (ログとユーザーダンプ) が採取されます。

この例ではユーザーダンプが 3 個採取されたことがわかります。

ログの解析

Advanced Analysis タブを選択します。

Crash/Hang Analyzers を選択して、Start Analysis をクリックします。

ダンプファイル (*.dmp) を選択します。ファイル名にプロセス名が含まれています。 w3wp.exe でユーザーのプログラムが実行されます。通常は w3wp.exe を確認します。

自動的にダンプが解析されます。

結果は HTML ファイルとして表示されます。

問題はこれをどのように解釈するか、というところです。

解析方法はケース・バイ・ケースで、一言で原因を特定できる場合もあれば、この例のように少し追加調査しないとわからない場合もあります。

ダンプの解析～簡単な切り分け方法

上記のログの表示から、直ちには問題がわからなかったものの、スレッド 21 には調査する余地があるというメッセージが表示されていたところに着目します。

そこで、自分でユーザダンプを開き、スレッド 21 番を確認してみましょう。

cdb や WinDbg などで、ユーザダンプ (*.dmp) を開きます。この前に、シンボルパスなどは設定しておいてください。

C:\Debuggers>cdb -z "C:\Program Files\DebugDiag\Logs\Hang_Test_Log...

Microsoft (R) Windows Debugger Version 6.10.0003.233 X86
Copyright (c) Microsoft Corporation. All rights reserved.


Loading Dump File [C:\Program Files\DebugDiag\Logs\Hang_Test_Log1\w3wp.exe__D...
User Mini Dump File with Full Memory: Only application data is available

Comment: 'Dump created by Debug Diagnostic Service. IIS_COM+ Hang Dump'
Symbol search path is: srv*C:\websymbols*http://msdl.microsoft.com/download/symbols
Executable search path is:
Windows Server 2008/Windows Vista SP1 Version 6001 (Service Pack 1) MP (2 procs)...
Product: WinNt, suite: SingleUserTS
Machine Name:
Debug session time: Fri Feb 20 14:10:27.000 2009 (GMT-8)
System Uptime: 1 days 16:27:27.614
Process Uptime: 0 days 0:10:24.000
................................................................
................................................................
.......
eax=00000001 ebx=00000001 ecx=7707f6b3 edx=00040002 esi=00000000 edi=00000000
eip=770b9a94 esp=001bf930 ebp=001bf9a0 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!KiFastSystemCallRet:
770b9a94 c3              ret

スレッド 21 番へ移動します。

0:000> ~21s
eax=6fa76914 ebx=00000000 ecx=0001d4c0 edx=02bb2448 esi=0f84e898 edi=00000000
eip=770b9a94 esp=0f84e854 ebp=0f84e8bc iopl=0         nv up ei pl nz na po nc
cs=001b  ss=0023  ds=0023  es=0023  fs=003b  gs=0000             efl=00000202
ntdll!KiFastSystemCallRet:
770b9a94 c3              ret

スタックバックトレースを確認します。

0:021> kbn 100
 # ChildEBP RetAddr  Args to Child
00 0f84e850 770b83b4 76d6c350 00000001 0f84e898 ntdll!KiFastSystemCallRet
01 0f84e854 76d6c350 00000001 0f84e898 3919cc74 ntdll!NtDelayExecution+0xc
02 0f84e8bc 7104d050 0001d4c0 00000001 39068131 kernel32!SleepEx+0x62
03 0f84e8f0 7112336f 0001d4c0 00000001 0f84e914 mscorwks!EESleepEx+0xbb
04 0f84e900 7112335d 7157dc98 0001d4c0 00000001 mscorwks!CExecutionEngine::ClrSle...
05 0f84e914 7112331c 0001d4c0 00000001 39068091 mscorwks!ClrSleepEx+0x14
06 0f84e950 7112341d 0001d4c0 39068031 02abbb58 mscorwks!Thread::UserSleep+0x63
*** WARNING: Unable to verify checksum for mscorlib.ni.dll
07 0f84e9f0 6fc09225 01ea0c9d 02bb2448 02bb2448 mscorwks!ThreadNative::Sleep+0xce
*** WARNING: Unable to verify checksum for System.Web.RegularExpressions.ni.dll
08 0f84ea04 53c8a7ff 02abbb58 0f84ea28 6c7c2594 mscorlib_ni+0x1d9225
*** WARNING: Unable to verify checksum for System.Web.ni.dll
09 0f84ea10 6c7c2594 02abbb58 02bb2448 02bb2448 System_Web_RegularExpression...
0a 0f84ea28 6c7bba84 02abbb58 02bb2448 02bb2448 System_Web_ni+0x192594
0b 0f84ea40 6c7bbac3 00f82098 02bb2448 02bb2448 System_Web_ni+0x18ba84
0c 0f84ea58 6c7b7b74 00000000 02a901d0 00000000 System_Web_ni+0x18bac3
0d 0f84ebac 6c7b77a4 00000001 02bb2448 00000001 System_Web_ni+0x187b74
0e 0f84ebe4 6c7b76d1 00000001 06a908f4 06a908f4 System_Web_ni+0x1877a4
0f 0f84ec20 6c7b7666 02bb2448 0f84ec40 6c7b7642 System_Web_ni+0x1876d1
10 0f84ec2c 6c7b7642 00000000 02bb2448 02abb438 System_Web_ni+0x187666
11 0f84ec50 6c7bdb16 0f0d7390 00000000 06ae73fc System_Web_ni+0x187642
12 0f84ec84 6c79132c 00000000 00000000 00000000 System_Web_ni+0x18db16
13 0f84ecc0 6cd8524f 0f84ed20 3e260ed9 7103a6b8 System_Web_ni+0x16132c
14 0f84ed54 6cd7b674 00000000 00000000 0f84ed78 System_Web_ni+0x75524f
15 0f84ed68 6cd660cd 06a9a01c 3e260ed9 7103a6b8 System_Web_ni+0x74b674
16 0f84edd4 6ce3a692 06ae73fc 3e260ed9 7103a6b8 System_Web_ni+0x7360cd
17 0f84ee54 6ce3a47f 00000000 0000000a 00000000 System_Web_ni+0x80a692
...
36 0f84f858 7709e4b6 0f0bdc88 7032df35 00000000 kernel32!BaseThreadInitThunk+0xe
37 0f84f898 7709e489 71151fcf 0f0bdc88 00000000 ntdll!__RtlUserThreadStart+0x23
38 0f84f8b0 00000000 71151fcf 0f0bdc88 00000000 ntdll!_RtlUserThreadStart+0x1b

System_Web_ni などは、このスレッドでマネージドスタックが形成されているときに見られます。

そこで、sos デバッガエクステンションを用いて、マネージドスタックを確認します。

0:021> !sos.clrstack
OS Thread Id: 0x1630 (21)
ESP       EIP
0f84e9a4 770b9a94 [HelperMethodFrame: 0f84e9a4] System.Threading.Thread.Sleep...
0f84e9f8 6fc09225 System.Threading.Thread.Sleep(Int32)
0f84e9fc 01ea0c9d ASP.hang_test_aspx.Page_Load(System.Object, System.EventArgs)
0f84ea10 53c8a7ff System.Web.Util.CalliHelper.EventArgFunctionCaller(IntPtr, Sys...
 System.Object, System.EventArgs)
0f84ea20 6c7c2594 System.Web.Util.CalliEventHandlerDelegateProxy.Callback(
System.Object, System.EventArgs)
0f84ea34 6c7bba84 System.Web.UI.Control.OnLoad(System.EventArgs)
0f84ea48 6c7bbac3 System.Web.UI.Control.LoadRecursive()
0f84ea60 6c7b7b74 System.Web.UI.Page.ProcessRequestMain(Boolean, Boolean)
0f84ebb8 6c7b77a4 System.Web.UI.Page.ProcessRequest(Boolean, Boolean)
0f84ebf0 6c7b76d1 System.Web.UI.Page.ProcessRequest()
0f84ec28 6c7b7666 System.Web.UI.Page.ProcessRequestWithNoAssert(System.Web.HttpC...
0f84ec34 6c7b7642 System.Web.UI.Page.ProcessRequest(System.Web.HttpContext)
0f84ec48 01ea07fe ASP.hang_test_aspx.ProcessRequest(System.Web.HttpContext)
...
0f84f4cc 00af22b4 [ContextTransitionFrame: 0f84f4cc]
0:021> ?0001d4c0
Evaluate expression: 120000 = 0001d4c0

上記から、このスレッドでは hang_test.asp の Page_Load にて、System.Threading.Thread.Sleep を呼び出していることが浮かび上がってきました。確かにこれは、テスト用のページで行っていた処理そのものです。