Как читать лог-файлы

Ну, пока я работал в поддержке EurekaLog, туда приходило немало вопросов, ответ на которые сводился, по сути, к тому, как правильно трактовать баг-отчёты. Аналогичные вопросы я встречал и на DK и на других форумах. Оказывается, у людей часто бывают трудности с пониманием того, что же, собственно, написано в отчётах. Хоть лично мне это и кажется удивительным, но, видимо, проблема всё же есть и требует решения.
Примечание: если вы плохо или совсем не понимаете, что такое указатели и/или объекты - рекомендую сначала прочитать эту статью.

Окей, давайте попробуем привести различные варианты отчётов и посмотреть, как их можно трактовать. Но прежде я в очередной раз напомню, что есть способы улучшить показания ваших лог файлов. И лучше бы вам сделать это до того, как к вам начнут поступать отчёты.

Стек вызовов

Центральное место в любом баг-отчёте занимает стек вызовов (call stack) – это последовательность адресов кода (часто с текстовым описанием), которые привели нас к моменту ошибки:

Call Stack Information:      
------------------------------------------------------------------------       
|Address |Module      |Unit        |Class |Procedure/Method      |Line |       
------------------------------------------------------------------------       
|*Exception Thread: ID=8820; Priority=0; Class=; [Main]                |       
|----------------------------------------------------------------------|       
|004D316F|Project8.exe|Unit9.pas   |TForm9|Button1Click          |33[3]|       
|76BD0AF5|user32.dll  |            |      |SendMessageW          |     |       
|76BB8C6B|user32.dll  |            |      |CallNextHookEx        |     |       
|76BD0051|user32.dll  |            |      |DispatchMessageW      |     |       
|004D499D|Project8.exe|Project8.dpr|      |                      |17[4]|       
|7691490F|kernel32.dll|            |      |BaseThreadInitThunk   |     |       
------------------------------------------------------------------------ 

Стек вызовов в EurekaLog (текстовый вид)

Стек вызовов в EurekaLog (вид в EurekaLog Viewer)

4CC5B7 [Unit15.pas][Unit15][Unit15.B][35]      
4CC5C4 [Unit15.pas][Unit15][Unit15.A][39]       
4CC5DC [Unit15.pas][Unit15][Unit15.TForm15.FormCreate][43]       
4C0CCB [Forms][Forms.TCustomForm.DoCreate]       
4C0913 [Forms][Forms.TCustomForm.AfterConstruction]       
4C08E8 [Forms][Forms.TCustomForm.Create]       
4CA539 [Forms][Forms.TApplication.CreateForm]       
4CD986 [Project14][Project14.Project14][14]       
75B94911 [BaseThreadInitThunk]       
770FE4B6

Стек вызовов в FastMM

(00087A8C){Project1.exe} [00488A8C] Unit1.B (Line 40, "Unit1.pas" + 1) + $5      
(00087ABC){Project1.exe} [00488ABC] Unit1.A (Line 44, "Unit1.pas" + 0) + $0       
(00055523){Project1.exe} [00456523] Controls.TWinControl.WndProc + $513       
(0003AA8C){Project1.exe} [0043BA8C] StdCtrls.TButtonControl.WndProc + $6C       
(00055673){Project1.exe} [00456673] Controls.DoControlMsg + $23       
(00055523){Project1.exe} [00456523] Controls.TWinControl.WndProc + $513       
(00068584){Project1.exe} [00469584] Forms.TCustomForm.WndProc + $594       
(00054C3C){Project1.exe} [00455C3C] Controls.TWinControl.MainWndProc + $2C       
(00025724){Project1.exe} [00426724] Classes.StdWndProc + $14       
(0005561F){Project1.exe} [0045661F] Controls.TWinControl.DefaultHandler + $D7       
(00055523){Project1.exe} [00456523] Controls.TWinControl.WndProc + $513       
(0003AA8C){Project1.exe} [0043BA8C] StdCtrls.TButtonControl.WndProc + $6C       
(00025724){Project1.exe} [00426724] Classes.StdWndProc + $14 

Стек вызовов в JCL

Стек вызовов в Delphi (View/Debug Windows/Call Stack)

Итак, как вы можете видеть, в какой бы утилите не был создан стек вызовов – он почти всегда содержит эквивалентные сведения (ну, в примерах выше приведены разные программы, так что не пытайтесь сравнивать эти стеки вызовов ;) ).

Во-первых, обычно первым элементом в строке идёт сам адрес кода. Это числа вида 00488ABC или 488ABC (с обрезанными нулями). В стиле Delphi это будет выглядеть как $00488ABC – т.е. указатель на место в памяти, а именно: на код. Вы можете использовать эти адреса и вручную (например, если другая информация отсутствует): запустите программу, вызовите меню Search/Goto address (программа должна стоять на паузе) и введите $00488ABC – и вы попадёте ровно в это место (при условии, что адрес не изменился при перезапуске программы).

Почти всегда рядом с адресом указывается имя исполняемого модуля, которому он принадлежит. Например, Project8.exe или user32.dll. По этому признаку можно быстро отделить “свой код” от системного. Впрочем, сам вид адреса зачастую говорит об этом. К примеру, exe практически всегда загружается по адресу $400000 – следовательно, адреса вида $488ABC (близкие к $400000) почти наверняка принадлежат нашей программе. А вот системные DLL обычно загружаются по верхним адресам. Так что адреса вида $75B94911 скорее всего принадлежат не нам. Промежуточные адреса (типа $58C3C0) обычно принадлежат сторонним DLL (нашим или не нашим, но не системным). Окей, это весьма грубое и не совсем точное описание – но это всего лишь введение для новичков, так что не придирайтесь ;)

Иногда вместе с адресами указывается смещение относительно начала исполняемого модуля или сегмента кода – например 87A8C для адреса 00488A8C в логе JCL ($00400000 + $1000 + $87A8C = $00488A8C). Такая информация не слишком часто нужна, но, если вы понимаете в этом, то включайте (выше приведён полный вывод, а вообще он настраиваемый) – лишним не будет. Тут также может пригодиться дополнительная информация в лог-файле: список модулей с дескриптором каждого.

Но достаточно про эти сухие цифры – уж их-то вы будете использовать редко :) Потому что при наличии отладочной информации, ассоциированной с этим адресом, рядом будет указана более дружественная информация. А именно: имя модуля (unit), класса, метода или функции и номер строки. Иногда часть информации может отсутствовать – это зависит от детальности самой информации. Мы уже обсуждали это здесь и здесь.

Собственно, эта информация говорит сама за себя: вот вам Delphi-вый модуль, вот вам метод и даже строка в нём, где возникла ошибка (для первой строки в стеке вызовов) или произошёл вызов подпрограммы (для всех остальных строк). Единственное, что требует комментария: номера строк. Часто вместе с абсолютными номерами строк (отсчёт от начала файла) указываются смещения в строках (и иногда даже в байтах) самой строки от начала процедуры, которой она принадлежит. Например, пусть у нас есть такой код:

procedure Test;
begin
  DoActions;
  DoActions2;
end;

Слева указывается обычная нумерация строк, как она есть в редакторе кода – абсолютная, от начала файла. Так вот, номера строк для DoActions2 может выглядеть как “48[2]” (стиль EurekaLog) или “Line 48, "Unit1.pas" + 1” (стиль JCL). Что следует читать как: это 48-я строка в файле или вторая строка в процедуре Test.

Зачем нужны эти относительные смещения? Ну, они чрезвычайно удобны при чтении стека вызовов, если ваши исходники поменялись. Например, вы добавили процедуру до процедуры Test. Сама процедура Test сместилась ниже на 27 строк. Понятно, что теперь строка 48 принадлежит совершенно другому коду. Однако, вы все ещё можете найти DoActions2, если вы посмотрите на имя процедуры в стеке вызовов (“Test”) и отсчитаете 2 строки от её начала.

Кстати, EurekaLog также умеет смотреть в папку __history (доступна только в новых версиях Delphi), чтобы извлечь оттуда наиболее подходящую версию исходника для просмотра (это происходит когда вы дважды щёлкаете по строке в стеке вызовов в EurekaLog Viewer).

Чтение стека вызовов

Вот несколько моментов, которые надо иметь ввиду, когда вы читаете стек вызовов.
Во-первых, в одном файле баг-отчёта может быть несколько отчётов об ошибках. Во-вторых, даже в одном отчёте может быть перечислено несколько стеков вызовов: по одному на каждый поток. Так что, прежде чем приступать к анализу стека, – убедитесь, что вы собрались читать нужный ;)

Как правило, все стеки вызова следует читать снизу-вверх: в самом низу находится процедура, которую вызвали первой. Выше – процедура, вызванная из стартовой, ещё выше – ещё один вложенный вызов и т.д., пока в самом верху вы не увидите текущее место. Часто это и будет именно место возникновения ошибки (но не всегда – см. ниже), а вся прочая часть стека вызовов показывает, как мы в это место пришли.

Первые (снизу) несколько процедур в стеке вызовов обычно являются системными или принадлежат RTL Delphi и, как правило, редко представляют интерес. Часто информация о них отображается лишь частично – ввиду отсутствия отладочной информации. Также иногда стек вызовов имеет ограничение в глубину, т.е. не может содержать более N элементов. В этом случае нижняя часть и вовсе обрезается.

С другой стороны, в верхней части стека вызовов кроме собственно места ошибки иногда могут идти упоминания и служебных процедур – это зависит от того, в каком месте (на какой стадии раскрутки) обнаруживается проблема и строится стек вызовов. К примеру, там могут упоминаться процедуры обработки исключений или вызовы GetMem и т.п.

Также некоторые утилиты специально добавляют в стек вызова адрес ошибки, если он доступен. Например, для исключения это будет адрес возникновения (т.е. адрес инструкции кода, возбудившей исключения). В этом случае, если стек вызовов уже содержал этот адрес в своём начале, то ничего и не происходит. В случае же, если в стек попали адреса каких-то служебных процедур, то адрес проблемы может дублироваться (указываться в стеке вызов два раза): в самом стеке и самой верхней строчкой.

Далее, надо также иметь ввиду способ, которым строится стек. Их два: по фреймам вызовов (frame-based) и raw-метод. Первый метод строит стек, опираясь на последовательность фреймов, которые добавляются в стек при большинстве вызовов процедур. Обычно этот метод даёт хорошие результаты, если только у вас нет большого числа коротких процедур – для них стековые фреймы, как правило, не создаются (хотя вы и можете это исправить, включая опцию “Stack Frames”). Благодаря тому, что метод смотрит только на информацию о реальных вызовах – он довольно точен и быстр, т.к. не смотрит всю информацию в стеке, а просто проходит по цепочке фреймов, каждый из которых ссылается на предыдущий.

Raw-метод работает иначе: он просто сканирует весь стек, пытаясь найти в нём адреса возврата. Действительно, создаётся или нет фрейм вызова – это вопрос. Но вот адрес возврата-то кладётся в стек всегда. Вот их-то и пытается найти raw-метод. Для этого он берёт каждое число в стеке и пытается определить: похоже это на адрес возврата или нет? Поэтому raw-метод применяется только в сочетании с некоторой эвристикой. В зависимости от качества этой эвристики, построенные стеки вызовов могут значительно отличаться. К примеру, можно смотреть на то, указывает ли значение на сегмент кода, есть ли для него отладочная информация и т.п.

К чему я вас этим гружу? Да к тому, что чтение стека вызова будет зависеть от того, каким методом он построен. И вам лучше бы знать это до того, как вы приступите к анализу отчётов.
Какая есть разница? Ну, по описанию можно и самому сообразить: frame-based метод может пропускать вызовы, если для них не создаются фреймы (как правило, это очень короткие процедуры) и вовсе застопориться, если хотя бы один фрейм был повреждён. С другой стороны, очевидно, что raw-метод во многом “агрессивнее” frame-based метода: уж он почти наверняка не пропустит вызов (если только он не отсёкся эвристикой), но может добавлять в стек вызовов лишние элементы – так называемые “ложные срабатывания”.

Поэтому, анализируя стек и видя странные вещи (“ну не может по моему коду эта процедура вызываться отсюда!”) – помните о методе, которым построен стек и либо предполагайте отсутствие метода в стеке (для frame-based), либо предполагайте лишнюю (ложную) запись (для raw). Особенно нужно помнить об этой разнице, если вы используете какой-либо метод получения стека вызова в самой программе – например, хотите получить имя вызывавшей вас процедуры. Не всегда (хотя и чаще всего) в стеке вызовов вызывающий будет следовать второй строкой.

EurekaLog версии 6 использует только raw-метод (поддержка frame-based планируется для версии 7). FastMM и JCL поддерживают оба метода, переключение между которыми осуществляется в опциях (последние версии по-умолчанию используют frame-based метод).

Поиск места ошибки

В основном тут хочется сказать такую вещь: ошибка не обязательно сидит в том месте, куда указывает стек вызова! Эту простую истину почему-то не понимает огромное количество народа.

Ну, например, у вас в программе есть один из этих проклятых багов порчи памяти: вы что-то делаете и попутно портите какую-то свою память. Код с багом может выполниться на ура, без ошибок. А ошибка возникнет много позже, при выполнении совершенно другого кода. У вас будет Access Violation, и стек вызовов будет указывать на совершенно невинный код.

Просто анализируйте ситуацию, чтобы не свалить всё на ни в чём не повинный код.

Более того, некоторые типы отчётов возможно получить именно не в момент ошибки. Речь, конечно же, идёт не об исключениях (уж их-то мы ловим сразу), а о проблемах с памятью (утечки и порча памяти). Например, очевидно, что менеджер памяти не может проверять весь пул памяти на корректность при каждой операции в программе: “а уж не собирается ли вот эта инструкция кода сейчас затереть нужную память?” Более того, это невозможно даже для выполнения только во время обращения к менеджеру памяти (т.е. к GetMem/FreeMem). Т.к. памяти выделяется много, управляющих структур ещё больше – и если сканировать их все при каждом обращении к менеджеру памяти, то производительность вашей программы упадёт до нуля.

Поэтому, менеджер памяти анализирует проблемы только по текущему контексту. Например, просим мы его освободить память: он проверит, уж не повреждён ли служебный заголовок у этого блока. Заметьте: только у этого, а не у всех. Далее, просим мы его выделить память: он пробегается по списку условно-свободных блоков и находит один. Прежде чем вернуть его вызывающему, менеджер памяти поверяет: а уж не писал ли кто чего в этот блок памяти, пока он был свободным?

Именно поэтому, обычно проблемы с памятью всплывают не в момент ошибки, а гораздо позже: когда испорченная память снова берётся в оборот.

Примеры? Ну, давайте посмотрим на FastMM (функциональность EurekaLog скромнее, поэтому с ней вы разберётесь по аналогии). Каждое сообщение FastMM начинается как “FastMM has detected an error during a ” – т.е. “FastMM обнаружил ошибку при ”. Далее указывается при какой же операции он нашёл ошибку: GetMem, FreeMem, ReallocMem или сканировании при поиске. Затем идёт собственно ошибка. Вот примеры ошибок:

• “The block header has been corrupted”
• “The block footer has been corrupted”
• “FastMM detected that a block has been modified after being freed”
• “An attempt has been made to free/reallocate an unallocated block”

Ну и другие, более редкие сообщения, типа вызова виртуального метода удалённого объекта. Смотрите: сообщения говорят о конкретных проблемах: FastMM обнаружил, что заголовок (header) или заглушка (footer) блока повреждены, запись в свободный блок или попытку повторного освобождения памяти. Ниоткуда не следует, что проблема произошла именно в этот момент! В текущий момент времени менеджер памяти просто обнаружил проблему. Сама проблема возникла ранее.

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

1. Вы выделили блок (FastMM покажет этот стек вызовов).
2. Вы освободили блок (FastMM покажет этот стек вызовов).
3. Какой-то код испортил память, ошибочно записывая в этот свободный блок.
4. Вы вызвали GetMem. В этот момент FastMM обнаруживает изменение в блоке и трубит тревогу (FastMM покажет этот стек вызовов).

В отчёте будет три (!) стека вызова для одной проблемы и ни один из них не будет представлять указание на проблему: проблема будет сидеть где-то между вторым и последним стеками вызовов.

Короче говоря: просто немного используйте свою голову (читайте сообщения, а не ломитесь проверять код по стекам вызовов) и всё будет отлично ;)

Как искать причину такой проблемы – об этом, в следующий раз.

Другая информация в отчёте

Помимо стека вызовов, в баг-отчёте есть ещё и другая информация, которая является вспомогательной. Из неё можно извлечь подсказки к поиску причины ошибки. Наиболее важными частями является информация о CPU и регистрах, а также дампы памяти. По ним зачастую можно определить состояние переменных в момент ошибки и другие полезные сведения. Конечно же, оперирование с этой информацией требует знания ассемблера, но это действительно мощный инструмент.

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

К сожалению, здесь действительно трудно дать какие-то общие рекомендации – практически к каждому случаю надо подходить индивидуально. Когда вы высказываете предположения, что же может происходить в программе, дополнительная информация в отчёте может помочь вам проверить эти предположения.

Ну, например, странный AV на, казалось бы, ровном месте при вызове функции. Посмотрев на поле версии ОС, вы увидите, что программа была запущена в Windows 2000, в которой вы её не проверяли. А копнув глубже, вы обнаружите, что проблема была в том, что используемая вами функция не существует в Windows 2000 (вы динамически импортировали функцию, не проверяя на ошибки).