пятница, марта 22, 2013

Логирование в С++. Бенчмаркинг 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).

Комментариев нет: