Логгер в топе VTune: как найти строки, создающие нагрузку

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

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

libc.so.6!writeliblogme.so!Logme::FileIo::WriteRawliblogme.so!Logme::FileIo::WriteAllliblogme.so!Logme::FileBackend::WriteReadyDataliblogme.so!Logme::FileBackend::WorkerFuncliblogme.so!Logme::FileManager::ManagementThread

В подобных ситуациях быстро появляется простое решение: «логирование слишком дорогое — отключите его».

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

Сам стек файлового backend также не отвечает на главный вопрос:

Какая из тысяч конструкций вывода создала нагрузку?

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

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

Почему счётчика записанных байтов недостаточно

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

• одного большого payload в секунду;

• тысячи коротких сообщений;

• одной записи, размноженной через несколько связанных каналов;

• нескольких каналов с общим файлом;

• короткого burst, который worker ещё дописывает.

Для каждого случая требуется своё исправление.

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

Если проблема в одном большом дампе, увеличение batch также не поможет.

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

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

конструкция в исходном коде    -> исходный канал        -> конечный канал и backend            -> фактическая работа файлового worker

Кроме того, необходимо разделять две метрики:

• records — число сообщений;

• bytes — объём полностью сформированного вывода.

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

Что происходит, когда профилирование выключено

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

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

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

В специально дешёвом benchmark с NullBackend дополнительная стоимость скомпилированного, но выключенного профилировщика составила около 0,7 нс на принятый вызов по медиане. В реальном FileBackend, где присутствуют форматирование и очередь, такая разница теряется на фоне основной работы.

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

Почему списка исходных строк тоже недостаточно

Канал может иметь несколько backend или ссылаться на другой канал:

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

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

Поэтому появились отдельные отчёты:

logstat toplogstat channelslogstat outputslogstat backendslogstat files

• top показывает исходные сообщения до маршрутизации;

• channels агрегирует их по исходным каналам;

• outputs связывает конкретную строку кода с конечным backend после routing и fan-out;

• backends показывает нагрузку по парам «конечный канал + backend»;

• files описывает фактическую работу асинхронных файловых worker.

Последний отчёт содержит число принятых записей и байтов, количество batches и операций записи, успешно записанные байты, ошибки, средний размер batch и потери очереди.

Как выглядит рабочий сеанс

Профилирование источников логирования включается через существующий control server библиотеки:

PORT=7791logmectl -p "$PORT" logstat start# Здесь воспроизводим нормальную или проблемную нагрузку.sleep 60logmectl -p "$PORT" logstat stoplogmectl -p "$PORT" logstat backends \  --sort bytes \  --limit 20logmectl -p "$PORT" logstat outputs \  --backend FileBackend \  --sort bytes \  --limit 30logmectl -p "$PORT" logstat outputs \  --backend FileBackend \  --sort records \  --limit 30logmectl -p "$PORT" logstat files \  --sort written-bytes \  --limit 20

Обычно полезно снять минимум два интервала:

1. простой сервиса;

2. характерную рабочую нагрузку.

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

Что обнаружилось в реальном профиле

Сбор шёл 287,184 секунды. За это время файловые backend получили:

252 771 сообщение24 802 272 байта

В верхней части отчёта оказались четыре конструкции:

1. records=30107 output-bytes=2536226   Condition.cpp:137 GetValue   format: [line:%i col:%i] evaluating: %s2. records=30107 output-bytes=2483250   Calculator.cpp:590 Evaluate   format: Evaluate expression: %s3. records=30107 output-bytes=2117192   Calculator.cpp:680 Evaluate   format: %s is %s4. records=30107 output-bytes=1931391   Condition.cpp:176 GetValue   format: %s is %s

Самая интересная деталь — одинаковое значение records=30107.

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

Ещё около 15% дали сообщения событийной сетевой подсистемы:

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

В результате расплывчатая формулировка «логгер высоко в профайлере» превратилась в небольшой список файлов, функций и строк.

Диск здесь почти ни при чём

Если пересчитать результат, получится примерно:

880 сообщений в секунду84 КиБ в секунду

84 КиБ/с — практически ничего для современного диска. Однако 880 сообщений в секунду означают 880 повторений целой цепочки:

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

Поэтому в VTune были видны не только write(), но также mutex, condition variables и операции с памятью.

Именно по этой причине сортировка по records оказалась не менее важна, чем сортировка по bytes.

Что делать с найденными сообщениями

Сам профилировщик не должен автоматически решать, какой лог лишний.

Возможные действия зависят от смысла сообщения:

• подробную трассировку вычисления перевести в DEBUG;

• вынести её в отдельный канал, включаемый только во время расследования;

• дамп payload выполнять при специальном диагностическом флаге;

• одинаковые ожидаемые события агрегировать или ограничивать по частоте;

• бесполезные маркеры вроде "." и "done" удалить;

• для повторяющихся состояний логировать переход, а не каждую проверку.

С уровнем ERROR сложнее. Если сообщение встречается тысячи раз, нельзя автоматически понижать его до DEBUG. Сначала нужно понять, обозначает ли оно настоящую повторяющуюся ошибку или ожидаемый fallback, которому неправильно назначили уровень.

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

Почему это лучше делать внутри логгера

Внешний профайлер видит функцию write(). Монитор файлов видит имя файла и количество байтов. Только библиотека логирования одновременно знает:

• исходную строку кода;

• шаблон сообщения;

• уровень;

• маршрутизацию каналов;

• конечный backend;

• полный размер после форматирования;

• результат помещения в асинхронную очередь;

• batching и ошибки файлового worker.

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

Итоговый алгоритм

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

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

Это безопаснее, чем отключать подсистему логирования целиком.

В нашем случае несколько строк пошаговой трассировки создали больше половины файловой нагрузки. Без внутренней атрибуции мы знали бы только, что FileBackend::WorkerFunc заметен в VTune. После неё появились конкретные файлы, функции, строки, частоты и объёмы.

Именно это превращает «отключить логирование» в нормальную инженерную оптимизацию.

Исходный код профилировщика доступен в открытом проекте logme, а подробный справочник команд — на странице Log Source Profiling.

---

Расширенная версия статьи первоначально опубликована на Developer’s Tips. Этот URL следует использовать как адрес оригинального источника при повторной публикации.