スタックした呼び出しの問題の分析
一般的な問題は、プロセスがクリティカル セクションまたはリソースを保持しながら、直接または間接的に RPC 呼び出しを行うときに発生します。 この場合、RPC 呼び出しは別のプロセスまたはコンピューターに送信され、マネージャー ルーチン (サーバー ルーチン) にディスパッチされ、ハングしたり、時間がかかりすぎたりします。 これにより、元の呼び出し元がクリティカル セクション タイムアウトに遭遇します。
デバッガーを使用して調べると、RPC はクリティカル セクションを所有するスレッドのスタックの上にありますが、何を待っているかは明確ではありません。
このようなスタックの例を次に示します。 さまざまなバリエーションが可能です。
0:002> ~1k
ChildEBP RetAddr
0068fba0 77e9e8eb ntdll!ZwWaitForSingleObject+0xb
0068fbc8 4efeff73 KERNEL32!WaitForSingleObjectEx+0x5a
0068fbe8 4eff0012 RPCRT4!UTIL_WaitForSyncIO+0x21
0068fc0c 4efe6e2b RPCRT4!UTIL_GetOverlappedResultEx+0x44
0068fc44 4ef973bf RPCRT4!WS_SyncRecv+0x12a
0068fc68 4ef98d5a RPCRT4!OSF_CCONNECTION__TransSendReceive+0xcb
0068fce4 4ef9b682 RPCRT4!OSF_CCONNECTION__SendFragment+0x297
0068fd38 4ef9a5a8 RPCRT4!OSF_CCALL__SendNextFragment+0x272
0068fd88 4ef9a9cb RPCRT4!OSF_CCALL__FastSendReceive+0x165
0068fda8 4ef9a7f8 RPCRT4!OSF_CCALL__SendReceiveHelper+0xed
0068fdd4 4ef946a7 RPCRT4!OSF_CCALL__SendReceive+0x37
0068fdf0 4efd56b3 RPCRT4!I_RpcSendReceive+0xc4
0068fe08 01002850 RPCRT4!NdrSendReceive+0x4f
0068ff40 01001f32 rtclnt+0x2850
0068ffb4 77e92ca8 rtclnt+0x1f32
0068ffec 00000000 KERNEL32!CreateFileA+0x11b
この問題をトラブルシューティングする方法は次のとおりです。
スタックした呼び出しの問題のトラブルシューティング - ステップ バイ ステップ
デバッガーがスタックしたセルを所有するプロセスをデバッグしていることを確認します。 (これは、RPC でのハングが疑われるクライアント スレッドを含むプロセスです)。
このスレッドのスタック ポインターを取得します。 スタックは、前の例に示したスタックのようになります。 この例では、スタック ポインターは 0x0068FBA0 です。
このスレッドの呼び出し情報を取得します。 これを行うには、次のように、パラメーターとして !rpcexts.rpcreadstack 拡張コマンドをスレッド スタック ポインターと共に使用します。
0:001> !rpcexts.rpcreadstack 68fba0
CallID: 1
IfStart: 19bb5061
ProcNum: 0
Protocol Sequence: "ncacn_ip_tcp" (Address: 00692ED8)
NetworkAddress: "" (Address: 00692F38)
Endpoint: "1120" (Address: 00693988)
ここに表示される情報を使用すると、呼び出しをトレースできます。
- ネットワーク アドレスは空です。つまり、ローカル コンピューターを示します。 エンドポイントは 1120 です。 このエンドポイントをホストするプロセスを決定する必要があります。 これを行うには、次のように、このエンドポイント番号を !rpcexts.getendpointinfo 拡張コマンドに渡します。
0:001> !rpcexts.getendpointinfo 1120
Searching for endpoint info ...
PID CELL ID ST PROTSEQ ENDPOINT
--------------------------------------------
0278 0000.0001 01 TCP 1120
- 上記の情報から、プロセス 0x278 にこのエンドポイントが含まれていることを確認できます。 !rpcexts.getcallinfo 拡張コマンドを使用して、このプロセスがこの呼び出しについて何かを認識しているかどうかを判断できます。 この拡張コマンドには、次の 4 つのパラメーター (CallID、IfStart、ProcNum (ステップ 3 で見つかった)、および 0x278 の ProcessID) が必要です。
0:001> !rpcexts.getcallinfo 1 19bb5061 0 278
Searching for call info ...
PID CELL ID ST PNO IFSTART TIDNUMBER CALLFLAG CALLID LASTTIME CONN/CLN
----------------------------------------------------------------------------
0278 0000.0004 02 000 19bb5061 0000.0002 00000001 00000001 00072c09 0000.0003
- ステップ 5 の情報は便利ですが、やや省略されています。 セル ID は、2 番目の列に 0000.0004 として指定されます。 プロセス ID とこのセル番号を !rpcexts.getdbgcell 拡張コマンドに渡すと、このセルが読みやすく表示されます。
0:001> !rpcexts.getdbgcell 278 0.4
Getting cell info ...
Call
Status: Dispatched
Procedure Number: 0
Interface UUID start (first DWORD only): 19BB5061
Call ID: 0x1 (1)
Servicing thread identifier: 0x0.2
Call Flags: cached
Last update time (in seconds since boot):470.25 (0x1D6.19)
Owning connection identifier: 0x0.3
これは、呼び出しが "ディスパッチ済み" 状態であることを示しています。つまり、RPC ランタイムが残っていることを意味します。 最終更新時刻 470.25 です。 現在の時刻は、!rpcexts.rpctime 拡張コマンドを使用して確認できます。
0:001> !rpcexts.rpctime
Current time is: 6003, 422
これは、この呼び出しの最後のコンタクトが約 5533 秒 (約 92 分) 前であったことを示しています。 したがって、これはスタックした呼び出しに違いありません。
- サーバー プロセスにデバッガーをアタッチする前の最後の手順として、サービス スレッド識別子を使用して、現在呼び出しを処理する必要があるスレッドを分離できます。 これは別のセル番号です。ステップ 6 で "0x0.2" と表示されました。 これを次のように使用できます。
0:001> !rpcexts.getdbgcell 278 0.2
Getting cell info ...
Thread
Status: Dispatched
Thread ID: 0x1A4 (420)
Last update time (in seconds since boot):470.25 (0x1D6.19)
これで、プロセス 0x278 でスレッド 0x1A4 を探していることがわかります。
スレッドが別の RPC 呼び出しを行っていた可能性があります。 必要に応じて、この手順を繰り返してこの呼び出しをトレースできます。
注: この手順では、クライアント スレッドがわかっている場合にサーバー スレッドを検索する方法を示します。 逆の手法の例については、「サーバー スレッドからの呼び出し元の特定」を参照してください。