Tuesday, June 17, 2014

Простой эффективный логгер на C++

Проект начинается с логгера

Хотя... некоторые проекты логгером и заканчиваются :-)

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

Есть еще одно заблуждение, что достаточно понатыкать в код что-то подобное: 
std::out << "message";
OutputDebugStr("message");

Почему это не катит? Потому что логгер это не только простой вывод сообщений куда-то, логгер должен решать множество задач.

Какие задачи решает логгер:

  • Фильтрация (какие сообщения показывать, а какие блокировать)
  • Форматирование (текстовое представления разнотипных данных)
  • Атрибутирование (добавление в лог маркеров, упрощающих анализ)
  • Буфферизация (накапливание фрагментов сообщения в для ускорения работы)
  • Вывод.



Фильтрация

Сообщения от разных подсистем приложения должны различаться и обрабатываться по-разному.

Для каждой подсистемы должен существовать свой *уровень логгирования*. Например, для менеджера памяти можно включить отображение только фатальных ошибок, а для пользовательского интерфейса - подробный список сообщений.

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

Должна быть предусмотрена возможность *статического* ограничения уровней логгирования при компиляции. Например, собирая production-код можно выключить все отладочные сообщения для некоторых подсистем, сократив размер программы. 

Форматирование

Должны поддерживаться пользовательские типы данных и пользовательское форматирование. 

Атрибутирование

Для упрощения анализа логгер должен маркировать сообщения 
  • именем подсистемы
  • уровнем логгирования
  • идентификатором приложения
  • треда
  • датой и временем.

Например: 01:10:55 [0x009033004] Appl1 [MEMORY] [i] text

Буфферизация

Логгер может буфферизовать сообщения, хотя это и не всегда желательно.

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

Вывод

Логгер должен выводить сформатированные строки через пользовательскую функцию.

Логгер имеет право полагаться на то, что эта функция потокобезопасна.

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

Общие требования

Логгер не должен обращаться к другим частям приложения, например к менеджеру памяти.

Логгер должен быть потокобезопасным.

Логгер не обязан быть сильно оптимизированным. Функция финального вывода сообщения в файл/сокет/консоль работает на порядки медленнее всех остальных функций логгера, поэтому их оптимизация не ускорит логгер.

Логгер должен быть доступен всегда. Лучше вообще не использовать в логгере синглтоны. Но если уж приперло использовать функцию вывода с состоянием - используйте синглтон «Феникс». 

Место логгера в архитектуре приложения

Любая часть приложения имеет право вывести в лог что угодно и в любой момент времени.

Следовательно логгер не должен полагаться на какие-либо службы приложения и по возможности вообще не должен к ним обращаться. Нельзя даже new/delete.
Поэтому логгер - штука базовая :-).

Реализация на C++

Download logger.zip 


Ключевые фичи логгера:

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


Пример использования: 

//
// вывод сообщения от имени подсистемы memory на уровне info
//
Log::memory::info("Address of AppObject = ", appPtr);
 
//
// динамическая смена уровня логгирования для подсистемы memory
//
Log::memory::level = Log::lv_Verbose;
 
//
// вывод разнотипной информации: подсистема exec, уровень verbose
//
int x = 1234567, y = -1230123;
Log::exec::verbose("x=", x, " y=", y);
 
//
// проверка на включенность уровня
//
if (Log::memory::verbose::on()) {
   scan_memory();
}

Все определения логгера помещены в namespace Log.

Финальный вывод

Для финального вывода строк объявлена функция Log::out(const str*), которую должен определить клиент. Логгер полагается на то, что она потокобезопасна.

Буферизация

Для буфферизации вывода существует шаблонный класс buf_stream<size_t buf_size>.

Вывод каждого сообщения сопровождается созданием временного объекта этого класса на стеке. Таким образом, каждое сообщение формируется в своем буфере, и потоки при совместном выводе сообщений не разрывают сообщения друг друга.

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

Существует отдельная специализация для случая buf_size=0. При этом из приложения выбрасывается весь код буфферизации и весь вывод идет напрямую в пользовательскую функцию. Это позволяет уменьшить размер программы, получить более надежные логи в которых при падении приложения не теряются последние выведенные части сообщений. Правда, за это придется заплатить существенным замедлением работы, поскольку вызов процедуры финального вывода будет происходить значительно чаще. Также при наличии нескольких тредов, повышается вероятность перемешивания их сообщений.

Атрибутирование

Выполняется в две стадии: 
  • Все операторы вывода в лог автоматически добавляют название подсистемы и уровень логгирования.
  • В конструкторе buf_stream можно добавить вывод времени, идентификатора треда и приложения.

Форматирование

Форматирование вывода осуществляется набором операторов 
stream & operator<< (stream& & s, const TYPE & val);

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

Предопределены два оператора – для вывода десятичных знаковых чисел и для вывода шестнадцатиричных чисел. Для ускорения работы они написаны с нуля и не используют библиотечные функции.

Для вывода пользоватлеьских типов данных можно определить собственные операторы << в манере iostream. Например: 
struct Point
{
   int x, y;
};
namespace Log
{
   stream &operator<< (stream& s, const Point &val)
   {
      return s << "Point {x=" << val.x << ", y=" << val.y << "}";
   }
}
//...
   Point myPoint;
   Log::exec::verbose("p=", myPoint);

Фильтрация

В логгере поддерживаются четыре уровня сообщений: 
  • lv_Verbose – подробные сообщения о нормальном ходе исполнения,
  • lv_Info – короткие сообщения о нормальном ходе исполнения,
  • lv_Warning – нефатальные ошибки и предупреждения,
  • lv_Fatal – фатальные ошибки, которые могут привести к краху,

Каждая подсистема может находиться в одном из пяти уровней: четыре преечисленные и lv_None, когда запрещены все сообщения.

Уровень логгирования для каждой системы может изменяться через переменную Log::имя_подсистемы::level 

Для добавления новой подсистемы достаточно добавить идентификатор в перечисление, продекларировать ее и задать префикс, который будет печататься перед сообщениями: 
enum
{
    s_memory,
    s_gc,
    s_exec,
    s_myNewSubSystem, //< новый идентификатор
};
 
// новая подсистема
typedef Logger<s_myNewSubSystem, lv_Info>   myNewSubSystem;
 
// ее префикс в логе
template<> const char * const myNewSubSystem::name   = "[myNewSubSystem]";

После этого ее можно использовать 
Log::myNewSubSystem::fatal("Message");

При декларации подсистемы второй параметр шаблона Logger задает статически разрешенный уровень логгирования. При этом все сообщения ниже этого уровня будут исключены на этапе компиляции. По умолчанию желательно устанавливать уровень lv_default, который изначально равен lv_Info. Тогда изменяя значение константы lv_default можно будет централизованно менять уровень логгирования у всех подсистем.

Кроме вывода сообщения, на любом уровне можно проверить assertion
void MyFunction(void * ptr)
{
    Log::memory::info::check(ptr == NULL, "MyFunction - bad parameter");
    ...
}

В данном примере происходит проверка условия, и при ptr==NULL программа завершится c выводом сообщения.
Posted by at
Labels:

No comments:

Post a Comment

Subscribe to: Post Comments (Atom)