Анализ дампов Delphi-приложений. Hang (Episode #2)

   История о зависании плагина для Internet Explorer-a.
   С чего началась история - было замечено, что в определенный момент этот BHO (Browser Helper Object)ля IE прекращал подавать признаки жизни (то бишь - внешние проявление активности). А может даже зависал браузер (детали, к сожалению, уже не помню)...


   С процесса iexplore.exe был, когда в очередной раз наступило это время "Ч", с него был снят дамп [1].

   Если быть совсем точным - то дамп был снят с нескольких процессов, т.к. дело было с IE8.

   Недолгий поиск по дампам обнаружил заблокированный на критической секции поток. И попытка захвата критической секции была предпринята из нашего кода:

0:004> k
ChildEBP RetAddr  
02e6e754 77068c64 ntdll!NtWaitForSingleObject+0x15
02e6e7b8 77068b48 ntdll!RtlpWaitOnCriticalSection+0x13e
02e6e7e0 20031fe0 ntdll!RtlEnterCriticalSection+0x150
WARNING: Stack unwind information not available. Following frames may be wrong.
02e6e820 23e089f4 rtl100!ClassesTThreadListLockList$qqrv+0xc
02e6e83c 23e08a32 storage!uStorage.TStorageHelper.CreateStorage+0x20
02e6e868 23e0a759 storage!uStorage.TStorageHelper.CreateStorage+0x36
02e6e8f4 23f0cb7f storage!uStorage.TStorageManager.GetStorage+0x15
02e6e954 23f0b123 pluginui!GetUiHelper+0xac67
02e6e98c 23f0b6bf pluginui!GetUiHelper+0x920b
02e6e9d8 23f104f4 pluginui!GetUiHelper+0x97a7
02e6ead8 23f10157 pluginui!RegisterEvents+0x28b8
02e6eb24 23f10832 pluginui!RegisterEvents+0x251b
02e6eb5c 23f071f5 pluginui!RegisterEvents+0x2bf6
02e6ebac 23f05add pluginui!GetUiHelper+0x52dd
02e6ec44 23f06932 pluginui!GetUiHelper+0x3bc5
02e6ecb0 23f12935 pluginui!GetUiHelper+0x4a1a
02e6ece0 206078e1 pluginui!RegisterEvents+0x4cf9
02e6ed1c 206079fe ieaddon!DllGetClassObject+0xcc9
02e6ed40 20607190 ieaddon!DllGetClassObject+0xde6
02e6ed7c 20606ea7 ieaddon!DllGetClassObject+0x578
02e6eea8 6de87683 ieaddon!DllGetClassObject+0x28f
02e6eedc 6decbe76 ieframe!EnumInvokeCallback+0x3c
02e6ef00 6decbdfb ieframe!EnumConnectionPointSinks+0x6c
02e6ef4c 6decd3f8 ieframe!IConnectionPoint_InvokeIndirect+0x81
02e6ef8c 6decd480 ieframe!IConnectionPoint_InvokeWithCancel+0x3a
02e6f064 6de1e0a1 ieframe!DoInvokeParamHelper+0x8b
02e6f0bc 6de7e92b ieframe!FireEvent_DocumentComplete+0xc3
02e6f0dc 6de7e892 ieframe!CBaseBrowser2::_FireDocumentComplete+0x46
02e6f104 6c7c716d ieframe!CBaseBrowser2::FireDocumentComplete+0x5d
02e6f144 6c7c6cb6 mshtml!CWebOCEvents::DocumentComplete+0x112
02e6f1ac 6c7c6aaf mshtml!CMarkup::OnLoadStatusDone+0x233
02e6f1cc 6c7c6fad mshtml!CMarkup::OnLoadStatus+0x47
02e6f620 6c754fab mshtml!CProgSink::DoUpdate+0x549
02e6f630 6c7f94b2 mshtml!CProgSink::OnMethodCall+0x12
02e6f664 6c7e37f7 mshtml!GlobalWndOnMethodCall+0xff
02e6f684 75496238 mshtml!GlobalWndProc+0x10c
02e6f6b0 754968ea user32!InternalCallWinProc+0x23
02e6f728 75497d31 user32!UserCallWinProcCheckWow+0x109
02e6f788 75497dfa user32!DispatchMessageWorker+0x3bc
02e6f798 6dea04a6 user32!DispatchMessageW+0xf
02e6f810 6deb0446 ieframe!CTabWindow::_TabWindowThreadProc+0x452
02e6f8c8 75b849bd ieframe!LCIETab_ThreadProc+0x2c1
02e6f8d8 75753677 iertutil!CIsoScope::RegisterThread+0xab
02e6f8e4 77069d72 kernel32!BaseThreadInitThunk+0xe
02e6f924 77069d45 ntdll!__RtlUserThreadStart+0x70
02e6f93c 00000000 ntdll!_RtlUserThreadStart+0x1b

   MAP-файл удалось найти только для storage.dll. Соответственно и отладочные символы в понятном для windbg формате удалось получить только для него.

   Но т.к. данная критическая секция (как нетрудно догадаться, принадлежащая объекту TThreadList) оказалась захвачена другим потоком, то найденный выше поток перешел в режим ожидания (пока критическая секция не будет разблокирована). Далее выясняем, какой поток владеет этой критической секцией (первый параметр RtlEnterCriticalSection - это адрес критической секции):

0:004> kv
ChildEBP RetAddr  Args to Child              
02e6e754 77068c64 00002be0 00000000 00000000 ntdll!NtWaitForSingleObject+0x15 (FPO: [3,0,0])
02e6e7b8 77068b48 00000000 00000000 07523688 ntdll!RtlpWaitOnCriticalSection+0x13e (FPO: [Non-Fpo])
02e6e7e0 20031fe0 07523690 00000000 23e0cb2c ntdll!RtlEnterCriticalSection+0x150 (FPO: [Non-Fpo])
02e6e820 23e089f4 02e6e8c4 08b14504 02e6e8c4 rtl100!Classes.TThreadList.LockList+0xc
...

0:004> !cs 07523690
-----------------------------------------
Critical section   = 0x07523690 (+0x7523690)
DebugInfo          = 0x0c9eecd8
LOCKED
LockCount          = 0x1
WaiterWoken        = No
OwningThread       = 0x000017b0
RecursionCount     = 0x1
LockSemaphore      = 0x2BE0
SpinCount          = 0x00000000

   Итак, критическая секция захвачена потоком с ID = 0x17b0. Полюбопытствуем, чем это он занят:

0:020> k
ChildEBP RetAddr  
0709eea8 76bf2c50 ntdll!ZwDelayExecution+0x15
0709ef10 76bf3520 KERNELBASE!SleepEx+0x65
0709ef20 60908e9e KERNELBASE!Sleep+0xf
WARNING: Stack unwind information not available. Following frames may be wrong.
0709ef50 60903651 sqlite3!sqlite3_win32_mbcs_to_utf8+0x100a
0709ef70 6094fc3c sqlite3!sqlite3_db_status+0x2339
0709efa0 2201ce2a sqlite3!sqlite3_sleep+0x34
0709efd8 6090f84e libkernel!ActivateEx+0x1f32
0709eff8 6091064b sqlite3!sqlite3_enable_shared_cache+0x1246
0709f038 609103c8 sqlite3!sqlite3_enable_shared_cache+0x2043
0709f068 609111f5 sqlite3!sqlite3_enable_shared_cache+0x1dc0
0709f0a8 609112d6 sqlite3!sqlite3_enable_shared_cache+0x2bed
0709f0f8 60938cfa sqlite3!sqlite3_enable_shared_cache+0x2cce
0709f1b8 60938ff3 sqlite3!sqlite3_reset_auto_extension+0x2cd2
0709f1f8 6093909c sqlite3!sqlite3_reset_auto_extension+0x2fcb
0709f228 6092c248 sqlite3!sqlite3_reset_auto_extension+0x3074
0709f278 6094ab03 sqlite3!sqlite3_set_authorizer+0x1168
0709f2f8 6094c2c4 sqlite3!sqlite3_declare_vtab+0x7b7b
0709f348 6094d1f5 sqlite3!sqlite3_declare_vtab+0x933c
0709f3a8 609393a0 sqlite3!sqlite3_declare_vtab+0xa26d
0709f5f8 609396bd sqlite3!sqlite3_reset_auto_extension+0x3378
0709f638 609397c3 sqlite3!sqlite3_reset_auto_extension+0x3695
0709f668 2201c801 sqlite3!sqlite3_prepare_v2+0x1f
0709f6a8 2201e93d libkernel!ActivateEx+0x2dc1
0709f6f0 2201dafb libkernel!RegisterHandlers+0x1b45
0709f724 2201fbd5 libkernel!RegisterHandlers+0xd03
0709f7ac 22020284 libkernel!RegisterHandlers+0x2ddd
0709f7d0 23e0cbc1 libkernel!RegisterHandlers+0x348c
0709f81c 23e089f4 storage!uStorage.TDatabaseManager.CreateStorage+0xc5
0709f838 23e08a32 storage!uStorage.TStorageHelper.CreateStorage+0x20
0709f864 23e0a759 storage!uStorage.TStorageHelper.CreateStorage+0x36
0709f8f0 23f09e71 storage!uStorage.TStorageManager.GetStorage+0x15
0709f93c 22014aea pluginui!GetUiHelper+0x7f59
0709f96c 22014253 libkernel!GetVersionInfo+0xed66
0709f990 2201405d libkernel!ActivateEx+0x1a8b
0709f9dc 2201393f libkernel!ActivateEx+0x1895
0709f9fc 2000794a libkernel!ActivateEx+0x1177
0709fa10 75753677 rtl100!System.ThreadWrapper+0x2a
0709fa1c 77069d72 kernel32!BaseThreadInitThunk+0xe
0709fa5c 77069d45 ntdll!__RtlUserThreadStart+0x70
0709fa74 00000000 ntdll!_RtlUserThreadStart+0x1b

   Ага! А вот и "корень зла" - этот поток "залип" при попытке выполнения sql-запроса к базе SQLite (sqlite3_prepare_v2). А т.к. на первый взгляд никаких проблем с базой не было (никаких следов ошибок или аномалий ни в дампе, и ни логах не обнаружено), то есть повод внимательно пересмотреть работу с базой данных в плане поиска проблемных мест.

   Еще из дампа можно выснить, какой sql-запрос пытался выполнить зависший поток (а вдруг это поможет в поисках истины). Для этого сначала посторим на заголовок функции sqlite3_prepare_v2:

int sqlite3_prepare_v2(
  sqlite3 *db,            /* Database handle */
  const char *zSql,       /* SQL statement, UTF-8 encoded */
  int nByte,              /* Maximum length of zSql in bytes. */
  sqlite3_stmt **ppStmt,  /* OUT: Statement handle */
  const char **pzTail     /* OUT: Pointer to unused portion of zSql */
);

   Соглашение вызова для sqlite3_prepare_v2 - cdecl. Значит параметры ей передаются через стек справа налево (как и для stdcall). Нас интересует второй параметр этой функции - его мы можем взять из вывода команды kv.

0:020> kv
...
ChildEBP RetAddr  Args to Child  
0709f638 609397c3 0c270670 05b87408 ffffffff soksqlite3!sqlite3_reset_auto_extension+0x3695
0709f668 2201c801 0c270670 05b87408 ffffffff soksqlite3!sqlite3_prepare_v2+0x1f
0709f6a8 2201e93d 0709f6dc 0709f6e0 0709f6c4 libkernel!ActivateEx+0x2dc1
...

   А вот и дамп sql-запроса:

0:020> da /c 50 05b87408
05b87408  "create table if not exists Storage (id integer primary key, parent_id integer, s"
05b87458  "ection varchar(150) not null, key varchar(150) not null, value blob, unique (sec"
05b874a8  "tion, key))"

Ссылки
[1] Как создать дамп процесса