Freigeben über

Analysieren eines Problems mit hängen gebliebenen Anrufen

  • Artikel

Ein häufiges Problem tritt auf, wenn ein Prozess direkt oder indirekt einen RPC-Aufruf ausgibt, während ein kritischer Abschnitt oder eine Ressource gehalten wird. In diesem Fall wird der RPC-Aufruf an einen anderen Prozess oder Computer weitergeleitet und an die Managerroutine (Serverroutine) weitergeleitet, die dann anhängt oder zu lange dauert. Dies führt dazu, dass für den ursprünglichen Aufrufer ein kritisches Abschnittstimeout auftritt.

Wenn sie über den Debugger untersucht wird, befindet sich RPC auf dem Stapel des Threads, der den kritischen Abschnitt besitzt, aber es ist nicht klar, worauf er wartet.

Hier sehen Sie ein Beispiel für einen solchen Stapel. Viele Variationen sind möglich.

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

Hier erfahren Sie, wie Sie dieses Problem beheben.

Problembehandlung bei einem Problem mit einem hängenden Anruf – Schritt für Schritt

  1. Stellen Sie sicher, dass der Debugger den Prozess debuggen, der die festgefahrene Zelle besitzt. (Dies ist der Prozess, der den Clientthread enthält, der vermutet wird, dass er in RPC hängen bleibt.)

  2. Rufen Sie den Stapelzeiger dieses Threads ab. Der Stapel sieht wie im vorherigen Beispiel gezeigt aus. In diesem Beispiel wird der Stapelzeiger 0x0068FBA0.

  3. Rufen Sie die Anrufinformationen für diesen Thread ab. Verwenden Sie dazu die Erweiterung !rpcexts.rpcreadstack mit dem Threadstapelzeiger als Parameter, wie folgt:

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)

Mit den hier angezeigten Informationen können Sie den Anruf nachverfolgen.

  1. Die Netzwerkadresse ist leer, was den lokalen Computer angibt. Der Endpunkt ist 1120. Sie müssen ermitteln, welcher Prozess diesen Endpunkt hostet. Hierzu können Sie diese Endpunktnummer wie folgt an die Erweiterung !rpcexts.getendpointinfo übergeben:
    0:001> !rpcexts.getendpointinfo 1120
    Searching for endpoint info ...
    PID  CELL ID   ST PROTSEQ        ENDPOINT
    --------------------------------------------
    0278 0000.0001 01            TCP 1120
  1. Aus den vorherigen Informationen können Sie sehen, dass der Prozess 0x278 diesen Endpunkt enthält. Sie können feststellen, ob dieser Prozess etwas über diesen Aufruf weiß, indem Sie die Erweiterung !rpcexts.getcallinfo verwenden. Diese Erweiterung benötigt vier Parameter: CallID, IfStart und ProcNum (die in Schritt 3 gefunden wurden) und die ProcessID von 0x278:
    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
  1. Die Informationen in Schritt 5 sind nützlich, aber etwas abgekürzt. Die Zell-ID wird in der zweiten Spalte als 0000.0004 angegeben. Wenn Sie die Prozess-ID und diese Zellennummer an die Erweiterung !rpcexts.getdbgcell übergeben, wird eine lesbarere Anzeige dieser Zelle angezeigt:
    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

Dies zeigt, dass sich der Aufruf im Status "dispatched" befindet, was bedeutet, dass die RPC-Laufzeit verlassen hat. Die letzte Aktualisierungszeit ist 470.25. Sie können die aktuelle Zeit mithilfe der Erweiterung !rpcexts.rpctime kennenlernen:

    0:001> !rpcexts.rpctime
    Current time is: 6003, 422

Dies zeigt, dass der letzte Kontakt mit diesem Anruf ungefähr 5533 Sekunden zurückliegt, also etwa 92 Minuten. Daher muss dies ein hängen gebliebener Anruf sein.

  1. Als letzten Schritt vor dem Anfügen eines Debuggers an den Serverprozess können Sie den Thread isolieren, der derzeit den Aufruf verarbeiten soll, indem Sie den Wartungsthreadbezeichner verwenden. Dies ist eine weitere Zellennummer. sie wurde in Schritt 6 als "0x0.2" angezeigt. Sie können es wie folgt verwenden:
    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)

Nun wissen Sie, dass Sie nach 0x1A4 im Prozess 0x278 suchen.

Es ist möglich, dass der Thread einen weiteren RPC-Aufruf ausgeführt hat. Bei Bedarf können Sie diesen Aufruf nachverfolgen, indem Sie diese Prozedur wiederholen.

Hinweis In diesem Verfahren wird gezeigt, wie Sie den Serverthread finden, wenn Sie den Clientthread kennen. Ein Beispiel für die umgekehrte Technik finden Sie unter Identifizieren des Aufrufers aus dem Serverthread.