Способы отладки приложений: Протоколирование

Дмитрий Долгов
Родился в 1973 году. Окончил Санкт-Петербургский Государственный Технический Университет (бывший Политехнический Институт) по специальности "Прикладная математика". Более 8 лет проработал в CREAT Studio, где до недавнего времени занимал пост главного программиста и начальника отдела программирования. Участвовал в выпуске игр для PC, Playstation 2, Xbox и Dreamcast. В настоящее время работает в отделе игровых и мультимедийных продуктов фирмы "1С".

Способы отладки приложений: вводная часть >>

Эта статья продолжает цикл, посвященный способам отладки приложений. Кратко все основные методы были рассмотрены в предыдущей статье, здесь же мы подробно остановимся на одном способе - отладке при помощи протоколирования.

Этот способ является одним из основных для выявления ошибок в том случае, если ваше приложение (или разработанная вами библиотека) запускается на удаленном компьютере. Например, у конечного пользователя или у программистов компании-заказчика. К сожалению, не все программисты относятся к протоколированию работы системы с должным вниманием, что зачастую приводит к трудноразрешимым проблемам после сдачи работ.

Разрабатываем систему протоколирования

В простейшем варианте протоколирование приложения может выглядеть следующим образом:

FILE *log_stream = fopen("mylog.txt", "wt");
...
fprintf(log_stream, "Resource file %s loaded", res_name);
...
fprintf(log_stream, "Loading level %s", map_name);
...

Но это - как самый простой, так и самый неудобный вариант. Давайте рассмотрим, как следует организовывать ведение протокола, и какую информацию необходимо в нем сохранять?

Пару лет назад мне пришлось столкнуться со следующим кодом, написанным прямо в дебрях графического движка:

FILE *log_stream = fopen("D:\\texture.log", "wt");

for (int i=0; i< texture_list.size(); i++) 
    fprintf(log_stream, "Texture loaded: %s\n", texture_list[i].name());

За организацию такого, с позволения сказать, "протокола" должен устраиваться показательно-массовый расстрел. Во-первых, нет никакой гарантии, что диск D: существует, и что нужный файл может быть открыт для записи. Во-вторых, приложение создает (в том числе и в финальной конфигурации!) файл в совершенно левом месте с кучей ненужной отладочной информации.

Чтобы такого не происходило, протоколирование должно вестись по жестким законам, общим для всех частей приложения. Каждая библиотека имеет право создавать диагностические сообщения, но работа с сообщениями должна проводиться централизованно и организованно, чтобы исключить появление "левых" файлов в произвольных подкаталогах, различных отладочных messagebox и неокаймленных в релиз конфигурации директив asm int 3.

Какие данные потребуются для централизованной обработки сообщений:

• Текстовое сообщение о произошедшем событии. Очевидно.
• Приоритет сообщения ("ошибка", "предупреждение" или что-то еще). Крайне желательно. Подробнее - см. ниже.
• Имя файла и номер строки. Желательно. Теоретически, необходимую строчку можно найти в программе, но нет никакой гарантии, что a) из-за подстановок дополнительных аргументов строчка выглядит именно так, как мы ее ищем; b) строчка с таким текстом только одна на весь проект.
• Время наступления события. Желательно. В интерактивных приложениях анализ содержимого протокола может дать много ценной информации, если проанализировать время наступления того или иного события. Формат задания времени - на ваш выбор (это может быть как текущее системное время, так и время с момента запуска приложения), но рекомендуемая гранулярность - не менее 1 миллисекунды.
• Идентификатор библиотеки, которая инициировала сообщение или идентификатор программиста, написавшего это сообщение. Желательно. Подробности будут рассмотрены ниже.
• Порядковый номер сообщения. Иногда оказывается полезным.

Теперь более подробно рассмотрим некоторые пункты.

Приоритет сообщения или уровень протоколирования

При разработке своей системы протокола можно ориентироваться на уже существующие примеры. Как вариант, проанализируем сообщения, которые выводятся при компиляции исходных файлов в Microsoft Visual Studio - тут можно выделить 3 уровня сообщений:

1. Информационные сообщения о ходе работы компилятора ("compiling file xxx.cpp", "Done, 0 errors, 0 warnings", …).
2. Сообщения-предупреждения (Warnings). Не являются критичными для компиляции приложения, но на них стоит обратить внимание.
3. Сообщения об ошибках (Errors). Обязательны к исправлению перед продолжением компиляции проекта.

Таким образом, в системе протоколирования можно выделить как минимум 3 основных типа сообщений: Notice, Warning, Error. Такая система используется во многих компаниях, но, как правило, оказывается не совсем удобной. Чем больше программистов в компании и чем более часто используется протоколирование, тем больше сообщений попадает в протокол, и в итоге нужные сообщения оказываются "забиты" шумом. Отключите в Visual Studio режимы "Suppress Startup Banner", "Show all progress", установите "Warning Level: 4" и попробуйте найти среди кучи мусора информативные сообщения об ошибке.

Чтобы правильно оценить требуемое количество уровней протоколирования, обратимся к описанию механизма syslogd операционной системы UNIX. В руководстве описываются следующие приоритеты сообщений (syslog (3) man page):

Priority	Description
Debug	Normally used for debugging
Info	Informational messages
Notice	Conditions that may require attention
Warning	Any warnings
Err	Any errors
Crit	Critical conditions like hardware problems
Alert	Any condition that demand immediate attention
Emerg	Any emergency condition

Попробуем перевести эти приоритеты в систему сообщений для игрового приложения. Рассмотренные выше информационные сообщения, предупреждения и ошибки попадают в классификацию Notice, Warning, Err. Остальные приоритеты могут использоваться в следующих целях:

Priority	Description
Debug	Отладочные сообщения. Могут использоваться для глубокой отладки приложения или его отдельных компонент. Debug: Player position changed to 34.23; 0.08; 18.96
Info	Отладочные сообщения. Также используются для отладки приложения или его отдельных компонент. Info: Player CDT with mesh "Object1"
Notice	Информационные сообщения. Информируют о серьезных событиях в ходе игры (завершена инициализация подсистем, начата загрузка уровня, игрок убит и т.д.). Notice: Loading level "Level1.map"...
Warning	Предупреждение. Может использоваться в том случае, если обнаружено некое несоответствие ожидаемому поведению игры. Warning: Player position outside scene bounding box
Err	Сообщение об ошибке. Текущая функция не может быть выполнена правильно, хотя общий процесс игры не прерывается (восстановимая ошибка). Err: Can't load sound file "attack.wav". Windows error 2.
Crit	Сообщение о критической ошибке. Какие-то компоненты приложения могут перестать функционировать. Crit: Can't detect compatible sound card. All sounds will be disabled.
Alert	Сообщение о невосстановимой ошибке. Приложение детектировало некорректную ситуацию, которая c большой долей вероятности может привести к фатальной остановке программы. Alert: Allocation failed. Not enough memory.
Emerg	Фатальное сообщение об ошибке. Как правило, используется в обработчиках Unhandled exceptions и в других случаях, когда приложение оказывается "за гранью" фатальной остановки. Emerg: Unhanded Exception. Code 0xC0000005 (access violation). Address:

Приведенная схема не является единственно возможной. Например, уровни Debug и Info, а также Alert и Emerg можно объединить вместе. Можно, наоборот, более подробно расписать условия для каждого из приоритетов и разбить предложенную схему еще на несколько уровней.

В протоколе также рекомендуется сохранять (если это возможно), сообщения assert и сообщения от менеджера памяти о найденных ошибках. В зависимости от идеологии использования assert в той или иной компании, событие assert может создавать сообщение для протокола с приоритетом от Warning до Alert. Сообщения от менеджера памяти (порча памяти, нехватка памяти и т.п.) могут идти с приоритетом Crit или Alert.

В штатном режиме работы сообщения приоритета Warning и более серьезные не должны происходить вообще. Сообщения класса Notice рекомендуется создавать таким образом, чтобы они происходили не чаще, чем 1 раз в несколько секунд. Сообщения приоритета Info и Debug должны отсекаться и не сохраняться в файл.

При таком режиме работы файл протокола растет с небольшой скоростью и практически не влияет на быстродействие программы. Тем не менее, по файлу протокола можно достаточно точно определить примерное состояние игры.

Type	Time (ms)	Message
Notice:	23	Game started, build version 1.01.0562
Warn:	167	Windows sound options set to 'Mute'.
Notice:	1983	Main resource file loaded, file version: 1.01.0554
Notice:	2351	Initialization complete.
Notice:	2352	Loading main menu.
Notice:	8092	Player selected: "Dima".
Warn:	8095	Can't load sound file 'res\sounds\NextMenuItem.wav'
Notice:	12361	Loading level "Tutorial.map".
Err:	14388	Can't find file "tutorial.mpg"
Notice:	14400	"Tutorial.map": loading complete.
Notice:	21082	Game paused by player
Alert:	22014	heapchk() return code: _HEAPBAD (-4)
Emerg:	22015	Unhandled exception. Access violation.

Идентификатор библиотеки

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

• Имя файла, в котором записано сообщение (__FILE__). Не всегда удобно - многие библиотеки состоят из нескольких cpp и header файлов. Кроме этого, если в различных частях проекта присутствуют файлы с одинаковыми именами, могут возникнуть конфликты.
• Имя (ник) программиста, который отвечает за эту библиотеку. Очень удобно делать фильтр и просматривать только свои собственные сообщения, но когда количество программистов приближается к десяти, наступает коллапс. Он может возникнуть и раньше, если над одной частью программы будут работать одновременно двое программистов (или если один из них передал свои дела другому).
• Идентификатор библиотеки. Наиболее универсальный и удобный способ идентификации. В качестве идентификатора может использоваться простая текстовая строчка или что-либо еще.