Delen via

Analyseren van een vastgelopen oproepprobleem

Een veelvoorkomend probleem treedt op wanneer een proces een RPC-aanroep maakt, direct of indirect, terwijl een kritieke sectie of een resource wordt vastgehouden. In dit geval gaat de RPC-aanroep naar een ander proces of een andere machine en verzendt deze naar de managerroutine (serverroutine), die vervolgens vastloopt of te lang duurt. Hierdoor krijgt de oorspronkelijke aanroeper een time-out in een kritieke sectie.

Bij onderzoek via het foutopsporingsprogramma bevindt RPC zich boven op de stack van de thread die eigenaar is van de kritieke sectie, maar het is niet duidelijk waar het op wacht.

Hier volgt een voorbeeld van een dergelijke stapel. Veel variaties zijn mogelijk.

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

U kunt dit probleem als volgt oplossen.

Problemen met vastgelopen aanroepen oplossen - stapsgewijs

  1. Zorg ervoor dat het foutopsporingsprogramma fouten opspoort in het proces dat eigenaar is van de vastgelopen cel. (Dit is het proces met de clientthread waarvan wordt vermoed dat deze in RPC vasthangt.)

  2. Haal de stack pointer van deze thread op. De stack ziet eruit als de stack die in het vorige voorbeeld wordt weergegeven. In dit voorbeeld is de stackpointer 0x0068FBA0.

  3. Haal de gespreksgegevens voor deze thread op. Gebruik de !rpcexts.rpcreadstack extensie met de thread-stackpointer als parameter hiervoor als volgt:

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)

Met de informatie die hier wordt weergegeven, kunt u de aanroep traceren.

  1. Het netwerkadres is leeg, wat de lokale computer aangeeft. Het eindpunt is 1120. U moet bepalen welk proces als host fungeert voor dit eindpunt. Dit kan worden gedaan door dit eindpuntnummer als volgt door te geven aan de !rpcexts.getendpointinfo extensie:
    0:001> !rpcexts.getendpointinfo 1120
    Searching for endpoint info ...
    PID  CELL ID   ST PROTSEQ        ENDPOINT
    --------------------------------------------
    0278 0000.0001 01            TCP 1120
  1. In de voorgaande informatie ziet u dat proces 0x278 dit eindpunt bevat. U kunt bepalen of dit proces iets van deze aanroep weet met behulp van de !rpcexts.getcallinfo extensie. Deze extensie heeft vier parameters nodig: CallID, IfStarten ProcNum (die zijn gevonden in stap 3) en de ProcessID van 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. De informatie in stap 5 is nuttig, maar enigszins afgekort. De cel-id wordt in de tweede kolom opgegeven als 0000,0004. Als u de proces-id en dit celnummer doorgeeft aan de extensie !rpcexts.getdbgcell, ziet u een beter leesbare weergave van deze cel:
    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

Dit geeft aan dat de aanroep de status 'verzonden' heeft, wat betekent dat de RPC-runtime is verlaten. De laatste updatetijd is 470.25. U kunt de huidige tijd leren met behulp van de extensie !rpcexts.rpctime:

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

Dit laat zien dat het laatste contact met deze oproep ongeveer 5533 seconden geleden was, wat ongeveer 92 minuten is. Dit moet dus een vastgelopen oproep zijn.

  1. Als laatste stap voordat u een foutopsporingsprogramma aan het serverproces koppelt, kunt u de thread isoleren die momenteel de aanroep moet verwerken met behulp van de servicethread-id. Dit is een ander celnummer; het werd weergegeven in stap 6 als '0x0.2'. U kunt deze als volgt gebruiken:
    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)

Nu weet u dat u naar thread 0x1A4 zoekt in proces 0x278.

Het is mogelijk dat de thread een andere RPC-aanroep maakte. Indien nodig kunt u deze aanroep traceren door deze procedure te herhalen.

Opmerking In deze procedure ziet u hoe u de serverthread kunt vinden als u de clientthread kent. Zie De aanroeper van de serverthreadidentificeren voor een voorbeeld van de omgekeerde techniek.

  • Last updated on