Логирование тормозит систему даже когда ничего не пишет
Сложно спорить с тем, что логирование — необходимая часть любого продукта.
Без него невозможно ни нормально диагностировать ошибки, ни понять, что происходит в системе. И всё же в реальных проектах его нередко отключают в релизных сборках — именно потому, что логирование тормозит систему.
Цена за это решение очевидна: система становится плохо наблюдаемой.
Но причина тоже понятна — логирование может стоить дорого.
Причём дорого не только тогда, когда оно активно, но и тогда, когда оно “выключено”.
Ошибка, которую делают почти все
Рассмотрим привычный код:
log.info("value = {}", CalcValue());Обычно ожидается, что если уровень info выключен — код ничего не делает.
Но происходит следующее:
- вызывается
CalcValue() - подготавливаются аргументы
- возможно, происходит форматирование
- и только потом логгер решает, что сообщение не нужно
То есть система уже потратила CPU — просто чтобы не записать лог.
Это поведение характерно для большинства библиотек: spdlog, glog, Boost.Log, Quill.
Первая проблема: не все логгеры можно остановить
Есть ещё более неприятный случай.
Некоторые системы логирования строятся вокруг вызовов методов:
logger->info("value = {}", CalcValue());Здесь:
- нет макроса
- нет точки, где можно “обрезать” выполнение
- аргументы будут вычислены в любом случае
Такой код невозможно полностью отключить без изменения исходника.
Это означает, что часть логирования в принципе не может быть дешёвой, даже если оно “выключено”.
Основная стоимость возникает раньше
Когда обсуждают производительность логирования, обычно говорят про:
- асинхронность
- скорость записи
- очереди
Но к моменту, когда логгер начинает что-то писать, основная работа уже может быть выполнена.
Рассмотрим пример:
std::string dump = DumpBuffer(packet.data(), packet.size());log.debug("packet:\n{}", dump);Если debug отключён:
- буфер разобран
- строка сформирована
- память выделена
И всё это — впустую.
Даже если переписать так:
log.debug("packet:\n{}", DumpBuffer(packet.data(), packet.size()));ничего не меняется.
Что хотелось бы получить
Интуитивно правильная модель выглядит так:
if (log_will_happen){ auto dump = DumpBuffer(...); log(...);}Но писать такие проверки вручную неудобно и легко забыть.
Значит, система логирования должна уметь делать это сама.
Condition — самый ранний стоп
Первый уровень фильтрации — это общее условие.
Система может ещё до любых действий спросить: логирование сейчас вообще разрешено?
Если нет — выполнение заканчивается сразу.
В logme это задаётся через:
Logger::SetCondition(...)Это дешёвая и очень ранняя точка выхода.
Precheck — остановка до вычислений
Следующий уровень — проверка канала.
Здесь происходит принципиально важный момент: решение принимается до вычисления аргументов.
LogmeD(channel, "packet:\n%s", DumpBuffer(packet.data(), packet.size()).c_str());Если канал отключён, DumpBuffer не будет вызван вообще.
Это уже означает, что логирование перестаёт запускать лишнюю работу.
Когда этого недостаточно
На практике подготовка данных часто вынесена отдельно:
std::string dump = DumpBuffer(...);LogmeD(channel, "%s", dump.c_str());Здесь precheck уже не помогает — вычисление произошло раньше.
Контроль над выполнением
Чтобы решить эту проблему, нужен следующий уровень — возможность управлять самим кодом подготовки:
LogmeD_Do( channel, std::string dump = DumpBuffer(...) , "%s" , dump.c_str());Теперь:
- сначала выполняется condition
- затем precheck
- и только потом выполняется код
Если лог не нужен — DumpBuffer не будет вызван вообще.
Но фильтрация — это не одна проверка
На этом месте легко сделать неверный вывод и решить, что всё сводится к precheck или Do.
На самом деле фильтрация — это система.
Рассмотрим другую проблему. Допустим, в коде есть цикл:
for (...){ LogmeD("value = %d", i);}Даже если одно сообщение дешёвое, тысячи повторов создают нагрузку.
Здесь помогают механизмы вроде:
LogmeD_Once("initial value = %d", i);Такой вызов сработает только один раз из данной точки, сколько бы раз код ни выполнялся.
Или:
LogmeD_Every(100, "processed %zu items", count);Это означает: выводить сообщение не на каждом вызове, а так чтобы оно отправлялось в лог не чаще чем раз в 100 миллисекунд.
Такие механизмы не уменьшают стоимость одного вызова. Они уменьшают количество вызовов.
И в реальных системах это влияет на производительность не меньше, чем оптимизация одного лог-сообщения.
Фильтрация может быть даже “архитектурной”
Есть ещё более грубый, но эффективный уровень.
Если:
- канал не создан
- или у него нет backend’ов
- или он отключён
то писать просто некуда.
И система логирования превращается в no-op без дополнительных проверок.
Поздняя фильтрация
Даже после формирования сообщения можно его отсеять.
Например, через display filter:
- сообщение уже готово
- но его можно не отправлять дальше
Это не экономит вычисления, но снижает нагрузку на вывод.
Почему это важнее, чем асинхронность
Асинхронный логгер ускоряет запись.
Но он не отменяет уже выполненную работу.
Фильтрация же позволяет эту работу не делать вообще. Про аспекты работы асинхронного логирования можно прочитать еще в этой нашей статье.
И именно поэтому:
ключевой вопрос — не “насколько быстро пишется лог”,
а “выполняется ли он вообще”
Вывод
Логирование — это не только вывод сообщений.
Это цепочка действий, которая начинается задолго до записи.
И в этой цепочке есть несколько точек, где можно остановиться:
- до входа в логирование
- до вычисления аргументов
- до выполнения пользовательского кода
- на уровне частоты сообщений
- на уровне каналов и конфигурации
Чем раньше система умеет остановиться, тем дешевле становится логирование.
И именно это определяет, можно ли использовать его:
- в горячих участках
- в высоконагруженных системах
- в production без риска скрытых затрат
Потому что разница между
“не записать сообщение” и
“не выполнить ничего лишнего вообще”
— принципиальна.