История о том, как поток заблокировал самого себя

   Интересный случай однажды встретился мне - поток заблокировал самого себя, а вместе с тем и подвесил все приложение. Случай скорее из области экзотики, но тем не менее, при его расследовании я узнал много нового, так что есть в нем определенный академический интерес.

   Но обо всем по-порядку...


   Действующие лица

1.  Многопоточное приложение (написанное на Delphi 2007)
2.  Exception hooking routines из Project JEDI Code Library (JCL)
3.  Ошибка, возникающая в условиях многопоточности

   Изначальная диспозиция: имеем, в определенных условиях, зависание приложения (действующее лицо №1) при его закрытии. Это не есть хорошо, поэтому снимаем с него дамп и начинаем его ковырять анализировать.

   Вырисовывается следующая картина:

• Главный поток (порядковый номер в дампе #0) ждет завершения потока #61 с обработкой сообщений (MsgWaitForMultipleObjects)
• Поток #61 заблокирован при попытке захватить критическую секцию, которой владеет #66
• Поток #66 застрял в каком-то цикле, где периодически вызывается Sleep

   Начнем детальный разбор полетов. Главный поток оставим в покое, т.к. он честно пытается дождаться корректного завершения другого потока.

   Посмотрим повнимательнее на #61 - а в нем произошло исключение (AV) и системный обработчик передал управление процедуре HookedExceptObjProc (из модуля JclHookExcept). Та, в свою очередь, вызвала DoExceptNotify.

   Логика работы DoExceptNotify простая - оповестить все заинтересованные стороны (заявившие о своей заинтересованности путем вызова JclAddExceptNotifier, который добавляет обратную процедуру вызова в список Notifiers: TThreadList) о возникшем исключении. Для этого сначала захватывается критическая секция, защищающая доступ к списку Notifiers в условиях многопоточности. А после захвата по очереди вызывается калбеки из списке Notifiers.

   Поток #61 как раз заблокирован при попытке захвата критической секции, защищающей список Notifiers:

ntdll.dll!RtlEnterCriticalSection
rtl100.bpl!Classes.TThreadList.LockList
applicatiion.exe!JclHookExcept.DoExceptNotify
applicatiion.exe!JclHookExcept.HookedExceptObjProc
rtl100.bpl!System.HandleAnyException
ntdll.dll!ExecuteHandler
ntdll.dll!KiUserExceptionDispatcher
...

   К слову сказать, приложению перед зависанием видать очень сильно "поплохело" - возникло сразу несколько исключений Access violation в разных потоках. Кроме #61 еще один поток был заблокирован при попытке захватить блокировку списка Notifiers.

   Теперь переходим ко второй части марлезонского балета - изучению потока #66. По стеку видно, что он пытается захватить спин-блокировку делфевой кучи для того, чтобы освободить память:

kernel32.dll!Sleep(AdditionalSleepTime)
rtl100.bpl!System.SysFreeMem
rtl100.bpl!System.FreeMem
...

   Дефолтный менеджер Delphi в многопоточном приложении (IsMultiThread=True) защищает свою кучу с помощью спин-блокировок (LockCmpxchg, Sleep).

   Итак, выяснилось, что поток #66 ждет освобождения кучи, чтобы освободить память. Теперь для окончательного прояснения ситуации остается определить, кто и при каких обстоятельствах заблокировал кучу?

   Более детальный анализ стека #66 показал, что в нем произошло два исключения: сначала возникло одно, а при его обработке - второе. Рассмотрим их подробнее.

   Ниже приведен стек потока в момент возникновения второго исключения

rtl100.bpl!System.SysGetMem
applicatiion.exe!JclFileUtils.TJclFileVersionInfo.Create
applicatiion.exe!uExceptionLog.SaveException
applicatiion.exe!JclHookExcept.TNotifierItem.DoNotify
applicatiion.exe!JclHookExcept.DoExceptNotify
applicatiion.exe!JclHookExcept.HookedExceptObjProc
rtl100.bpl!System.HandleAnyException
ntdll.dll!ExecuteHandler
ntdll.dll!KiUserExceptionDispatcher
...

   Как видим, при возникновении первого исключения системный обработчик передал управление процедуре HookedExceptObjProc. Захватив блокировку списка Notifiers, был вызван калбэк одного из зарегистрированных обработчиков (TNotifierItem.DoNotify -> uExceptionLog.SaveException). Также видно, что исключение возникло в конструкторе класса TJclFileVersionInfo, а именно - на выделении памяти под новый экземпляр.

   Посмотрим на код SaveException из модуля uExceptionLog (не полный, а только ключевые моменты). Ее цель - сохранить информацию о возникшем исключении в лог-файл.

procedure SaveException(EMessage: AnsiString; const SystemInfo: TExcDialogSystemInfos);
var
  list, buffer: TStringList;
  j: Integer;
  ModuleName: TFileName;
  NtHeaders: PImageNtHeaders;
  ModuleBase: Cardinal;
  ImageBase  DWORD;
  verBinary, verFile: AnsiString;
begin
  list := TStringList.Create;
  buffer := TStringList.Create;
  try
    ...
    if (siModuleList in SystemInfo) and LoadedModulesList(list, GetCurrentProcessId) then
      begin
        buffer.Add('');
        list.CustomSort(SortModulesList);
        for j := 0 to list.Count - 1 do
          begin
            ModuleName := list[j];
            ModuleBase := Cardinal(list.Objects[j]);

            NtHeaders := PeMapImgNtHeaders(Pointer(ModuleBase));
            if (NtHeaders <> nil) and (NtHeaders^.OptionalHeader.ImageBase <> ModuleBase) then
              ImageBase := NtHeaders^.OptionalHeader.ImageBase
            else
              ImageBase := 0;

            if VersionResourceAvailable(ModuleName) then
              with TJclFileVersionInfo.Create(ModuleName) do 
                try
                  verBinary := BinFileVersion;
                  verFile := FileVersion;
                finally
                  Free;
                end
            else
              begin
                verBinary := '';
                verFile := '';
              end;
            
            //
            // Format ModuleBase, ImageBase, ModuleName, verBinary, verFile
            //
            buffer.Add('...');
          end;

        buffer.Add('');
      end;
    ...
  finally
    list.Free;
    buffer.Free;
  end;
end;

   И на "окончательный" стек зависшего потока:

kernel32.dll!Sleep(AdditionalSleepTime)
rtl100.bpl!System.SysFreeMem
rtl100.bpl!System.FreeMem
rtl100.bpl!System.LStrClr
rtl100.bpl!System.FinalizeArray
rtl100.bpl!System.FinalizeRecord
rtl100.bpl!System.FinalizeArray
rtl100.bpl!Classes.TStringList.Destroy
rtl100.bpl!System.TObject.Free
ntdll.dll!ExecuteHandler2
ntdll.dll!ExecuteHandler
rtl100.bpl!System.HandleFinally
applicatiion.exe!uExceptionLog.SaveException
applicatiion.exe!JclHookExcept.TNotifierItem.DoNotify
applicatiion.exe!JclHookExcept.DoExceptNotify
applicatiion.exe!JclHookExcept.HookedExceptObjProc
rtl100.bpl!System.HandleAnyException
ntdll.dll!ExecuteHandler
ntdll.dll!KiUserExceptionDispatcher
...

   Подведем итоги. Очевидно хронология событий была такой:

1.  В работающем потоке возникает исключение Access violation.
2.  Управление получает процедура DoExceptNotify, которая, захватив блокировку списка Notifiers, по очереди вызывает зарегистрированные обработчики. Т.о. образом управление попадает в SaveException.
3.  В самом начале SaveException создается 2 объекта TStringList. После чего начинается наполение их смыслом (различного рода информацией).
4. В какой-то момент, при выделении памяти во время создания экземпляра объекта TJclFileVersionInfo возникает еще одно исключение типа Access violation (по-видимому все оказалось очень плохо). Но т.к. исключительная ситуация возникла где-то в недрах SysGetMem, то очевидно, какая-то из спин-блокировок делфевой кучи (на самом деле их несколько) оказалась захваченной вследствие того, что выход из SysGetMem был досрочным и флаг блокировки не был сброшен.
5. Во время обработки нового (второго по счету для данного потока) исключения, при глобальной раскрутке стека, система вызывает обработчик finally в SaveException, в котором вызывается деструктор TStringList (см. п.3).
   

   ...
     finally
       list.Free;
       buffer.Free;
     end;
   ...
   

6. Но вследствие того, что флаг блокировки кучи не сброшен (п.4), поток не выйдет из деструктора - SysFreeMem не вернет управление, пока не освободит память. А сделать она этого не сможет, потому что в цикле пытается захватить блокировку, которую уже не кому освободить.
7. Поток заблокировал самого себя.