troushoo

ダンプを用いたハング状態のアプリの調査方法 - クリティカルセクション編

Defrag Tools
今回は、ハング状態のアプリを、ダンプを用いて調査する方法を紹介します。
今回の内容は、マイクロソフトのエンジニアが出演する人気のビデオ、Defrag Tools で紹介されていた内容を元に記述しています。

【ダンプの取得】
まずは、ハング状態にあるアプリのダンプを取得します。

1. アプリを起動し、ハング状態を発生させます。
今回使用したプログラムコードは後述しますが、プログラム自体は重要ではありません。

2. タスクマネージャーよりダンプを取得します。
アプリ名を右クリックし、”ダンプ ファイルの作成”で作成可能です。
ダンプの取得

【ダンプの調査】
WinDbg を用いて、取得したダンプを調査します。

0. WinDbg でダンプファイルを開き、シンボルの設定を行います。

1. ~*k を実行し、すべてのスレッドのコールスタックを確認します。
すると、コールスタックに “CriticalSection” を含む関数(= 赤色の部分)があることがわかります。
これにより、「クリティカルセクションによるデッドロックのため、ハングが発生しているのではないか?」と推測できます。

0:000> ~*k
~略~

1 Id: fb4.e84 Suspend: 0 Teb: 000007f6`d819b000 Unfrozen
Child-SP RetAddr Call Site
0000003b`4a96f5c8 000007fe`0bcfab2a ntdll!NtWaitForSingleObject+0xa
0000003b`4a96f5d0 000007fe`0bcad015 ntdll!RtlpWaitOnCriticalSection+0xea
0000003b`4a96f6a0 000007f6`d85c1479 ntdll!RtlpEnterCriticalSectionContended+0x94
0000003b`4a96f6e0 000007fd`faae6e65 MyDeadLock!func0+0x69 [c:\users\eight\documents\visual studio 2012\projects\mydeadlock\mydeadlock\mydeadlock.cpp @ 24]
0000003b`4a96f710 000007fd`faae6f8c MSVCR110D!beginthread+0x205
0000003b`4a96f760 000007fe`090c167e MSVCR110D!endthread+0xfc
0000003b`4a96f7a0 000007fe`0bcfd609 kernel32!BaseThreadInitThunk+0x1a
0000003b`4a96f7d0 00000000`00000000 ntdll!RtlUserThreadStart+0x1d

2 Id: fb4.60c Suspend: 0 Teb: 000007f6`d806e000 Unfrozen
Child-SP RetAddr Call Site
0000003b`4aa6fa58 000007fe`0bcfab2a ntdll!NtWaitForSingleObject+0xa
0000003b`4aa6fa60 000007fe`0bcad015 ntdll!RtlpWaitOnCriticalSection+0xea
0000003b`4aa6fb30 000007f6`d85c1509 ntdll!RtlpEnterCriticalSectionContended+0x94
0000003b`4aa6fb70 000007fd`faae6e65 MyDeadLock!func1+0x69 [c:\users\eight\documents\visual studio 2012\projects\mydeadlock\mydeadlock\mydeadlock.cpp @ 43]
0000003b`4aa6fba0 000007fd`faae6f8c MSVCR110D!beginthread+0x205
0000003b`4aa6fbf0 000007fe`090c167e MSVCR110D!endthread+0xfc
0000003b`4aa6fc30 000007fe`0bcfd609 kernel32!BaseThreadInitThunk+0x1a
0000003b`4aa6fc60 00000000`00000000 ntdll!RtlUserThreadStart+0x1d

2. !locks を実行し、現在ロックされているクリティカルセクションを調べます。
OwningThread の部分(= 赤色の部分) より、e84 と 60c が クリティカルセクションを持っていることがわかります。
0:000> !locks

CritSec MyDeadLock!CriticalSection0+0 at 000007f6d85d0270
WaiterWoken No
LockCount 1
RecursionCount 1
OwningThread e84
EntryCount 0
ContentionCount 1
*** Locked

CritSec MyDeadLock!CriticalSection1+0 at 000007f6d85d0298
WaiterWoken No
LockCount 1
RecursionCount 1
OwningThread 60c
EntryCount 0
ContentionCount 1
*** Locked

Scanned 6 critical sections

3.  ~~[e84]s で、ロックされているクリティカルセクションを保持しているスレッドに切り替えます。
0:000> ~~[e84]s
ntdll!NtWaitForSingleObject+0xa:
000007fe`0bca2c2a c3 ret

4. kv を実行し、クリティカルセクションを探します。
すると、000007f6`d85d0298 (= スレッド60c が持っているクリティカルセクション) を確認できます。
0:001> kv
Child-SP RetAddr : Args to Child : Call Site
0000003b`4a96f5c8 000007fe`0bcfab2a : 000007f6`d85d0298 00000000`0000003c 00000000`00000000 000007f6`d85c1b85 : ntdll!NtWaitForSingleObject+0xa
0000003b`4a96f5d0 000007fe`0bcad015 : 000007fd`ffc9bc70 00000000`00000026 000007f6`d85d0298 cccccccc`cccccccc : ntdll!RtlpWaitOnCriticalSection+0xea
0000003b`4a96f6a0 000007f6`d85c1479 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : ntdll!RtlpEnterCriticalSectionContended+0x94
0000003b`4a96f6e0 000007fd`faae6e65 : 00000000`00000000 000007fd`00000002 00000000`00000000 00000000`00000000 : MyDeadLock!func0+0x69 [c:\users\eight\documents\visual studio 2012\projects\mydeadlock\mydeadlock\mydeadlock.cpp @ 24]
0000003b`4a96f710 000007fd`faae6f8c : 0000003b`4a6ff110 00000000`00000000 00000000`00000000 00000000`00000000 : MSVCR110D!beginthread+0x205
0000003b`4a96f760 000007fe`090c167e : 0000003b`4a6ff5d0 00000000`00000000 00000000`00000000 00000000`00000000 : MSVCR110D!endthread+0xfc
0000003b`4a96f7a0 000007fe`0bcfd609 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : kernel32!BaseThreadInitThunk+0x1a
0000003b`4a96f7d0 00000000`00000000 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : ntdll!RtlUserThreadStart+0x1d
この結果より、以下がわかります。
「スレッドe84 は、スレッド60c が持っているクリティカルセクションを待っている (*1)」

5. 同様に~~[60c]s で、ロックされているクリティカルセクションを保持しているスレッドに切り替え、kv を実行します。
すると、000007f6`d85d0270 (= スレッドe84 が待っているクリティカルセクション) を確認できます。
0:001> ~~[60c]s
ntdll!NtWaitForSingleObject+0xa:
000007fe`0bca2c2a c3 ret
0:002> kv
Child-SP RetAddr : Args to Child : Call Site
0000003b`4aa6fa58 000007fe`0bcfab2a : 000007f6`d85d0270 00000000`00000038 00000000`00000000 000007f6`d85c1b85 : ntdll!NtWaitForSingleObject+0xa
0000003b`4aa6fa60 000007fe`0bcad015 : 000007fd`ffc9bc70 00000000`0000002b 000007f6`d85d0270 cccccccc`cccccccc : ntdll!RtlpWaitOnCriticalSection+0xea
0000003b`4aa6fb30 000007f6`d85c1509 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : ntdll!RtlpEnterCriticalSectionContended+0x94
0000003b`4aa6fb70 000007fd`faae6e65 : 00000000`00000000 000007fd`00000002 00000000`00000000 00000000`00000000 : MyDeadLock!func1+0x69 [c:\users\eight\documents\visual studio 2012\projects\mydeadlock\mydeadlock\mydeadlock.cpp @ 43]
0000003b`4aa6fba0 000007fd`faae6f8c : 0000003b`4a6ff5d0 00000000`00000000 00000000`00000000 00000000`00000000 : MSVCR110D!beginthread+0x205
0000003b`4aa6fbf0 000007fe`090c167e : 0000003b`4a6ffa90 00000000`00000000 00000000`00000000 00000000`00000000 : MSVCR110D!endthread+0xfc
0000003b`4aa6fc30 000007fe`0bcfd609 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : kernel32!BaseThreadInitThunk+0x1a
0000003b`4aa6fc60 00000000`00000000 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : ntdll!RtlUserThreadStart+0x1d
この結果より、以下がわかります。
「スレッド60c は、スレッドe84 が待っているクリティカルセクションを持っている (*2)」

(*1) と (*2) をもう一度書くとこのようになります。
「スレッドe84 は、スレッド60c が持っているクリティカルセクションを待っている (*1)」
  → すなわち、スレッド60c が動かないと、スレッドe84 は動けない。
「スレッド60c は、スレッドe84 が待っているクリティカルセクションを持っている (*2)」
  → すなわち、スレッドe84 が動かないと、スレッド60c は動けない。
この結果より、デッドロックに陥っていることがわかり、これがハングの原因であったとわかります。

補足: !cs を実行してクリティカルセクションの状態を確認することもできます。
LOCKED より、上記のクリティカルセクションはロックされていること、LockCount より、1つのスレッドより待たれていることがわかります。
0:002> !cs
-----------------------------------------
DebugInfo = 0x000007fe0bddf400
Critical section = 0x000007fe0bdd8140 (ntdll!RtlpProcessHeapsListLock+0x0)
NOT LOCKED
LockSemaphore = 0x0
SpinCount = 0x00000000020007d0
-----------------------------------------
DebugInfo = 0x000007fe0bddf430
Critical section = 0x0000003b4a6f0298 (+0x3B4A6F0298)
NOT LOCKED
LockSemaphore = 0x0
SpinCount = 0x00000000020007d0
-----------------------------------------
DebugInfo = 0x000007fe0bddf460
Critical section = 0x0000003b4a530298 (+0x3B4A530298)
NOT LOCKED
LockSemaphore = 0x0
SpinCount = 0x00000000020007d0
-----------------------------------------
DebugInfo = 0x000007fe0bddf490
Critical section = 0x000007fdfacb2c58 (MSVCR110D!wcmdln+0x218)
NOT LOCKED
LockSemaphore = 0x34
SpinCount = 0x0000000000000fa0
-----------------------------------------
DebugInfo = 0x000007fe0bddf4c0
Critical section = 0x000007f6d85d0270 (MyDeadLock!CriticalSection0+0x0)
LOCKED
LockCount = 0x1
WaiterWoken = No
OwningThread = 0x0000000000000e84
RecursionCount = 0x1
LockSemaphore = 0x38
SpinCount = 0x00000000020007d0
-----------------------------------------
DebugInfo = 0x000007fe0bddf4f0
Critical section = 0x000007f6d85d0298 (MyDeadLock!CriticalSection1+0x0)
LOCKED
LockCount = 0x1
WaiterWoken = No
OwningThread = 0x000000000000060c
RecursionCount = 0x1
LockSemaphore = 0x3C
SpinCount = 0x00000000020007d0


補足
・今回使用したアプリのコード

// MyDeadLock.cpp : コンソール アプリケーションのエントリ ポイントを定義します。
//

#include "stdafx.h"

CRITICAL_SECTION CriticalSection0;
CRITICAL_SECTION CriticalSection1;


void func0(LPVOID pParam){
//スレッド0 が CriticalSection0 を取得
EnterCriticalSection(&CriticalSection0);
std::cout << "スレッド0 が CriticalSection0 を取得 \n";

Sleep(1000); //デッドロックを発生させやすいようにするためのコード

std::cout << "スレッド0 が CriticalSection1 を待機 \n";

//スレッド0 が CriticalSection1 を取得
EnterCriticalSection(&CriticalSection1);


//スレッド0 が CriticalSection1 を放棄
LeaveCriticalSection(&CriticalSection1);

//スレッド0 が CriticalSection0 を放棄
LeaveCriticalSection(&CriticalSection0);
}

void func1(LPVOID pParam){
//スレッド1 が CriticalSection1 を取得
EnterCriticalSection(&CriticalSection1);
std::cout << "\t\t\t\t\tスレッド1 が CriticalSection1 を取得 \n";

Sleep(1000); //デッドロックを発生させやすいようにするためのコード

std::cout << "\t\t\t\t\tスレッド1 が CriticalSection0 を待機 \n";

//スレッド1 が CriticalSection0 を取得
EnterCriticalSection(&CriticalSection0);

//スレッド1 が CriticalSection0 を放棄
LeaveCriticalSection(&CriticalSection0);

//スレッド1 が CriticalSection1 を放棄
LeaveCriticalSection(&CriticalSection1);

}


int _tmain(int argc, _TCHAR* argv[])
{
HANDLE hThread[2];

//クリティカルセクションオブジェクトの初期化
InitializeCriticalSection(&CriticalSection0);
InitializeCriticalSection(&CriticalSection1);

hThread[0] = (HANDLE)_beginthread(func0, 0, NULL);
hThread[1] = (HANDLE)_beginthread(func1, 0, NULL);

//スレッドの終了を待って、ハンドルをクローズ
WaitForMultipleObjects(2,hThread,TRUE, INFINITE);

//クリティカルセクションオブジェクトの削除
DeleteCriticalSection(&CriticalSection0);
DeleteCriticalSection(&CriticalSection1);


CloseHandle(hThread[0]);
CloseHandle(hThread[1]);

return 0;
}


上記を実行すると、以下の画面の状態で処理が進まなくなります。
ハング時の画面

リンク
・Defrag Tools: #24 - WinDbg - Critical Sections (英語)
http://channel9.msdn.com/Shows/Defrag-Tools/Defrag-Tools-24-WinDbg-Critical-Sections


  1. 2013/06/04(火) 22:27:30|
  2. WinDbg
  3. | トラックバック:0
  4. | コメント:0
<<Visual Studio 2012 Update 2 の新機能 : コードマップとデバッガーとの統合 | ホーム | 待機チェーンの分析 : Windows 8 のタスクマネージャーの新機能>>

コメント

コメントの投稿


管理者にだけ表示を許可する

トラックバック

トラックバック URL
http://troushoo.blog.fc2.com/tb.php/117-1f8f1c45
この記事にトラックバックする(FC2ブログユーザー)

スポンサーリンク

最新記事

月別アーカイブ

カテゴリ

ツール (92)
ネットワーク (76)
Visual Studio (56)
SOS・Psscor2/Psscor4 (25)
WinDbg (25)
Linux (22)
Azure (17)
Tips (20)
英語 (1)
About Me (1)
未分類 (0)

全記事表示リンク

全ての記事を表示する

検索フォーム

RSSリンクの表示

リンク

このブログをリンクに追加する