27 Июл 2026

Профилирование источников логирования: какая строка создаёт нагрузку?

Опубликовано в Логирование, С++ Eduard Mishkurov 27 июля, 2026

Как профилирование источников логирования связывает нагрузку на CPU и файловый ввод-вывод с конкретными конструкциями C и C++, не отключая рабочую диагностику

Профилирование источников логирования начинается там, где обычный CPU-профайлер останавливается. Системный профайлер умеет показать, что заметную долю процессорного времени потребляет поток логирования, а в верхней части профиля находятся write(), worker файлового backend, синхронизация очереди, копирование памяти и форматирование строк.

Однако эта информация не отвечает на главный вопрос:

Какие именно конструкции вывода в лог создают эту нагрузку?

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

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

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

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

С чего началось профилирование источников логирования

Сервис под Linux недавно был переведён на событийную модель ввода-вывода. Даже при отсутствии запросов четыре процессорных ядра оставались полностью загруженными.

Первый профиль VTune был однозначным: рабочие потоки вращались в цикле вокруг epoll_wait() и epoll_ctl(). Постоянное состояние EPOLLRDHUP повторно перевзводилось без завершения операции, поэтому очередной epoll_wait() сразу возвращал то же событие.

После исправления busy loop загрузка CPU резко снизилась. В результате новый профиль выглядел намного здоровее: больше не было одного стека, занимавшего почти всё процессорное время. Стала видна реальная работа приложения — TLS, HTTP/2, вычисление политик, синхронизация потоков и логирование.

Среди верхних стеков появился такой:

libc.so.6!write
liblogme.so!Logme::FileIo::WriteRaw
liblogme.so!Logme::FileIo::WriteAll
liblogme.so!Logme::FileBackend::WriteReadyData
liblogme.so!Logme::FileBackend::WorkerFunc
liblogme.so!Logme::FileManager::ManagementThread

Тем не менее этот стек не доказывал, что в логгере есть дефект. Он показывал только, что приложение поручает логгеру записывать достаточно данных или достаточно отдельных сообщений, чтобы эта работа стала заметной.

Следующий вопрос VTune уже не мог решить:

Какие строки исходного кода породили эти записи?

Почему профилированию источников логирования недостаточно общих счётчиков backend

Библиотеки логирования часто имеют полезные агрегированные счётчики: число записанных байтов, размер очереди, потерянные сообщения, ошибки записи, ротации и сбросы буферов. Они хорошо описывают состояние backend, но не связывают нагрузку с кодом, который её создал.

Предположим, файловый backend записывает 80 КиБ/с. Такой поток может состоять из:

одного большого JSON или payload-дампа в секунду;
тысячи небольших сообщений в секунду;
одной записи, размноженной через связанные каналы;
нескольких независимых каналов, использующих общий backend;
кратковременного всплеска, который асинхронный worker ещё не успел обработать.

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

Полезное профилирование источников логирования должно сохранять связь между четырьмя уровнями:

Место вызова, которое создало сообщение.
Исходный канал, первоначально принявший его.
Все конечные каналы и backend, достигнутые после маршрутизации и fan-out.
Фактическая работа файлового worker после помещения записи в очередь.

Также нельзя объединять две разные метрики:

records находят высокочастотные источники, расходующие CPU на форматирование, очереди, блокировки, атомарные операции и пробуждения worker;
bytes находят длинные сообщения, дампы и большой объём вывода.

На практике логирование может быть дорогим даже при небольшой скорости записи на диск.

Профилирование источников логирования начинается с отдельного log site

Каждый C++-макрос logme уже создавал статический контекстный кэш в конкретной точке исходного кода. Концептуально вызов:

LogmeI(PCH, "evaluating expression: %s", expression);

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

Профилирование источников логирования лениво регистрирует log site и сохраняет:

исходный файл
функцию
номер строки
уровень
первую увиденную строку формата

Сформированные сообщения и реальные аргументы не сохраняются. В отчёте может присутствовать:

format: evaluating expression: %s

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

Для нативных C-макросов потребовалось отдельное изменение. Старый C API использовал общий кэш внутри библиотеки, поэтому разные места вызова невозможно было различить. Теперь стандартные C-макросы также создают локальный статический кэш. Прямые вызовы старых функций сохранили ABI, а для точной идентификации доступны site-aware варианты API.

Как сохранить почти бесплатное профилирование источников логирования в выключенном режиме

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

При выключенном профилировании горячий путь не должен выполнять:

регистрацию call site;
обновление счётчиков;
захват mutex;
выделение памяти;
поиск в таблицах;
копирование метаданных;
получение текущего времени.

После обычной фильтрации по уровню и каналу принятая запись доходит до проверки, эквивалентной следующей:

LogStatisticsCollector* statistics =
  ActiveLogStatistics.load(std::memory_order_relaxed);

if (statistics != nullptr)
{
  // Профилирование выполняется только во время активного сбора.
}

Инструментирование backend использует ту же модель. Если указатель равен nullptr, назначения не регистрируются, а счётчики не изменяются.

Такая схема важна по двум причинам.

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

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

Например, в искусственном тесте с NullBackend, где три миллиона принятых сообщений почти не выполняли полезной работы, разница между исходным путём и скомпилированным, но выключенным профилировщиком составила примерно 0,5–1,4 нс на вызов в зависимости от запуска. Медианная разница в последующих измерениях была около 0,7 нс. Такой тест специально преувеличивает относительную стоимость, поскольку сам backend почти ничего не делает. В реальном файловом или сетевом логировании доля значительно меньше. Отдельный benchmark асинхронного FileBackend не показал регрессии за пределами погрешности измерений. Этот результат согласуется с более широкими измерениями в статье о производительности C++-логирования.

Цель состояла не в декларации математически нулевой стоимости. Важно было гарантировать, что неактивный профилировщик не добавляет блокировок, выделений памяти, регистрации, измерения времени и трафика счётчиков в обычное выполнение приложения.

Профилирование источников логирования между каналами и backend

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

Например:

source site
  -> channel policy
       -> FileBackend
       -> ConsoleBackend
       -> linked channel diagnostics
            -> another FileBackend

Исходная конструкция создала одно сообщение, но система логирования выполнила четыре доставки.

Поэтому для профилирования источников логирования logme предоставляет отдельные представления:

logstat top
logstat channels
logstat outputs
logstat backends

top считает исходные сообщения до маршрутизации. outputs связывает сформированный вывод backend с исходной строкой кода после routing и fan-out. backends агрегирует те же данные по конечному каналу и типу backend.

Для файлового вывода output-bytes содержит размер полностью сформированной записи, принятой backend, включая префиксы канала и остальные включённые поля. В асинхронном режиме значение учитывается после принятия записи файловой очередью. В синхронном — после успешной записи.

Файловому worker нужен отдельный профиль

Атрибуция показывает, кто создал нагрузку, но не говорит, насколько эффективно её обработал файловый worker.

Отчёт logstat files собирает runtime-счётчики асинхронных экземпляров FileBackend:

число записей и байтов, принятых очередью
worker batches
операции записи
число буферов и входных байтов
успешно записанные байты
ошибочные операции записи
потерянные очередью записи и байты
средний и максимальный размер batch

В результате можно разделить две типичные проблемы.

Если принятые байты почти равны записанным, ошибок нет, а batch имеют разумный размер, backend успевает обрабатывать поток. Исправлять нужно источники сообщений.

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

Как использовать профилирование источников логирования в работающем сервисе

Профилировщик управляется через обычный control server logme, как правило при помощи logmectl. По умолчанию сбор выключен.

Минимальная сессия выглядит так:

PORT=7791

logmectl -p "$PORT" logstat start

# Воспроизводим характерную нагрузку.
sleep 60

logmectl -p "$PORT" logstat stop

logmectl -p "$PORT" logstat backends \
  --sort bytes \
  --limit 20

logmectl -p "$PORT" logstat outputs \
  --backend FileBackend \
  --sort bytes \
  --limit 30

logmectl -p "$PORT" logstat outputs \
  --backend FileBackend \
  --sort records \
  --limit 30

logmectl -p "$PORT" logstat files \
  --sort written-bytes \
  --limit 20

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

Для серьёзного исследования я, как правило, снимаю как минимум два интервала:

простой сервиса без характерных запросов;
нормальная рабочая нагрузка;
при необходимости — отдельный интервал с воспроизведением проблемного сценария.

Разница позволяет отделить периодические фоновые сообщения от логов, вызванных обработкой запросов.

Полный набор команд:

logstat start
logstat stop
logstat status
logstat reset
logstat top [--sort bytes|records] [--limit count]
logstat channels [--sort bytes|records] [--limit count]
logstat outputs [--sort bytes|records] [--limit count] [--backend type]
logstat backends [--sort bytes|records] [--limit count] [--backend type]
logstat files [--sort written-bytes|batches|errors|dropped-bytes] [--limit count]

Для скриптов и автоматического сравнения доступен JSON через обычный режим logmectl --format json.

Что профилирование источников логирования нашло в реальном сервисе

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

Log backend statistics: stopped
Duration: 287.184 s
Sort: output-bytes
Backend filter: FileBackend
Total: records=252771 output-bytes=24802272

1. share=10.23% records=30107 records/s=104.84
   output-bytes=2536226 KiB/s=8.62 avg=84.2 max=165
   level=INFO channel=policy backend=FileBackend
   Entity/Condition.cpp:137 GetValue
   format: [line:%i col:%i] evaluating: %s

2. share=10.01% records=30107 records/s=104.84
   output-bytes=2483250 KiB/s=8.44 avg=82.5 max=216
   level=INFO channel=policy backend=FileBackend
   Eval/Calculator.cpp:590 Evaluate
   format: Evaluate expression: %s

3. share=8.54% records=30107 records/s=104.84
   output-bytes=2117192 KiB/s=7.20 avg=70.3 max=204
   level=INFO channel=policy backend=FileBackend
   Eval/Calculator.cpp:680 Evaluate
   format: %s is %s

4. share=7.79% records=30107 records/s=104.84
   output-bytes=1931391 KiB/s=6.57 avg=64.2 max=145
   level=INFO channel=policy backend=FileBackend
   Entity/Condition.cpp:176 GetValue
   format: %s is %s

Самым важным признаком оказалось одинаковое значение records=30107. Оно показало, что каждое вычисление выражения порождает одну и ту же последовательность подробных сообщений.

Дополнительные записи из Calculator, Subcondition и Entry завершили цепочку. Восемь конструкций, связанных с вычислением выражений, создали примерно 56,5% всех байтов, переданных в FileBackend за интервал.

Другая группа состояла из подробной диагностики каждого сетевого события:

async queue: ... size=... queued=...
async TLS protocol result: op=... bytes=... state=...
call policy engine with text size: ...
<полный дамп frame или payload>

Вместе с дампами кадров и короткими сообщениями о завершении эта группа дала ещё примерно 15% файлового вывода.

Таким образом, расплывчатая формулировка «логгер высоко в VTune» превратилась в короткий список конкретных файлов, функций и строк, который можно обсуждать при code review.

Почему главным фактором оказалось число записей, а не объём байтов

За интервал приложение создало:

252 771 запись файлового backend
24 802 272 байта вывода
287,184 секунды

Это примерно:

880 записей в секунду
84 КиБ в секунду

84 КиБ/с — ничтожная нагрузка для современного диска. Однако, если смотреть только на throughput, можно решить, что логирование не способно влиять на производительность.

Но 880 записей в секунду означают 880 повторяющихся наборов работы:

отформатировать сообщение;
сформировать поля и префиксы;
выполнить маршрутизацию по каналам;
поместить запись в асинхронную очередь;
синхронизировать producer и worker;
при необходимости разбудить или запланировать worker;
собрать буферы в batch и выполнить запись;
обновить состояние файлового менеджера.

В результате write(), mutex, condition variables и операции с памятью появились в CPU-профиле, несмотря на небольшой общий объём данных.

В этом случае сортировка по records была не менее важна, чем сортировка по bytes.

Что менять после того, как профилирование источников логирования нашло горячую конструкцию

Профилирование источников логирования намеренно не решает, какие сообщения лишние. Это семантическое решение владельца приложения.

Подробная пошаговая трассировка интерпретатора может относиться к уровню DEBUG или к отдельному каналу, включаемому только на время диагностики. Полный дамп payload может требовать специального диагностического флага. Повторяющийся маркер вроде "." или "done" иногда не несёт пользы вовсе. Ожидаемое высокочастотное состояние может нуждаться в агрегации, collapse или rate limiting.

С сообщениями уровня ERROR нужно быть осторожнее. В том же профиле несколько error-sites срабатывали тысячи раз. Нельзя понижать их уровень только потому, что они частые. Сначала нужно определить, обозначают ли они настоящую повторяющуюся ошибку или ожидаемый fallback, которому ошибочно присвоили высокий уровень. Исправлением может быть логирование перехода состояния, дедупликация или устранение самой ошибки.

В конечном счёте цель не в уничтожении логов. Каждая диагностическая запись должна оправдывать свою стоимость.

Почему профилирование источников логирования должно находиться внутри библиотеки

Обычный CPU-профайлер видит функции и системные вызовы. Внешний монитор файлов видит пути и объём записи. Ни один из них не имеет достаточного контекста, чтобы восстановить одновременно call site, маршрутизацию каналов, fan-out backend и поведение асинхронной очереди.

Между тем этой информацией уже владеет сама библиотека логирования. Она знает:

кэш конкретной конструкции;
файл, функцию, строку, уровень и шаблон формата;
исходный и конечный каналы;
какой backend принял запись;
размер после форматирования backend;
приняла или отбросила запись асинхронная файловая очередь;
как worker группировал и записывал batch.

Следовательно, включаемая по требованию атрибуция на этих границах даёт гораздо более полезный профиль, чем выборка конечного write().

При этом функция должна оставаться необязательной. Производственная библиотека логирования не должна постоянно навязывать приложениям стоимость профилирования. Поэтому активный collector выбирается через nullable atomic pointer, конструкции регистрируются лениво, а счётчики не работают до явного включения.

Доступ к функции можно отдельно ограничивать через ControlPolicy::AllowLogStatistics, как и остальные операции runtime-control.

Практический алгоритм профилирования источников логирования

Когда логирование оказывается высоко в профиле, я теперь использую такую последовательность:

1. Сначала устранить очевидный busy loop или другой доминирующий дефект.
2. Снять logstat в простое.
3. Снять logstat под характерной рабочей нагрузкой.
4. Через backends найти главный канал/backend.
5. Через outputs, отсортированный по bytes, найти крупные источники.
6. Через outputs, отсортированный по records, найти частые источники.
7. Через files проверить batching, ошибки записи и потери очереди.
8. Изменять только ответственные конструкции или политики.
9. Повторить тот же интервал и сравнить скорости.

Такой подход безопаснее, чем глобально отключать логирование, и создаёт проверяемые данные для code review.

Заключение: профилирование источников логирования вместо отключения диагностики

В заключение: горячий файловый backend — это ещё не диагноз. Это конечная точка цепочки, которая начинается в отдельных строках исходного кода.

В описанном сервисе несколько подробных сообщений вычисления политик породили более половины файлового вывода. Ещё одна небольшая группа сетевой диагностики создала значительную часть остатка. Общий поток байтов был невелик, но сервис формировал около 880 отдельных записей в секунду.

Без атрибуции естественной реакцией было бы обвинить всю подсистему логирования. С ней проблема превратилась в конкретный список файлов, функций, строк, уровней, каналов, частот и объёмов.

Именно в этом состоит разница между отключением диагностики и её улучшением.

Исходный код и документация доступны в репозитории logme. Дополнительные материалы о библиотеке собраны в разделе Logme, а справочник по командам и рабочим сценариям находится в документации профилировщика.

Tags:logging, logme

Добавить комментарий Отменить ответ

Для отправки комментария вам необходимо авторизоваться.