Воскрешение логов из дампа памяти (core dump)

Вся заметка про специфику под *nix подобными операционками. Но идея вобщем будет такой же и под Windows - инструментарий другой.

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

Конечно можно воткнуть обработчик сигналов(signal handler) и прикрутив его попробовать форсировать сброс буфера(если логгер в принципе имеет такую возможность) на диск перед смертью программы. Проблема в том что если уже случилось что-то ужасное мы уже не можем быть уверены что логгер находится в рабочем состоянии на момент как мы получили сигнал и попали в обработчик.

Если при этом у вас многопоточное приложение вам придётся пробежаться по всем потокам(кроме одного который и обрабатывает сигналы) чтобы заблокировать в них обработку сигналов в старом добром C стиле (ну я по крайней мере не видел аналога для pthread_sigmask даже в стандарте C++11). Да и для C++11 политика "не пишите поточных async'ов не заблокировав им сигналы" мягко говоря вряд ли будет популярной особенно если вы используете std::async с std::launch::async | std::launch::deferred и не знаете будет тут отдельный поток или нет. И если какой-нибудь поток пропустим и в итоге обработчик сигнала вызовется хрен знает в каком потоке и в худшем для нас случае(например если вы используете сторонний асинхронный логгер и вообще не можете контролировать создание им потока - то и заблокировать сигналы для него скорее всего не сможете) он вызовется в том же потоке что и логгер в момент когда логгер сделал lock перед записью - так что если мы в обработчике вызовем flush для логгера, то получим deadlock в большинстве логгеров(теоретически рекурсивный mutex тут поможет, но во первых не факт что он безопасен в случае async signal, да и нам это не поможет если логгер в виде сторонней либы). Вобщем чтобы не уползти в обсуждение сигналов страниц на 5, примем за аксиому  - обработчик сигналов должен быть простым и тупым, например записать бэктрейс в stderr и умереть.

Т.е. всё просто, если уж нам суждено умереть от чего-то ужасного(segfault и тп) - умираем не пытаясь шаманить с логгером. А потом лезем с помощью gdb в core dump и пытаемся восстановить недописанные логи.

Для начала проверьте что core dump у вас разрешён:
ulimit -c

Если команда выводит 0, то установите unlimited:
ulimit -c unlimited

Теперь напишем небольшую программу(не вздумайте использовать этот логгер как образец для подражания - код хорош только для наших исследовательских целей, за появление чего-то похожего в продакшене положен расстрел на месте) с псевдологгером с буфером и уроним её с core dump'ом. В классе мы запишем в начало буфера более-менее уникальную строку чтобы потом найти с помощью неё начало буфера в gdb. В случае использования не рукописного буфера придётся записывать уникальную строку в сообщение. В разных логгерах это можно сделать по разному - либо через кастомный форматтер, либо через контекстный дескриптор и тп.
После запуска программа выдаст:
test message 1 
test message 2 
test message 3 
... 
test message 16 
test message 17 
test message 18 
Aborted (core dumped) 

Т.е. логгер успел вывести все сообщения кроме последнего "test message 19".

Теперь запустим
gdb program.out core

В gdb запускаем
maintenance info sections

Там нас интересует раздел для core файла (перед ним будет раздел exec файла), мы увидим что-то вроде этого(понятно что всё что ниже зависит от ОС, компилятора и флагов компиляции):

Нас интересуют сегменты load1, load2 и тп(на самом деле как раз конкретно load1 и load2 не интересуют, но вобщем нас интересует подмножество load сегментов). Попробуем поискать в них, но не всё что мы найдём будет тем что надо, потому что  последовательность символов "my cookie" должна встречаться ещё как минимум один раз, но в реальности в зависимости реализации string, ключей компиляции и тп оно может встретиться ещё много раз. Поэтому мы после каждого найденного случая будем смотреть на этот кусок памяти, и если после "my cookie" идет нуль-терминатор, то это не то что нам нужно - нам надо чтобы сразу после "my cookie" шло что-то похожее на лог-сообщение (в нашем случае мы вообще-то знаем что это будет, но в реальности конечно нет). В нашем случае из-за убогой реализации и отсутствия оптимизации мы найдём порядочно совпадений. Скажу только что в реальности, с асинхронным логерром где буфер сделан не в виде std::string, а через хардкорный malloc и буфера тасуются между фронтэндом и бэкэндом вы тоже можете найти немало совпадений и потратить время чтобы вытащить то что вам надо. Итак ищем так (передаём "my cookie" посимвольно, потому что иначе find будет искать строку с нуль терминатором, а нам это как раз не надо):

Вобщем то что нам надо лежит по адресу 0x86232fc а по адресу 0x8623344 последний буфер который мы послали в cout. Как бы мы поняли в реальности(здесь то мы знали) что нам нужно то что в 0x86232fc а не в 0x8623344? Для этого в логи и пишут точное время для каждого сообщения - мы бы выбрали кусок памяти в котором сообщения моложе самого последнего сообщения записанного в лог-файл.

Многие из вас заметят вполне логично, что нафиг тут gdb если можно взять core файл и в каком-нибудь редакторе в нём поискать нашу метку. Правда в gdb мы видим что в некоторых сегментах можно было и не искать - например очевидно что в READONLY load2 не лежит наш буфер. Ну и если вы пишете свой логгер то проще в начало буффера записать не текст, а что-то более компактное и относительно уникальное - например адрес какого-нибудь метода из того же класса логгера. Тогда в gdb вы можете получить этот адрес (чтобы потом искать уже его) с помощью такой команды:
(gdb) info address PseudoLogger::PseudoLogger

Опять же удобно бэктрейс посмотреть, да много чего можно. Но опять же дело не в инструменте - дело в принципе.

P. S. Тут я привёл листинги из gdb после сборки на 32битной системе, просто чтобы в ширину было всё поуже и попроще читать. Кроме длины адресов разницы c 64битной системой в нашем случае никакой.

Логирование в С++. Бенчмаркинг Poco::Logger и google-glog.

С прошлого поста про логгирование прошло порядочно времени. Я по прежнему считаю что glog хорош, но очевидно не идеален. Не всем нравится, да и иметь альтернативу всегда приятно.

Так вот решил я для мультиплатформенного кода попробовать Poco::Logger (ищите тут http://pocoproject.org/ ). Вроде бы кто-то хвалил, даже у меня коммент к прошлой записи был про него, но я его случайно стёр в борьбе с очередной спам-атакой (кто бы его не писал - сорри, не хотел). Сначала показалось что поднакрутили лишнего в нем, но гибкость вполне на уровне и можно использовать так как тебе нужно. Можно использовать printf-подобные макросы или вызов метода класса или даже использовать Poco::LogStream чтобы писать как в ostream. После того как он мне более-менее понравился захотелось померять насколько он медленный по сравнению с glog.

В итоге написал маленький бенчмарк в котором логгеры последовательно вызывали микробенчмарки в каждом из которых писали 1 сообщение с debug флагом и 2 обычных. Сообщение с debug флагом пишется естественно только в debug сборке, а в release в идеале пропадает без потерь в производительности. Лог пишем в один файл (те glog писал всё в INFO), хотя glog и пишет лог в разные файлы но в реальности под сильной нагрузкой на логгер львиная часть пишется в один файл (ну кроме редких пиков когда что-то совсем ужасное происходит, но в хорошей программе эти пики должны быть кратковременны). Также для каждого логгера есть один микробенчмарк в котором пишутся только debug сообщения - чтобы посмотреть насколько хорошо они испаряются в релизе.

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

Но некоторые консистентные результаты я всё-таки опишу:

•  в release сборке микробенчмарк с только debug сообщениями съедает практически абсолютный ноль и в случае с glog и в случае с Poco::Logger, так что можете писать debug логи хоть через строчку не боясь;
• добавление FormattingChannel к логгеру Poco понятно просаживает производительность ощутимо, с другой стороны логировать без timestamp'а или ставить его периодически руками это нужно иметь очень сильные причины для этого;
• если вы ошиблись и передали например в poco_error_f1(logger_, "bad thing: %s", param); в качестве параметра не строку а например int то на том месте где должен был быть подставлен этот параметр в лог пишется [ERRFMT]. Так вот в этом случае тоже происходит ощутимая потеря производительности - так что лучше быть внимательным. Хотя не заметить это в логах наверное сложно.

В интересующей меня конфигурации glog был быстрее, но не настолько чтобы не рассматривать Poco::Logger как альтернативу. Опять же не забываем что условия слегка отклонены от реальных(glog пишет только в INFO) так что glog в реальности будет чуть медленнее чем в этом бенчмарке и они станут ещё ближе. Учитывая что у Poco есть AsyncChannel и вообще архитектура гибкая и расширяемая, то во многих случаях можно закрыть глаза на небольшие(в масштабах реальной программы, а не только логгера) потери производительности.

 P.S. По поводу бенчмарка https://github.com/Dmitriy403/logBenchmark . FindGlog.cmake написан только под linux, так что кто хочет собрать под винду либо допилите его сами либо загрузите либу glog'а вручную как-нибудь так:
add_library(xxx UNKNOWN IMPORTED)

set_target_properties(xxx PROPERTIES IMPORTED_LOCATION "xxx.lib")

Ну или соберите отдельно руками в чём вам угодно.7 файлов организовать и добавить две либы - не велика задача.
P.P.S. Компилятор должен быть не очень древний, потому что я использовал пару С++11 конструкций. Но я думаю что они уже несколько лет в разных компиляторах есть (chrono и std::bind).

Логирование в С++. Сравнительный мини-обзор

Вполне стандартная задача(логирование) имеет слишком много инструментов для решения в C++. В том плане что ярко выраженного лидера нет(ну если не считать за лидера "свой велосипед"). Пришлось мне ковыряться. Дело усугубилось тем что среди c++ девелоперов очень много людей считающих что подробная документация не нужна (кому надо - в исходник заглянут).

После поверхностного поиска я выделил следующее:

log4j клоны для c++ - log4cxx , log4cpp , log4cplus;

Pantheios;
boost-log;
google-glog.

Попробовав log4cxx  я заподозрил плохое увидев что по сути в проекте не было изменений с 2004 года. Увидев незакрытые баги связанные с многопоточностью(что для меня критично), я на него забил и решил пока не трогать другие log4j клоны (судя по датам релизов живой только log4cplus и если вам хочется во чтобы-то ни стало использовать клон log4j то наверное стоит обратить внимание именно на него).

Далее идут не клоны log4j, так что стандартная схема log4j включая все плюсы и минусы в них отсутствует. Это не значит что они слабее функционально (хотя некоторые объективно нацелены на простоту), они просто другие.

Pantheios выглядит отлично в плане документации/описаний, по отзывам вроде у всех работает без проблем. Я почти остановился на нём, но решил уж посмотреть оставшиеся альтернативы.

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

Наконец очередь дошла до google-glog. И тут я понял что это то что мне нужно. Очень мощный и одновременно простой функционал. DLOG (ну и DCHECK и тд) например позволяет выкинуть мысли о том во что выльется слишком подробное логирование в плане производительности - как только вы скомпиляете релиз-версию все DLOG вызовы превратятся в тыкву просто исчезнут. Но у glog есть и минусы. Например встроенной ротации логов нет. Документация очень куцая, часто приходится заглядывать в исходники (особенно в http://code.google.com/p/google-glog/source/browse/trunk/src/logging.cc ) для поиска настроек (например для максимального размера логфайла).

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

Достоен внимания и Pantheios особенно если вам импонирует его архитектура.