Поделиться через

Анализ проблемы с зависанием звонка

  • Статья

Распространенная проблема возникает, когда процесс прямо или косвенно вызывает 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

Вот как устранить эту проблему.

Пошаговые инструкции по устранению проблемы с зависанием звонка

  1. Убедитесь, что отладчик выполняет отладку процесса, которому принадлежит зависающая ячейка. (Это процесс, содержащий клиентский поток, который, как предполагается, зависает в RPC.)

  2. Получение указателя стека этого потока. Стек будет выглядеть так, как показано в предыдущем примере. В этом примере указатель стека 0x0068FBA0.

  3. Получение сведений о вызове для этого потока. Для этого используйте расширение !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)

Сведения, отображаемые здесь, позволят отслеживать вызов.

  1. Сетевой адрес пуст, что указывает на локальный компьютер. Конечная точка — 1120. Необходимо определить, в каком процессе размещается эта конечная точка. Это можно сделать, передав этот номер конечной точки в расширение !rpcexts.getendpointinfo следующим образом:
    0:001> !rpcexts.getendpointinfo 1120
    Searching for endpoint info ...
    PID  CELL ID   ST PROTSEQ        ENDPOINT
    --------------------------------------------
    0278 0000.0001 01            TCP 1120
  1. Из приведенных выше сведений видно, что 0x278 процесса содержит эту конечную точку. Определить, знает ли этот процесс что-либо об этом вызове, можно с помощью расширения !rpcexts.getcallinfo . Для этого расширения требуются четыре параметра: CallID, IfStart и ProcNum (которые были найдены на шаге 3), а также ProcessID 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. Сведения на шаге 5 полезны, но несколько сокращены. Идентификатор ячейки указан во втором столбце как 0000,0004. Если вы передадите идентификатор процесса и этот номер ячейки в расширение !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

Это показывает, что вызов находится в состоянии "dispatched", что означает, что он покинул время выполнения RPC. Время последнего обновления — 470,25. Текущее время можно узнать с помощью расширения !rpcexts.rpctime :

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

Это показывает, что последний контакт с этим вызовом был примерно 5533 секунд назад, то есть около 92 минут. Таким образом, это должен быть застрявший вызов.

  1. На последнем шаге перед подключением отладчика к процессу сервера можно изолировать поток, который в настоящее время должен обслуживать вызов, с помощью идентификатора потока обслуживания. Это другое число ячейки; на шаге 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)

Теперь вы знаете, что вы ищете поток 0x1A4 в процессе 0x278.

Возможно, поток выполнял еще один вызов RPC. При необходимости можно отследить этот вызов, повторив эту процедуру.

Примечание В этой процедуре показано, как найти поток сервера, если вы знаете поток клиента. Пример обратного метода см. в разделе Определение вызывающего объекта из потока сервера.