ASP.NET デッドロック検知機能について (4)


こんにちは。
d99 です。いよいよこのシリーズも最後の回です。

今回は前回の方法で採取したダンプファイルを解析してみましょう。ASP.NET の簡単なダンプ解析方法をご紹介します。細かいところが分からなくても「だいたいのイメージ」が分かって頂けるといいかなと思います。

ダンプ解析には、採取時にインストールした Debugging Tools for Windows に含まれる windbg というデバッガを使用します。[スタート] – [すべてのプログラム] – [Debugging Tools for Windows (x86)] – [WinDbg] を起動し、c:\dump にある .dmp ファイルをドラッグアンドドロップします。Worspace に関するダイアログには一旦 [No] と答えておいてください。

image image

今回の場合、現象はハングアップですので、動作が止まっているスレッドを探し出すことになります。一般的な方法としては、まず各スレッドのスタックトレース、つまり関数の呼び出し履歴を表示し、この中から止まっているスレッドを探します。まずは .NET 用のデバッガエクステンションを読み込みます。以下のコマンドを入力して Enter します。

.loadby sos mscorwks

その上で、全スレッドのスタックトレースを表示するコマンドは ~*k、マネージドのみの全スタックトレースは ~*e !clrstack で表示できます。しかしやってみても(シンボルを設定していない事もあり)あまり良く分からない内容が大量に出てきます。

実は、スタックトレースを見るだけでこのスレッドがハングアップしているのか、それとも単に作業を割り当てられるのを待っているなどの問題のない状態なのかを判断するには、それなりの経験が必要です。ダンプが採取できるタイミングというのは各スレッドが一瞬でも止まることができるタイミングなので、基本的にすべてのスレッドはなんらかの理由で止まっています。問題はその停止が動作の流れの中の一時的なものなのか、それとも異常なものなのかを見極める事です。それを間違うと何の問題もないスレッドをハングアップの原因とみなしてしまう事になります。

では、何か良いヒントはないのでしょうか。実は、ASP.NET の比較的シンプルな Web ページであれば、簡単な判別方法があります。先ほど読み込んだ sos デバッガエクステンションのコマンド、!threads でLockCount が 1以上 になっているスレッドは、非常にざっくりと言うと、ASP.NET ページ処理で作業中の可能性が高いスレッドです。

0:028> !threads
ThreadCount: 10
UnstartedThread: 0
BackgroundThread: 10
PendingThread: 0
DeadThread: 0
Hosted Runtime: no
                                      PreEmptive   GC Alloc           Lock
       ID OSID ThreadOBJ    State     GC       Context       Domain   Count APT Exception
  15    1  8e8 000dd3a0   3808220 Enabled  02b19d68:02b1b008 000fdf28     1 MTA (Threadpool Worker)
  19    2  ad0 000e33d0      b220 Enabled  00000000:00000000 000d7098     0 MTA (Finalizer)
  20    3  404 000fa500    80a220 Enabled  00000000:00000000 000d7098     0 MTA (Threadpool Completion Port)
  21    4  ebc 000fd7e8      1220 Enabled  00000000:00000000 000d7098     0 Ukn
  22    5  730 0012d768   380b220 Enabled  06b5f1b4:06b60fe8 000fdf28     2 MTA (Threadpool Worker)
  23    6  eec 0012f960   380b220 Enabled  06b63cf8:06b64fe8 000fdf28     1 MTA (Threadpool Worker)
  24    7   a4 00137188   380b220 Enabled  06b66df0:06b66fe8 000fdf28     1 MTA (Threadpool Worker)
  25    8  6a8 00138230   380b220 Enabled  02b1ce10:02b1d008 000fdf28     1 MTA (Threadpool Worker)
  26    9  d2c 00138da0   180b220 Enabled  02ae3b20:02ae4fe8 000d7098     0 MTA (Threadpool Worker)
  13    a  960 00139b50   880a220 Enabled  00000000:00000000 000d7098     0 MTA (Threadpool Completion Port)

また以前ご紹介した psscor2 には !aspxpages というコマンドもあります。ダウンロードした EXE を実行すると、指定したフォルダに ZIP ファイルが解凍されますので、これをさらに解凍し、その中に含まれる psscor2.dll を Debugging Tools for Windows のフォルダに移動します。.load コマンドで読み込み、!aspxpapegs コマンドを実行してみましょう。

0:028> .load psscor2

0:028> !aspxpages
PDB symbol for mscorwks.dll not loaded
Going to dump the HttpContexts found in the heap.
Loading the heap objects into our cache.
HttpContext    Timeout  Completed     Running  ThreadId ReturnCode   Verb RequestPath+QueryString
0x02ab28f0    19200 Sec        no       142 Sec      25        200   POST /DeadlockTest/test.aspx

x02af8438    19200 Sec        no        44 Sec      15        200   POST /DeadlockTest/test.aspx
0x06ae6484    19200 Sec       yes                   XXX        200   POST /DeadlockTest/test.aspx
0x06ae8990    19200 Sec        no       144 Sec      22        200   POST /DeadlockTest/test.aspx
0x06aee8f0    19200 Sec        no       143 Sec      23        200   POST /DeadlockTest/test.aspx
0x06af48f0    19200 Sec        no       143 Sec      24        200   POST /DeadlockTest/test.aspx
Total 70 HttpContext objects

こちらはもっと分かりやすいですね。このコマンドではリクエスト処理中のスレッドを列挙します。ThreadId が XXX のものは単純に言うと処理が終わってしまったものですので(一部例外もあります)、無視してください。これはヒープから HttpContext のクラスインスタンスを列挙し、そのプロパティから状態を出しているため、またガベージコレクトされていない HttpContext クラスインスタンスも表示されてしまうためです。

HttpContext クラス
http://msdn.microsoft.com/ja-jp/library/system.web.httpcontext(v=VS.80).aspx

今回の場合、Running 列の一番大きいものの、ThreadId は 22 ですので、このスレッドのスタックトレースを表示しましょう。~22s というコマンドで 22番 スレッドに移り、!clrstack コマンドで Visual Studio を使って C# でデバッグしている感覚(呼出し履歴ウィンドウの表示)に近い出力を出します。これが .NET の呼び出し履歴、いわゆるマネージドスタックトレースになります。

0:028> ~22s
eax=00000000 ebx=00000000 ecx=000003fc edx=069d0000 esi=00000000 edi=109cf120
eip=7c97845c esp=109cf0e0 ebp=109cf148 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:
7c97845c c3              ret

0:022> !clrstack
OS Thread Id: 0x730 (22)
ESP       EIP    
109cf230 7c97845c [HelperMethodFrame: 109cf230] System.Threading.Thread.SleepInternal(Int32)
109cf284 0eba9345 System.Threading.Thread.Sleep(Int32)
109cf288 106407da ASP.test_aspx.Button1_Click(System.Object, System.EventArgs)*** WARNING: Unable to verify checksum for App_Web__mrqmt6b.dll
c:\Inetpub\wwwroot\DeadlockTest\test.aspx:10

109cf2d0 6679f618 System.Web.UI.WebControls.Button.OnClick(System.EventArgs)
109cf2e8 6679f43b System.Web.UI.WebControls.Button.RaisePostBackEvent(System.String)
109cf300 6679f6bb System.Web.UI.WebControls.Button.System.Web.UI.IPostBackEventHandler.RaisePostBackEvent(System.String)
109cf308 6609842e System.Web.UI.Page.RaisePostBackEvent(System.Web.UI.IPostBackEventHandler, System.String)
109cf314 66098385 System.Web.UI.Page.RaisePostBackEvent(System.Collections.Specialized.NameValueCollection)
109cf328 660aa65e System.Web.UI.Page.ProcessRequestMain(Boolean, Boolean)
109cf480 660a9ee4 System.Web.UI.Page.ProcessRequest(Boolean, Boolean)
109cf4b8 660a9e11 System.Web.UI.Page.ProcessRequest()
109cf4f0 660a9da6 System.Web.UI.Page.ProcessRequestWithNoAssert(System.Web.HttpContext)
109cf4fc 660a9d82 System.Web.UI.Page.ProcessRequest(System.Web.HttpContext)
109cf510 106401b6 ASP.test_aspx.ProcessRequest(System.Web.HttpContext)
109cf520 660b0256 System.Web.HttpApplication+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
109cf554 6608332c System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)
109cf594 6608eb83 System.Web.HttpApplication+ApplicationStepManager.ResumeSteps(System.Exception)
109cf5e4 660828ac System.Web.HttpApplication.System.Web.IHttpAsyncHandler.BeginProcessRequest(System.Web.HttpContext, System.AsyncCallback, System.Object)
109cf600 66085e1c System.Web.HttpRuntime.ProcessRequestInternal(System.Web.HttpWorkerRequest)
109cf634 66085ac3 System.Web.HttpRuntime.ProcessRequestNoDemand(System.Web.HttpWorkerRequest)
109cf644 66084c5c System.Web.Hosting.ISAPIRuntime.ProcessRequest(IntPtr, Int32)
109cf858 79faca45 [ContextTransitionFrame: 109cf858]
109cf88c 79faca45 [GCFrame: 109cf88c]
109cf9e8 79faca45 [ComMethodFrame: 109cf9e8]

呼出し履歴ウィンドウと同様に、関数の呼び出しは下から上です。最終的には一番上の関数を実行中です。ただし停止の原因が一番上にあるとは限りません。例えば、System.Threading.Thread.Sleep() メソッドが一番上にあっていたとしても Sleep() 自体が悪いのではなく、なぜ Sleep() が呼び出されたのか、これはどのくらいスリープしているのかという事が重要です。

ただ今回の場合、意図的にスリープしているのですから、旅はひとまずここまでです。このスタックトレースのおおまかな形を覚えておくと役に立つかもしれません。これは「あるページでスリープさせた時のスタックトレース」であるとともに、「ASP.NET ページ処理までの関数呼び出し履歴」でもあります。前述のように、ダンプファイルから各スレッドがどういった作業中なのかを判断するにはこういった、「あるコードが実行されるまでの流れ」を知っておくと、スタックをパッと見て判別できるようになります。なので、私は初めて触るプログラミングプラットホームでは、まずコードで長期間スリープさせ、デバッガをアタッチしてスタックをみてみるといった事をよくやります。

閑話休題、デッドロックについてはいったんここで区切ります。今後もまたちょっとしたダンプの取り方・見方をちょくちょく紹介していきますので、お楽しみに。

ではまた。
d99でした。


Skip to main content