Compartir a través de

Análisis de un problema de llamada bloqueada

  • Artículo

Un problema común se produce cuando un proceso realiza una llamada RPC, directa o indirectamente, mientras mantiene una sección crítica o un recurso. En este caso, la llamada RPC va a otro proceso o máquina y envía a la rutina de administrador (rutina del servidor), que luego se bloquea o tarda demasiado tiempo. Esto hace que el autor de la llamada original encuentre un tiempo de espera de sección crítico.

Cuando se examina a través del depurador, RPC está encima de la pila del subproceso que posee la sección crítica, pero no está claro lo que está esperando.

Este es un ejemplo de este tipo de pila. Muchas variaciones son posibles.

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

Aquí se muestra cómo solucionar este problema.

Solución de problemas de llamadas bloqueadas: paso a paso

  1. Asegúrese de que el depurador está depurando el proceso que posee la celda bloqueada. (Este es el proceso que contiene el subproceso de cliente sospechoso de colgar en RPC).

  2. Obtenga el puntero de pila de este subproceso. La pila tendrá un aspecto similar al que se muestra en el ejemplo anterior. En este ejemplo, el puntero de pila se 0x0068FBA0.

  3. Obtenga la información de llamada de este subproceso. Para ello, use la extensión !rpcexts.rpcreadstack con el puntero de pila de subprocesos como parámetro, como se indica a continuación:

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)

La información que se muestra aquí le permitirá realizar un seguimiento de la llamada.

  1. La dirección de red está vacía, lo que indica la máquina local. El punto de conexión es 1120. Debe determinar qué proceso hospeda este punto de conexión. Para ello, pase este número de punto de conexión a la extensión !rpcexts.getendpointinfo , como se indica a continuación:
    0:001> !rpcexts.getendpointinfo 1120
    Searching for endpoint info ...
    PID  CELL ID   ST PROTSEQ        ENDPOINT
    --------------------------------------------
    0278 0000.0001 01            TCP 1120
  1. En la información anterior, puede ver que el proceso 0x278 contiene este punto de conexión. Puede determinar si este proceso conoce algo sobre esta llamada mediante la extensión !rpcexts.getcallinfo . Esta extensión necesita cuatro parámetros: CallID, IfStart y ProcNum (que se encontraron en el paso 3) y processID de 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. La información del paso 5 es útil, pero algo abreviada. El identificador de celda se asigna en la segunda columna como 0000.0004. Si pasa el identificador de proceso y este número de celda a la extensión !rpcexts.getdbgcell , verá una presentación más legible de esta celda:
    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

Esto muestra que la llamada está en estado "enviado", lo que significa que ha dejado el tiempo de ejecución rpc. La hora de la última actualización es 470.25. Puede aprender la hora actual mediante la extensión !rpcexts.rpctime :

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

Esto muestra que el último contacto con esta llamada fue hace aproximadamente 5533 segundos, que es de aproximadamente 92 minutos. Por lo tanto, esto debe ser una llamada bloqueada.

  1. Como último paso antes de adjuntar un depurador al proceso del servidor, puede aislar el subproceso que debe atender actualmente la llamada mediante el identificador del subproceso de mantenimiento. Este es otro número de celda; apareció en el paso 6 como "0x0.2". Puede usarlo de la siguiente manera:
    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)

Ahora sabe que busca 0x1A4 de subprocesos en el proceso 0x278.

Es posible que el subproceso realice otra llamada RPC. Si es necesario, puede realizar un seguimiento de esta llamada repitiendo este procedimiento.

Nota Este procedimiento muestra cómo buscar el subproceso de servidor si conoce el subproceso de cliente. Para obtener un ejemplo de la técnica inversa, vea Identificación del autor de la llamada desde el subproceso del servidor.