Почему stream-style logging может быть дорогим

Stream-style logging выглядит очень естественно для C++ кода:

LogmeD() << "request=" << requestId << ", user=" << userId;

Такой стиль удобен. Он хорошо читается, работает с разными типами и позволяет использовать уже существующие operator<<. Поэтому многие C++ логгеры в той или иной форме поддерживают stream-style API.

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

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

Логирование — это не только write

Когда мы говорим “логгер быстрый” или “логгер медленный”, часто смотрим только на финальную запись: файл, консоль, debug output, async queue. Но перед этим есть еще один важный этап — подготовка сообщения.

Например:

LogmeD() << "payload: " << DumpPayload(payload);

Если лог действительно пишется, здесь происходит не только вызов логгера. Нужно выполнить DumpPayload, построить строку, передать ее в stream, собрать итоговое сообщение и только потом отправить его в backend.

Если payload большой, то стоимость DumpPayload может быть намного выше стоимости самого logging API. В этом случае спорить о скорости backend-а бессмысленно: основная цена уже заплачена до записи.

Именно поэтому хорошая logging-модель должна отвечать не только на вопрос “как быстро записать сообщение?”, но и на вопрос “как не строить сообщение, если оно не нужно?”.

Почему stream-style удобен

Stream-style logging хорош для простых сообщений:

LogmeI() << "connected to " << host << ":" << port;

Он не требует format string. Типы можно выводить через обычные operator<<. Код выглядит привычно для C++ разработчика.

Такой стиль удобен для редких сообщений, тестового кода, временной диагностики и мест, где производительность не критична. Также он полезен, когда у типа уже есть хороший stream output, и нет желания писать отдельный formatter.

Проблема начинается тогда, когда stream-style попадает в hot path или начинает использоваться для сложных объектов.

Где появляется цена stream-style logging

Stream-style logging обычно строит сообщение пошагово. Каждый << — это отдельная операция. Для простых чисел это не страшно, но для сложных объектов может запускаться произвольный код.

Например:

LogmeD() << "connection state: " << connection;

Выглядит просто. Но за operator<< для connection может скрываться обход структуры, форматирование адресов, списков, заголовков, статистики или внутренних буферов.

Еще хуже, когда дорогая подготовка вынесена отдельно:

std::string dump = DumpPayload(payload);
LogmeD() << "payload: " << dump;

Здесь DumpPayload будет выполнен независимо от того, нужен debug-log или нет. Даже если debug для channel-а выключен, дорогая строка уже построена.

Stream-style сам по себе не всегда виноват. Виноват паттерн, при котором подготовка текста отделена от precheck-а логгера.

Format-style logging обычно предсказуемее

Format-style logging делает сообщение более явным:

LogmeD("request=%s, elapsed=%u", requestId.c_str(), elapsedMs);

или:

fLogmeD("request={}, elapsed={}", requestId, elapsedMs);

Такой стиль обычно легче анализировать. Видно, какие значения выводятся, как они форматируются и где находится format string.

В активном logging path format-style часто оказывается дешевле stream-style, особенно если сообщение состоит из простых типов. Здесь нет длинной цепочки operator<<, меньше неявных преобразований и меньше риска случайно спрятать тяжелую работу внутри stream operator-а.

Но format-style сам по себе тоже не решает всю проблему. Если в аргументах стоит дорогая функция, ее все равно нельзя вызывать без precheck-а:

LogmeD("payload=%s", DumpPayload(payload).c_str());

Такой код плох не из-за format-style. Он плох потому, что дорогая диагностика находится прямо в аргументах сообщения.

Почему важны именно макросы

В C++ обычная функция не может предотвратить вычисление своих аргументов. Перед входом в функцию аргументы уже должны быть вычислены.

Например, если API выглядит так:

logger.debug("payload={}", DumpPayload(payload));

то DumpPayload(payload) обычно будет выполнен до вызова debug. Даже если внутри debug сразу выяснится, что debug-уровень выключен, уже поздно.

Макрос может устроить precheck раньше. Он может сначала проверить, включен ли лог, нужен ли этот level, активен ли channel, и только потом выполнить код, который строит сообщение.

Именно поэтому в logme logging API построен вокруг макросов. Макрос нужен не только для __FILE__, __LINE__ и __FUNCTION__. Он нужен для того, чтобы дешево выйти до построения сообщения.

Например:

LogmeD(CH, "request=%s", requestId.c_str());

В logme это не просто вызов функции. Макрос сначала проверяет глобальное состояние логирования и то, будет ли выбранный channel писать DEBUG. Если нет — сообщение не строится и dispatch не вызывается.

То же относится и к stream-style вызову через logme macro:

LogmeD(CH) << "request=" << requestId;

Если precheck показывает, что сообщение не будет записано, stream expression не выполняется.

Но это работает только для того, что находится внутри logging expression. Если дорогая подготовка сделана до макроса, logme уже не может ее отменить.

Правильное место для дорогой диагностики

Плохой вариант:

std::string dump = DumpPayload(payload);
LogmeD(CH, "payload=%s", dump.c_str());

Здесь dump строится всегда.

Лучше использовать _Do:

LogmeD_Do(CH,
  std::string dump = DumpPayload(payload),
  "payload=%s",
  dump.c_str());

В этом варианте DumpPayload(payload) будет выполнен только если выбранный channel действительно будет писать DEBUG. Если debug выключен, код подготовки dump вообще не запускается.

То же самое можно сделать с format-style API:

fLogmeD_Do(CH,
  std::string dump = DumpPayload(payload),
  "payload={}",
  dump);

Это ключевая идея precheck-а: дорогие данные должны готовиться внутри guarded logging path, а не перед ним.

Stream-style не должен быть default для hot path

Stream-style logging не нужно запрещать. Он полезен и удобен. Но его не стоит делать стилем по умолчанию для горячего кода.

В hot path лучше выбирать более предсказуемые формы:

LogmeD(CH, "state=%d, queue=%u", state, queueSize);

или:

fLogmeD(CH, "state={}, queue={}", state, queueSize);

А если нужна дорогая диагностика:

LogmeD_Do(CH,
  std::string details = BuildConnectionDetails(connection),
  "connection details: %s",
  details.c_str());

Stream-style можно оставить для простых и редких сообщений:

LogmeI() << "service started";
LogmeW() << "configuration file is missing, defaults will be used";

Но если сообщение находится в цикле, сетевом обработчике, parser-е, allocator-adjacent коде или любом другом hot path, лучше не прятать работу внутри operator<<.

Precheck важнее, чем выбор синтаксиса

Иногда спор выглядит так: что быстрее — stream-style или format-style? Это полезный вопрос, но не главный.

Главный вопрос другой: будет ли вообще выполняться подготовка сообщения, если лог выключен?

Например, оба варианта могут быть плохими:

LogmeD() << DumpPayload(payload);
LogmeD("payload=%s", DumpPayload(payload).c_str());

И оба варианта могут быть нормальными, если они защищены precheck-ом и не делают дорогой работы при отключенном уровне.

Для простых значений достаточно обычного macro logging:

LogmeD(CH, "size=%zu", payload.size());

Ну а для дорогой подготовки нужен _Do:

LogmeD_Do(CH,
  std::string dump = DumpPayload(payload),
  "payload=%s",
  dump.c_str());

Для редких сообщений stream-style допустим:

LogmeI() << "loaded configuration from " << path;

То есть выбор должен зависеть не от вкуса, а от стоимости конкретного сообщения.

Что происходит с disabled logs

Disabled logs — это самый важный сценарий для production. Debug-логи нужны тогда, когда что-то пошло не так, но постоянно держать их включенными обычно нельзя.

Если disabled debug-log все равно строит строки, dump-ы и временные объекты, он продолжает нагружать приложение, хотя сообщений в файле нет.

Правильная модель такая: если лог не будет записан, стоимость должна быть близка к стоимости precheck-а.

В logme это достигается несколькими слоями:

обычные logging macros проверяют глобальное состояние и channel-level policy до dispatch;

_Do выполняет подготовительный код только если сообщение действительно будет записано;

_Once, _Every, _Collapse и related macros помогают не заливать лог повторяющимися сообщениями;

runtime-control позволяет включать подробную диагностику только тогда, когда она нужна.

В результате debug-logging может быть встроен в production-код, но не превращаться в постоянный источник нагрузки.

Stream-style и operator<< для сложных объектов

Особенно осторожно нужно относиться к operator<< для доменных объектов.

Например:

LogmeD() << "session=" << session;

Такой код выглядит дешево, но реальная цена зависит от того, что делает operator<<.

Если он печатает только id, это нормально. Если он обходит список запросов, headers, buffers, metadata и statistics, это уже тяжелая диагностика. Ее нельзя скрывать за обычным stream output.

Лучше разделить легкое и тяжелое представление:

LogmeD(CH, "session=%s", session.Id().c_str());

А подробный dump делать только под precheck:

LogmeD_Do(CH,
  std::string dump = session.Dump(),
  "session dump: %s",
  dump.c_str());

Так код сразу показывает намерение. Легкая строка — обычный log. Тяжелая диагностика — guarded diagnostic path.

Сравнение подходов

Подход	Когда подходит	Основной риск
Stream-style	простые и редкие сообщения, удобный debug	скрытая цена operator<<, temporaries, сложные объекты
Printf-style	горячий код, простые типы, быстрый file logging	меньше type-safety, нужно следить за format string
Format-style	читаемый современный код, простые и средние сообщения	дорогие аргументы нельзя строить без precheck
Macro logging	основной production path	важно не выносить дорогую подготовку до макроса
_Do / precheck	дорогие dump-ы, сериализация, обход структур	не стоит использовать для простых сообщений без необходимости

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

Практические правила

Для горячего кода лучше начинать с обычного macro logging:

LogmeD(CH, "request=%s, status=%d", requestId.c_str(), status);

Если хочется type-safe format-style, можно использовать format API:

fLogmeD(CH, "request={}, status={}", requestId, status);

А если сообщение редкое и простое, stream-style нормален:

LogmeI() << "worker stopped";

Если нужно построить dump, JSON, список headers, stack-like trace, hex buffer или другую дорогую диагностику, используйте _Do:

LogmeD_Do(CH,
  std::string dump = DumpBuffer(data, size),
  "buffer dump: %s",
  dump.c_str());

Ну и если сообщение повторяется слишком часто, добавляйте rate limiting или collapse-механизмы, а не пытайтесь решить проблему только скоростью backend-а.

Итог

Stream-style logging удобен, но он может быть дорогим. Его цена появляется не только в самом stream-е, но и в скрытых operator<<, временных строках, форматировании сложных объектов и подготовке диагностических данных.

Format-style обычно предсказуемее для hot path. Macro logging нужен, чтобы сделать precheck до вычисления сообщения. _Do нужен, чтобы дорогая подготовка выполнялась только тогда, когда сообщение действительно будет записано.

Поэтому правильный вопрос звучит не “stream или format?”, а “где выполняется работа по подготовке сообщения?”.

Если работа выполняется всегда — логирование будет дорогим даже при выключенном уровне. Если работа находится за precheck-ом — подробная диагностика может жить в production-коде и включаться только тогда, когда она действительно нужна.