Condividi tramite

Analisi di un problema di chiamata bloccata

  • Articolo

Si verifica un problema comune quando un processo effettua una chiamata RPC, direttamente o indirettamente, mantenendo una sezione critica o una risorsa. In questo caso, la chiamata RPC passa a un altro processo o computer e invia alla routine di gestione (routine del server), che quindi blocca o richiede troppo tempo. In questo modo il chiamante originale rileva un timeout della sezione critica.

Quando viene esaminato attraverso il debugger, RPC si trova sopra lo stack del thread proprietario della sezione critica, ma non è chiaro cosa sta aspettando.

Ecco un esempio di tale stack. Sono possibili molte varianti.

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

Ecco come risolvere questo problema.

Risoluzione di un problema di chiamata bloccata - passaggio per passaggio

  1. Assicurarsi che il debugger stia eseguendo il debug del processo proprietario della cella bloccata. Questo è il processo contenente il thread client sospetto di sospensione in RPC.

  2. Ottenere il puntatore dello stack di questo thread. Lo stack sarà simile a quello mostrato nell'esempio precedente. In questo esempio il puntatore dello stack è 0x0068FBA0.

  3. Ottenere le informazioni sulla chiamata per questo thread. A tale scopo, usare l'estensione !rpcexts.rpcreadstack con il puntatore dello stack di thread come parametro, come indicato di seguito:

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)

Le informazioni visualizzate qui consentono di tracciare la chiamata.

  1. L'indirizzo di rete è vuoto, che indica il computer locale. L'endpoint è 1120. È necessario determinare quale processo ospita questo endpoint. Questa operazione può essere eseguita passando questo numero di endpoint all'estensione !rpcexts.getendpointinfo , come indicato di seguito:
    0:001> !rpcexts.getendpointinfo 1120
    Searching for endpoint info ...
    PID  CELL ID   ST PROTSEQ        ENDPOINT
    --------------------------------------------
    0278 0000.0001 01            TCP 1120
  1. Dalle informazioni precedenti, è possibile vedere che il processo 0x278 contiene questo endpoint. È possibile determinare se questo processo conosce qualcosa su questa chiamata usando l'estensione !rpcexts.getcallinfo . Questa estensione richiede quattro parametri: CallID, IfStart e ProcNum (che sono stati trovati nel passaggio 3) e ProcessID di 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. Le informazioni nel passaggio 5 sono utili, ma leggermente abbreviate. L'ID cella viene specificato nella seconda colonna come 0000.0004. Se si passa l'ID processo e questo numero di cella all'estensione !rpcexts.getdbgcell , verrà visualizzata una visualizzazione più leggibile di questa cella:
    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

Ciò indica che la chiamata è in stato "inviato", ovvero è stata lasciata l'ora di esecuzione RPC. L'ultima ora di aggiornamento è 470.25. È possibile apprendere l'ora corrente usando l'estensione !rpcexts.rpctime :

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

Questo mostra che l'ultimo contatto con questa chiamata era circa 5533 secondi fa, che è di circa 92 minuti. Pertanto, questa deve essere una chiamata bloccata.

  1. Come ultimo passaggio prima di collegare un debugger al processo del server, è possibile isolare il thread che deve attualmente eseguire il servizio della chiamata usando l'identificatore del thread di manutenzione. Si tratta di un altro numero di cella; è apparso nel passaggio 6 come "0x0.2". È possibile usarlo come segue:
    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)

Ora si sa che si sta cercando thread 0x1A4 in processo 0x278.

È possibile che il thread effettuasse un'altra chiamata RPC. Se necessario, è possibile tracciare questa chiamata ripetendo questa procedura.

Nota Questa procedura illustra come trovare il thread del server se si conosce il thread client. Per un esempio della tecnica inversa, vedere Identificazione del chiamante dal thread del server.