hkarel Dec 12 2020 at 17:15

ALog: плюс один логгер для C++ приложений

20 min

10K

Система логирования ALog первоначально разрабатывалась для использования в серверных приложениях. Первая реализация ALog была выполнена в 2013 году, на тот момент я и подумать не мог, что спустя семь лет буду писать про нее статью на Хабр. Но, видимо, на все воля случая… Сейчас уже и не вспомню, что именно искал на просторах интернета, когда мне на глаза попалась статья Сравнение библиотек логирования. Я решил бегло просмотреть её в ознакомительных целях. По мере знакомства с материалом в голове возникла мысль: "А где же в этом 'табеле о рангах' находится мой логгер?". Чтобы это выяснить был создан небольшой проект LoggerTest для тестирования систем логирования.

Асинхронный логгер

Прежде чем переходить к тестам, нужно сказать пару слов про ALog¹. Это асинхронная система логирования, предназначенная для использования в высоконагруженных многопоточных приложениях. Как правило, подобные приложения работают на серверных станциях, что определяет специфику самого логгера. По большому счету особенностей две:

У логгера нет ограничения по памяти (обычно серверы не испытывают недостатка в ОЗУ)²
Стоимость вызова логгера в рабочих потоках должна быть минимальной. Данная характеристика важна для любой программы, но для серверной - особенно, где стоимость процессорных ресурсов может быть достаточно высока.

[1] ALog не является самостоятельной библиотекой, это всего лишь несколько модулей в составе библиотеки общего назначения.

[2] Использование ALog в ситуациях отличных от тестовых не приводит к существенному потреблению оперативной памяти, что позволяет использовать логгер на ARM-системах с небольшим объемом ОЗУ.

Участники тестирования

Первоначально для сравнения была выбран только Spdlog. Это было сделано по нескольким причинам:

В исходной статье Spdlog показал неплохие результаты - фактически второе место;
Логгер асинхронный (синхронные логгеры меня не интересовали в принципе, по причине их низкой производительности в многопоточных приложениях);
Под впечатлением от статьи, P7 казался просто недосягаемым, поэтому вначале я его даже не рассматривал в качестве участника тестирования.

Первые сравнения были сильно не в пользу ALog. Пришлось заняться оптимизацией, благо было понимание какие механизмы могут тормозить работу логгера. В итоге отставание стало не столь катастрофическим. Воодушевленный результатом, я написал автору статьи Сравнение библиотек логирования о своем логгере, и приложил первые тесты. Но реакции на мое сообщение не последовало. Выдержав паузу в пару месяцев, я решил самостоятельно написать о проделанной работе.

Для тестов было отобрано три логгера::

G3log (версия 1.3.3, gitrev: f1eff42b)
P7 (версия 5.5)
Spdlog (версия 2.x, gitrev: f803e1c7)

G3log был добавлен просто для статистики. У этого логгера не очень высокая скорость сохранения данных на диск, что и было подтверждено тестами. Последним в сравнение был включен P7. Хочу сказать спасибо разработчикам P7, за помощь в написании тестового примера.

Формат тестовых сообщений

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

У Spdlog и G3log формат префикса можно менять, что позволяет сделать лог-сообщения похожими на сообщения ALog, и таким образом обеспечить примерно одинаковый объем записываемой информации.

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

Внешний вид префиксов для лог-сообщений:

ALog ----------------------------------------------------- 15.10.2020 19:39:23.981457 DEBUG2 LWP18876 [alog_test.cpp:35 LoggerTest]
Spdlog ---------------------------------------------------[2020-10-15 20:22:55.165] [trace] LWP19519 [spdlog_test.cpp:76 LoggerTest]
G3log -----------------------------------------------------2020/10/15 20:24:48 836329 DEBUG [g3log_test.cpp->thread_func:36]

Тестовый стенд

OS: Ubuntu 20.04
Compiler: GCC 8.4.0 C++14
CPU: Intel Core i7 2700K, 4 ядра, 8 потоков (4.5GHz, разгон)
RAM: 32Gb (DDR3-1600, XMP 8-8-8-24-2N)
SSD: Samsung 860 Pro 512Gb³
Количество итераций в тесте: 5
Количество записываемых строк: 5 000 000

[3] Любопытный момент: скорость сохранения логов на HDD диск (TOSHIBA HDWD120) оказалась выше чем на SSD.

Тестирование

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

Прямые характеристики:

Logging time - усредненное время, за которое все тестовые сообщения будут добавлены в систему логирования;
Flush time - усредненное время, за которое все тестовые сообщения будут сохранены на диск (это время отсчитывается от начала теста, поэтому включает в себя значение Logging time).

Косвенные характеристики:

Memory usage (max/average) - пиковое и среднее потребление памяти логгером в тесте (берутся худшие показатели из выполненных итераций);
CPU usage (max/average) - пиковое и среднее потребление ресурсов процессора. За 100% принимается полная загрузка одного ядра процессора (берутся худшие показатели из выполненных итераций).

Дополнительные условия:

В P7 размер пула был установлен в 1 Гб (/P7.Pool=1048576). Для P7 это абсолютно сверх меры, но все участники на старте должны иметь более-менее одинаковые условия;
Для Spdlog размер очереди установлен в 3 млн. сообщений. Уменьшение её размера будет сказываться на показателе Logging time. Логгер работает в режиме async_overflow_policy::block, что запрещает ему отбрасывать "старые" сообщения если очередь переполнена.

Тест 4 потока (режим сборки: release, ключ компилятора -O2)

	ALog	G3log	P7	Spdlog
Logging time (sec)	1.325060	2.91048	4.27096	2.489934
Flush time (sec)	3.051857	23.1829	4.66385	2.489951
Logging per/sec	3788071	1720496	1170852	2008105
Flush per/sec	1638855	215697	1072226	2008092
Memory usage (max, MB)	1468	2343	86	1170
Memory usage (avg, MB)	1302	2310	85	1095
CPU usage (max, %)	106	87	57	100
CPU usage (avg, %)	39	18	37	67

По параметру Flush time ALog так и не смог опередить Spdlog. Поэтому можно сказать, что по Flush time Spdlog - лидер. Правда тут есть одна оговорка: это преимущество сохраняется до тех пор, пока размер очереди больше либо равен 3 * 10^6. "Ложка дегтя" заключается в том, что память под очередь сообщений выделяется в момент создания Spdlog, и остается занятой на всем протяжении работы логгера. В данном тесте Spdlog использовал 1170 Мб. Остальные участники тестирования выделяют память по мере повышения нагрузки, и освобождают по мере понижения.

Тест 4 потока (режим сборки: debug, ключ компилятора -O0)

	ALog	G3log	P7	Spdlog
Logging time (sec)	3.080949	5.59882	4.69356	7.591786
Flush time (sec)	4.717017	38.5406	5.05907	7.591814
Logging per/sec	1625193	893396	1065342	658611
Flush per/sec	1060223	129736	988428	658609
Memory usage (max, MB)	1241	1840	57	1170
Memory usage (avg, MB)	1071	1811	56	1130
CPU usage (max, %)	106	100	58	118
CPU usage (avg, %)	44	21	36	73

Тест в debug-режиме интересен с точки зрения падения производительности. Очевидно, что проседание есть, но оно не такое катастрофическое (десятки раз), как об этом говорится в Сравнение библиотек логирования. Возможно, причина в том, что тесты проводились на Linux.

Тест 1 поток (режим сборки: release, ключ компилятора -O2)

	ALog	G3log	P7	Spdlog
Logging time (sec)	3.936475	8.43987	1.93741	3.090048
Flush time (sec)	4.029064	22.5557	2.32743	3.090063
Logging per/sec	1270377	596768	2580784	1618186
Flush per/sec	1241177	221687	2148340	1618178
Memory usage (max, MB)	84	1353	53	392
Memory usage (avg, MB)	55	1350	52	383
CPU usage (max, %)	50	64	21	64
CPU usage (avg, %)	25	21	11	44

В этом тесте P7 восстановил свой статус-кво. Запись в систему логирования 5 млн. сообщений в один поток за ~1.9 секунды выглядит просто недосягаемо! Скорость сохранения данных на диск тоже весьма впечатляет.

Здесь ALog уступает Spdlog в Logging time. Valgrind по этому поводу "говорит", что одна из причин низкой производительности кроется в использовании функции std::vsnprintf(). При сборке тестов под С++17 появляется возможность минимизировать использование std::vsnprintf(). При этом Spdlog все еще впереди, но отставание уже минимально (~0.15 сек). В то же время ALog улучшает другие показатели: максимальный объем занимаемой памяти уменьшился до 44 Мб, а пиковое потребление ресурсов процессора сократилось до 33%.

Для Spdlog размер очереди сообщений уменьшен до 1 млн. записей, что позволило сократить объем занимаемой памяти с 1170 Мб до 392 Мб. Дальнейшее уменьшение размера очереди ведет к ухудшению Logging time. Еще один штрих: сборка Spdlog под С++17 даёт незначительное (примерно на 0.1 секунды) увеличение Logging time, не затрагивая остальные результаты.

Промежуточный итог

Что ж, тщеславие удовлетворено. Пусть ALog не первый в этом тестировании, но тем не менее выглядит вполне достойно, а по параметру Logging time в многопоточном режиме работы - безусловный лидер.

Но что же дальше?! Эффективность работы системы логирования безусловно важна, но есть и другие критерии, которые целесообразно принимать во внимание. Например: возможность конфигурирования, фильтрация, удобство записи лог-сообщений в рабочем коде. Уже в процессе подготовки тестов пришла мысль, что наверное не следует ограничиваться только сравнением логгеров, и было бы неплохо рассказать об особенностях использования ALog. Это я и собираюсь сделать в следующих разделах.

Немного плагиата

Собственно, в чем плагиат: из статьи Сравнение библиотек логирования я решил позаимствовать авторские названия некоторых разделов, чтобы обеспечить ассоциативность восприятия материала.

Документация и зависимости

Документация: отсутствует, к сожалению. Что бы сгладить этот недостаток, был создан небольшой проект LoggerDemo с примерами использования логгера. Сейчас их шесть:

Demo 01: Вывод в лог "Hello world";
Demo 02: Вывод сообщений в файл;
Demo 03: Вывод сообщений из разных потоков;
Demo 04: Фильтрация лог-сообщений по имени модуля, с последующим сохранением в разные лог-файлы;
Demo 05: Конфигурирование лог-системы при помощи конфиг-файлов⁴;
Demo 06: Форматированный вывод через log_format (тестовое использование)

Для сборки потребуется QtCreator 4.12 или выше. Сборочная система QBS.

Примечание: сборка под ОС Windows не выполнялась, но проект тривиален, поэтому проблем возникнуть не должно.

Зависимости: ALog - не самостоятельное решение, он является составной частью библиотеки общего назначения SharedTools. Для такого подхода есть пара причин:

ALog достаточно маленький - всего три программных модуля⁵:
1. logger - непосредственно сам логгер;
2. config - модуль конфигурирования;
3. format - модуль для форматированного вывода сообщений.
ALog зависит от некоторых модулей общего назначения из SharedTools. Поэтому я посчитал нецелесообразным выносить логгер в отдельную библиотеку, и делать ее зависимой от SharedTools.

[4] Для сборки примера Demo 5 требуется Qt-framework.

[5] Под программным модулем понимается пара cpp/h файлов, или один h-файл.

Тип логгера, контроль потребления памяти и потокобезопасность

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

Обработка сбоев процесса

Автоматическая обработка сбоев процесса не предусмотрена. Считаю, что программист должен самостоятельно выполнять такого вида обработки, так как сложно предвидеть все инварианты, которые могут потребоваться разработчику. Тем не менее, существует механизм для немедленного "сброса" всех сообщений из буфера логгера в систему вывода. Функция "сброса" сообщений может выглядеть так:

void prog_abort()
{
    log_error << "Program aborted";
    alog::logger().flush();
    alog::logger().waitingFlush();
    alog::logger().stop();
    abort();
}

Стиль логирования и вывод (sink)

Вывод (sink): В ALog механизм вывода называется Saver (дословно: хранитель, в вольной трактовке: средство/механизм сохранения). В дальнейшем будет использоваться именно этот термин.

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

Стиль логирования: ALog поддерживает два стиля логирования: потоковый оператор << и форматированный вывод. При этом, вывод через потоковый оператор является основным, а форматированный вывод был добавлен сравнительно недавно и, на текущий момент, находится в статусе экспериментальный.

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

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

Используем структуру TaskLog для группировки необходимых параметров логирования.

struct TaskLog
{
    int taskId;
    int userId;
    string status;
};

На следующем шаге реализуем потоковый оператор ⁶.

namespace alog {
Line& operator<< (Line& line, const TaskLog& tl)
{
    if (line.toLogger())
        line << "TaskId: "   << tl.taskId
             << "; UserId: " << tl.userId
             << "; Status: " << tl.success;
    return line;
}
} // namespace alog

Реализацию saver-a для записи сообщений в базу данных я оставлю за рамками этой статьи по причине существенного объема кода. Отмечу только, что saver нужно будет создать и зарегистрировать в системе логирования при старте программы. Далее в рабочем коде приложения вызываем логгер:

TaskLog tl {10, 20, "success"};
log_info << "Task complete. " << tl;

В лог-файл будет добавлена строка: 15.10.2020 19:39:23 INFO LWP18876 [example.cpp:35] Task complete. TaskId: 10; UserId: 20; Status: success И одновременно с этим система логирования вставит в таблицу базы данных запись из трех полей: TASK_ID, USER_ID, STATUS. Конечно, реализация потокового оператора и saver-a для вывода информации в базу данных потребует определенных усилий, но это может быть оправдано удобством последующего использования.

Вот еще одна ситуация, которую хотелось бы рассмотреть: иногда лог-сообщение должно формироваться в зависимости от условия. "Классический" способ решения этой задачи - конкатенация строк с последующим выводом результата. В ALog конкатенация может быть заменена на последовательное формирование лог-сообщения при помощи явно объявленной переменной с типом alog::Line:

{ //Block for alog::Line
    alog::Line logLine = log_verbose << "Threshold ";
    if (threshold > 0.5)
        logLine << "exceeded";
    else
        logLine << "is normal";
    logLine << " (current value: " << threshold << ")";
}

Форматированный вывод реализован как надстройка над потоковыми операторами. Таким образом форматированный вывод будет работать со всеми типами данных для которых реализован оператор <<. Пример с выводом TaskLog будет выглядеть так:

TaskLog tl {10, 20, "success"};
log_info << log_format("Task complete. %?", tl);

Возможно комбинирование потоковых операторов и форматированного вывода:

log_info << "Task complete." << log_format(" %?", tl);

[6] В примере приведена базовая (упрощенная) реализация потокового оператора.

Инициализация логгера

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

Для stdout программная инициализация состоит из одной строки:

alog::logger().addSaverStdOut(alog::Level::Info);

Инициализация для вывода в файл будет чуть сложнее:

const char* saverName = "default";
const char* filePath = "/tmp/logger-demo.log";
alog::Level logLevel = alog::Level::Debug;
bool logContinue = true;
{ //Block for SaverPtr
    SaverPtr saver {new SaverFile(saverName, filePath, logLevel, logContinue)};
    logger().addSaver(saver);
}

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

Пример секции инициализации логгера:

### YAML syntax ###
# Конфигурирование системы логирования
logger:
    # Уровень логирования. Допускаются следующие значения: error, warning, info,
    # verbose, debug, debug2. По умолчанию используется info
    level: verbose
    
    # Определяет будет ли пересоздаваться log-файл при перезапуске программы.
    # (флаг: true/false). Если параметр равен 'false', то log-файл будет
    # пересоздаваться при каждом перезапуске программы, в противном случае
    # логирование будет выполняться в существующий файл
    continue: true
    
    # Наименование файла логирования
    file: /var/opt/application/log/application.log
    
    # Наименование файла логирования в Windows
    file_win: ProgramData/application/log/application.log
    
    # Определяет файл конфигурирования сейверов и фильтров для системы логирования
    conf: /etc/application/application.logger.conf
    
    # Определяет файл конфигурирования сейверов и фильтров для системы логирования в Windows
    conf_win: ProgramData/application/config/application.logger.conf
    
    filters:
        # Наименование фильтра
      - name: default
        type: module_name
        mode: exclude
    
        modules: [
            VideoCap,
            VideoJitter,
        ]

В этой конфигурации будет создан saver по умолчанию⁷, с выводом в файл /var/opt/application/log/application.log. Параметры logger.conf и logger.filters отвечают за механизмы расширенной фильтрации, их назначение будет рассмотрено в разделе Настройка фильтрации.

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

// Время последней модификации конфиг-файла приложения
std::time_t configBaseModify = 0;
// Время последней модификации конфиг-файла для логера
std::time_t configLoggerModify = 0;

void init()
{
    // Время модификации файлов на момент старта программы
    configBaseModify = config::baseModifyTime();
    configLoggerModify = config::loggerModifyTime();
}

// Таймер-функция
void configModifyTimer()
{
    bool modify = false;
    std::time_t configModify = config::baseModifyTime();
    if (configBaseModify != configModify)
    {
        modify = true;
        configBaseModify = configModify;
        config::base().rereadFile();
        log_verbose << "Config file was reread: " << config::base().filePath();
        alog::configDefaultSaver();
    }

    configModify = config::loggerModifyTime();
    if (configLoggerModify != configModify)
    {
        modify = true;
        configLoggerModify = configModify;
        alog::configExtensionSavers();
    }
    if (modify)
        alog::printSaversInfo();
}

[7] Наименование saver-a по умолчанию всегда 'default'

Точность времени

Все сообщения в ALog фиксируются с точностью до 1 микросекунды, что покрывает потребности большинства существующих приложений. Но выводится это время только при уровне логирования Debug2 (режим трассировки). Такая точность временных меток необходима для режима подробной диагностики, для менее интенсивных режимов логирования вполне достаточно точности в 1 секунду. Данный подход несколько сокращает объем лог-файла. При разработке собственного saver-a разработчик может выводить микросекунды на любом уровне логирования.

Доступ к логгеру

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

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

Настройка фильтрации

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

enum Level {None = 0, Error = 1, Warning = 2, Info = 3, Verbose = 4, Debug = 5, Debug2 = 6};

Debug2 - соответствует режиму трассировки, название имеет исторические причины.

На этом, сходство с другими логгерами заканчиваются. Первое существенное отличие состоит в том, что для ALog невозможно задать уровень логирования напрямую, так как уровень логирования - не характеристика логгера, а характеристика его saver-ов. Уровень логирования самого логгера всегда будет равен максимальному уровню логирования saver-ов, использующихся на данный момент. Однако, для логгера эта характеристика тоже достаточно важна, так как она позволяет еще на первичном этапе обработки сообщений отсекать те из них, которые гарантированно не будут выводиться в лог.

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

При использовании глобального логгера все программные модули будут выдавать сообщения с заданным уровнем логирования, в результате чего получается много лишней, избыточной информации;
Использование нескольких экземпляров логгера в попытке уйти от проблемы из п.1 выглядит не очень удачной идеей. На мой взгляд, система логирования должна быть простой и единообразной в использовании из любой части программы. Программист не должен задумываться над тем, каким экземпляром логгера ему пользоваться;
Объем файлов логирования может быть очень большим (см. п.1). Иногда объемы лог-файлов исчисляются десятками гигабайт, то есть существует риск отказа операционной системы из-за отсутствия свободного места на диске;
Анализ больших лог-файлов достаточно трудоемкое занятие, часто требующее наличия вычислительных мощностей, что бы можно было за разумное время обрабатывать полученные лог-данные.

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

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

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

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

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

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

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

Тип фильтрации	Описание
module_name	По именам логических модулей
log_level	По уровню логирования (это вариант одного файла с разными уровнями логирования)
func_name	По именам функций (механизм реализован, но фактически не востребован)
file_name:line	По именам файлов (читай: по именам программных модулей) и номерам строк
thread_id	По идентификаторам потоков
content	По контенту сообщения

Более подробно типы фильтрации описаны тут. Файл demo05.logger.conf содержит пример конфигурации логгера для Demo 05

Осталось рассмотреть вопрос с наименованием логических модулей. Можно использовать решение "в лоб", но выглядит оно не очень…

alog::logger().debug(alog_line_location, "Module1") << "Message";

Как часто бывает в таких ситуациях - на помощь приходят макросы.

// Определяем макросы в начале модуля
#define log_error_m   alog::logger().error   (alog_line_location, "Module1")
#define log_warn_m    alog::logger().warn    (alog_line_location, "Module1")
#define log_info_m    alog::logger().info    (alog_line_location, "Module1")
#define log_verbose_m alog::logger().verbose (alog_line_location, "Module1")
#define log_debug_m   alog::logger().debug   (alog_line_location, "Module1")
#define log_debug2_m  alog::logger().debug2  (alog_line_location, "Module1")
...

void moduleFunc1()
{
    for (int i = 0; i < 10; ++i)
    {
        log_debug_m << "Func1. Message " << i;
        usleep(10);
    }
}
...
// Удаляем макросы в конце модуля
#undef log_error_m
#undef log_warn_m
#undef log_info_m
#undef log_verbose_m
#undef log_debug_m
#undef log_debug2_m

В cpp-файлах #undef можно опустить, но не стоит так делать в заголовочных файлах. В этом случае результат работы лог-фильтров может оказаться неожиданным.

Поддержка юникода

Фактически, широкой поддержки юникода нет. В Linux в подавляющем большинстве ситуаций используется UTF-8. Для QString есть перегруженный потоковый оператор, в нем осуществляется преобразование из UTF-16 в UTF-8. На этом все.

Ротация файлов

ALog не поддерживает какие либо механизмы по ротации лог-файлов, так как с этой задачей прекрасно справляется logrotate.

Некоторые приемы использования

Здесь описаны некоторые приемы использования ALog, которые не попали в другие разделы. Делаю это на тот случай, если вдруг кому-то в голову придет мысль о применении ALog в своей программе.

Сложные трассировочные сообщения лучше использовать внутри условия:

if (alog::logger().level() == alog::Level::Debug2)
{
    log_debug2_m << "Message was sent to socket"
                 << ". Id: " << message->id()
                 << ". Command: " << CommandNameLog(message->command())
                 << ". Type: " << message->type()
                 << ". ExecStatus: " << message->execStatus();
}

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

log_debug2_m << "Message was sent to socket";

Наименование программного модуля получено из другой программы

std::string s = ".../python/example1.py";
const char* file = alog::__file__cache(s);
alog::logger().info(file, 0, 10, "Python") << "Message from python-script";

Не так давно в ALog была добавлена оптимизация позволяющая извлекать наименование программного модуля из макроса __FILE__ в процессе компиляции, и это реально ускорило работу логгера. Но у такой оптимизации есть обратная сторона: адреса строк содержащих наименования модулей не должны меняться на протяжении жизни программы. В принципе, с макросом __FILE__ все так и есть. Но иногда возникает желание (или необходимость) сделать сквозное логирование для внутренних и внешних (работающих в другом процессе) компонентов приложения. В данном случае наименования модулей получаемые из внешней программы имеют динамические адреса строк, а следовательно их нельзя передавать в ALog. Для решения этой проблему была создана функция alog::__file__cache(), она преобразует динамические строки в псевдостатические, что вполне устраивает логгер.

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

Пример подмены функции логирования logmvnc() для драйвера Intel Movidius Neural Compute Stick:

void logmvnc(enum mvLog_t level, const char* file, int line, const char* func,
             const char* format, ...) asm ("logmvnc");

void logmvnc(enum mvLog_t level, const char* file, int line, const char* func,
             const char* format, ...)
{
    va_list args;
    va_start(args, format);

    int len;
    char buff[1024] = {0};


    auto removeLastN = [&len, &buff]()
    {
        if ((len < int(sizeof(buff))) && (buff[len - 1] == '\n'))
            buff[len - 1] = '\0';
    };

    switch (level)
    {
        case MVLOG_DEBUG:
            if (alog::logger().level() == alog::Level::Debug2)
            {
                len = vsnprintf(buff, sizeof(buff) - 1, format, args);
                removeLastN();
                alog::logger().debug2(file, func, line, "Movidius") << buff;
            }
            break;

        case MVLOG_WARN:
            {
                len = vsnprintf(buff, sizeof(buff) - 1, format, args);
                removeLastN();
                alog::logger().warn(file, func, line, "Movidius") << buff;
            }
            break;

        case MVLOG_ERROR:
        case MVLOG_FATAL:
        case MVLOG_LAST:
            {
                len = vsnprintf(buff, sizeof(buff) - 1, format, args);
                removeLastN();
                alog::logger().error(file, func, line, "Movidius") << buff;
            }
            break;

        default:
            {
                // LEVEL_INFO
                len = vsnprintf(buff, sizeof(buff) - 1, format, args);
                removeLastN();
                alog::logger().info(file, func, line, "Movidius") << buff;
            }
    }
    va_end(args);
}

[8] Это возможно не для всех библиотек.

Вместо заключения

Когда я только начинал работу над этим материалом, то полагал, что ALog уже достаточно устоявшееся, отработанное решение. Но мои представления были неверными. Оказалось, что есть много аспектов, требующих переоценки или доработки. Какие-то правки вносились в процессе тестирования, а какие-то уже в процессе написания этой статьи. Благодаря всей этой затее были созданы два новых проекта: LoggerTest и LoggerDemo. Оба проекта открыты для развития, поэтому если у кого-то возникнут вопросы по работе логгера - постараюсь, по мере возможности, на них ответить. Может быть ответы воплотятся в новых примерах. Касательно LoggerTest - думаю, я далеко не единственный, кто пишет свой логгер, так что если есть желание помериться цифирьками - приходите.

UPD

По совету @ksergey01 добавлены тесты для системы логирования Quill. Версия логгера 1.6.1, gitrev: 96a713f.

Тест 4 потока (режим сборки: release, ключ компилятора -O2)

	ALog	Quill
Logging time (sec)	1.351790	0.048965
Flush time (sec)	2.845629	5.80767
Logging per/sec	3703800	103627238
Flush per/sec	1758392	861922
Memory usage (max, MB)	1370	1384
Memory usage (avg, MB)	1236	1110
CPU usage (max, %)	106	59
CPU usage (avg, %)	39	12

Значение Logging per/sec равное 103 млн. записей в секунду не является ошибкой, логгер действительно обрабатывает лог-сообщения в рабочих потоках с такой скоростью. Точнее сказать, он их почти не обрабатывает в рабочих потоках, а старается как можно быстрее передать в фоновый поток логгера, где происходит основная работа и вывод в файл. Отчасти поэтому значение параметра Flush per/sec такое невысокое.

Некоторые особенности Quill, на которые хотелось бы обратить внимание:

Формат-строка является параметром шаблона, поэтому она не может быть изменена в процессе работы программы. Как следствие, динамические сообщения или локализация недоступны для логгера. Автор Quill предложил такой выход из этой ситуации: LOG_TRACE(logger, “{} {}”, format_string.c_str(), i);
Механизм вывода лог-сообщений должен быть инициализирован до начала работы логгера. В процессе работы приложения смена экземпляра вывода не допускается.
Quill поддерживает работу с пользовательскими типами. Механизм описан тут, тесты приведены ниже.

Тест вывода пользовательского типа (4 потока, release, -O2)

	ALog	Quill (1)	Quill (2)
Logging time (sec)	2.326450	0.24764	2.22776
Flush time (sec)	4.037588	15.0679	7.8387
Logging per/sec	2149603	20731451	2244706
Flush per/sec	1238723	331919	638584
Memory usage (max, MB)	1969	2388	1968
Memory usage (avg, MB)	1398	2251	1808
CPU usage (max, %)	106	73	71
CPU usage (avg, %)	40	13	23

В тесте (1) пользовательский тип преобразуется в лог-строку во вспомогательном потоке логгера; в тесте (2) пользовательский тип преобразуется в лог-строку в рабочем потоке.

Tags:

Hubs: