Логирование в C++: как формат съедает производительность

Почему лог оказался на критическом пути

Сервис обработки заказов держал 40 тысяч запросов в секунду, пока в горячий путь не добавили строку отладки: std::cout << "order " << id << " processed at " << timestamp << std::endl;. После деплоя throughput упал до 26 тысяч, а p99-латентность выросла с 3 до 11 мс. Виновата не сама запись в файл — виноваты синхронный flush на каждой строке, форматирование через потоки и блокировка мьютекса, которую логгер держал, пока форматировал сообщение.

Разберём, из чего складывается стоимость одной строки лога в C++, чем платит каждый из популярных подходов и как вынести форматирование и запись за пределы горячего пути. Речь про C++17/20 и библиотеки spdlog 1.x, fmt 10.x и стандартный std::format из C++20.

Из чего состоит цена одной строки

Когда вы вызываете логгер, происходит цепочка операций, и каждая стоит времени:

• Проверка уровня — включён ли DEBUG. Дешёвая операция, если сделана до форматирования.
• Форматирование — превращение аргументов в строку. Здесь iostream проигрывает всем.
• Захват метаданных — временная метка, поток, имя файла. std::chrono::system_clock::now() и особенно преобразование в строку времени стоят заметно.
• Синхронизация — блокировка на время записи, чтобы строки разных потоков не перемешались.
• Запись — в буфер, в файл, в сеть. std::endl дополнительно вызывает flush, а это системный вызов на каждую строку.

Классическая ошибка — форматировать сообщение до проверки уровня. Если DEBUG отключён, а строка собирается через operator<<, вы платите за конкатенацию впустую. Макросы spdlog проверяют уровень до вычисления аргументов, поэтому SPDLOG_DEBUG(...) при выключенном уровне почти бесплатен.

Почему iostream медленный

Каждый operator<< — отдельный вызов с проверкой состояния потока, работой с локалью и, часто, виртуальной диспетчеризацией. Форматирование числа идёт через машину локали, которая тяжелее, чем прямое преобразование. std::endl — отдельная беда: это не просто \n, а \n плюс flush. На диске это превращается в системный вызов на каждую запись.

Первое, что стоит сделать в любом C++-проекте с логами: заменить std::endl на '\n' везде, где не нужен немедленный сброс. Flush нужен только перед возможным падением процесса, а не после каждой строки.

Форматирование: iostream против fmt/std::format

Библиотека fmt (и вошедший в стандарт std::format в C++20) форматирует по строке шаблона за один проход, без пересборки состояния потока на каждый аргумент. Разница на числах и строках существенна.

#include <fmt/format.h>
#include <string>

int order_id = 4211;
double amount = 199.90;

// Через fmt: один проход по шаблону
std::string msg = fmt::format("order {} amount {:.2f}", order_id, amount);

// Через iostream: отдельный вызов на каждый аргумент
// std::ostringstream oss;
// oss << "order " << order_id << " amount " << amount;
// std::string msg = oss.str();

Точные цифры зависят от компилятора, флагов оптимизации и типов аргументов, поэтому не буду называть конкретный множитель — измерьте на своей сборке. Но направление устойчивое: fmt быстрее iostream на форматировании и не тащит за собой локаль. Если у вас C++20 и свежий компилятор, std::format даёт тот же API без внешней зависимости, хотя по скорости он местами уступает fmt — проверяйте на своей версии стандартной библиотеки.

Отложенное форматирование

Главный приём для горячего пути — не форматировать в потоке, который логирует. spdlog в асинхронном режиме копирует аргументы в очередь, а форматирование выполняет фоновый поток. Продающий поток платит только за копирование аргументов и постановку в очередь, а не за сборку строки и запись в файл.

Синхронный, асинхронный, lock-free

Три модели записи различаются тем, кто и когда платит за I/O.

В spdlog асинхронный режим включается через thread pool и очередь фиксированного размера. При переполнении очереди есть два поведения: блокировать вызывающий поток или отбрасывать сообщения. Для сервиса с жёсткими требованиями по латентности отбрасывание лучше, чем блокировка на горячем пути — но вы теряете часть логов под пиковой нагрузкой, и это нужно осознавать.

#include <spdlog/spdlog.h>
#include <spdlog/async.h>
#include <spdlog/sinks/basic_file_sink.h>

// spdlog 1.x: пул из 1 фонового потока, очередь на 8192 сообщения
spdlog::init_thread_pool(8192, 1);

auto logger = spdlog::basic_logger_mt<spdlog::async_factory>(
    "svc", "logs/service.log");

logger->set_level(spdlog::level::info);
// Форматирование строки шаблона делает фоновый поток
logger->info("order {} processed in {} us", order_id, elapsed_us);

Обратите внимание: аргументы order_id и elapsed_us копируются в очередь по значению. Если передать в асинхронный логгер указатель или ссылку на объект, который умрёт до того, как фоновый поток дойдёт до форматирования, вы получите чтение освобождённой памяти. Строковые литералы безопасны, а вот const char* на временный буфер — нет. Передавайте std::string или значения.

Метаданные и паттерн вывода

Каждый элемент в паттерне лога стоит времени. Разбор паттерна вроде [%Y-%m-%d %H:%M:%S.%e] [%t] [%l] %v заставляет логгер на каждую строку форматировать дату, номер потока и уровень. Преобразование времени в человекочитаемый вид — одна из самых дорогих частей.

• Если строк много и важна скорость, храните время как эпоху в микросекундах и форматируйте при чтении логов, а не при записи.
• Убирайте из паттерна то, что не читаете. Имя исходного файла и номер строки удобны, но %s и %# не бесплатны.
• spdlog кеширует форматированную секунду времени, поэтому в пределах одной секунды пересчитывается только дробная часть — это уже оптимизация из коробки, но паттерн всё равно разбирается.

Что мерить, а не гадать

Не переписывайте логгер по ощущениям. Соберите цифры на своей нагрузке:

1. Возьмите репрезентативный сценарий — реальные типы аргументов и реальную частоту вызовов.
2. Измерьте латентность одного вызова логгера в горячем потоке (не throughput записи в файл — именно задержку, которую видит ваш код).
3. Сравните синхронный и асинхронный режим при вашем размере очереди.
4. Посмотрите на p99, а не на среднее: под нагрузкой хвост латентности растёт из-за конкуренции за мьютекс синхронного логгера.

Условия замера фиксируйте всегда: модель CPU, количество потоков, размер сообщения, диск или сеть в качестве приёмника. Число «в 5 раз быстрее» без этих условий бесполезно.

Где подход ломается

Асинхронное логирование не бесплатно и не универсально:

• Потеря логов при падении. Если процесс упал, содержимое очереди фонового потока не записано. Для отладки крешей это худший момент терять последние строки. Регистрируйте flush в обработчике сигнала или используйте синхронный логгер для критических путей.
• Переполнение очереди. При всплеске логов очередь заполняется, и вы либо блокируете горячий поток (латентность взлетает), либо теряете сообщения. Оба варианта надо выбрать сознательно.
• Порядок между потоками. Асинхронная запись может слегка переупорядочить строки относительно реального времени событий, если у вас несколько источников. Полагайтесь на временную метку в записи, а не на порядок строк в файле.
• Висячие ссылки. Передача в асинхронный логгер данных по указателю без копирования — источник трудноуловимых багов, которые проявляются только под нагрузкой.

Что настроить дальше

Начните с дешёвых побед: замените std::endl на '\n', перенесите проверку уровня до форматирования (макросы spdlog делают это сами), уберите из паттерна неиспользуемые поля. Дальше — вынесите форматирование в фоновый поток через асинхронный режим и подберите размер очереди под свой пик. После этого измерьте p99 латентности логгера в горячем пути и сравните с baseline. Отдельная тема, которую здесь не разворачиваем, — ротация и сжатие файлов лога: она влияет на диск, но не на латентность горячего пути.