Содержание урока · 10 разделов
- Почему zerolog быстрый: буфер вместо структур
- Disabled и nil-событие: цена горячего пути
- Bool-хелперы и Enabled(): дорогие поля под контролем
- Приёмы горячего пути одним списком
- Как мерить самому: b.Run и -benchmem
- Стоимость события zerolog (бенчмарки README)
- Что дальше по курсу
- Песочница урока
- Коротко: что запомнить
- Вопросы и ответы
Логгер на горячем пути — это сотни тысяч событий в секунду, и каждая аллокация в них платит дважды: памятью под объект и работой сборщика мусора, который потом всё это собирает. Отсюда правило быстрого логирования: цена записи должна быть не «маленькой», а предсказуемой и не зависящей от нагрузки. Быстрое логирование в zerolog устроено ровно так: событие — это байтовый буфер, который переиспользуется, поля дописываются в него без промежуточных структур, а writer получает готовую JSON-строку одним вызовом. GC-давление от логов исчезает не потому, что записи стали дешевле по наносекундам, а потому, что их вклад в общую кучу равен нулю. Второй эффект тише, но заметнее: хвост задержек. Аллокации размазаны по времени выполнения, и сборщик мусора отвечает за пики, на которых p95 подпрыгивает без видимой причины — лог без аллокаций из этого уравнения уходит. В этом уроке разберём механику, посмотрим на цифры из бенчмарков и — главное — на приёмы горячего пути: Disabled, nil-событие, guard через Enabled() и Bool-хелперы. И научимся мерить самостоятельно, потому что чужие цифры — это ориентир, а не гарантия: на вашем железе они будут другими.
Почему zerolog быстрый: буфер вместо структур#
Под капотом каждого события — sync.Pool. Внутренний eventPool раздаёт структуры Event с байтовым буфером: поля дописываются в буфер сразу как JSON-байты — Str пишет строку с кавычками и экранированием, Int — число, — и никакой промежуточной карты или дерева полей не существует. Контекст логгера, собранный через With, хранится как готовые байты и приписывается к событию копированием, поэтому копия логгера с десятью предзаданными полями почти ничего не добавляет к цене записи. После Msg буфер уходит writer-у одним вызовом Write, а Event возвращается в пул для следующего события. Возврат не безусловный: буфер, разросшийся свыше шестидесяти четырёх килобайт, в пул не возвращается — гигантский дамп одним событием портит переиспользование, и zerolog просто выбрасывает его GC-у. Контраст со старым поколением логгеров разительный: logrus на каждое событие строит карту, считает рефлексией и форматирует текст — README-бенчмарки zerolog показывают на десять полей разницу в разы и на десятки аллокаций. Отсюда же и ограничения: типизированные методы Str и Int не случайны — Any с произвольным интерфейсом идёт через json.Marshal и стоит дороже, поэтому на горячем пути поля должны быть типизированными, а карта полей map[string]interface{} — исключением. Time и Dur тоже пишут числа сами, без общего маршалера: типизация — не стиль, а прямой путь мимо json.Marshal.
Бенчмарк с b.Run: включено и отключено
GOpackage perf
import (
"io"
"testing"
"github.com/rs/zerolog"
)
func BenchmarkHotPath(b *testing.B) {
logger := zerolog.New(io.Discard)
quiet := logger.Level(zerolog.Disabled)
b.Run("info", func(b *testing.B) {
for i := 0; i < b.N; i++ {
logger.Info().Str("op", "scan").Msg("tick")
}
})
b.Run("disabled", func(b *testing.B) {
for i := 0; i < b.N; i++ {
quiet.Info().Str("op", "scan").Msg("tick")
}
})
}
// go test -bench . -benchmemb.Run разбивает бенчмарк на подслучаи, и вывод покажет оба сценария рядом. Приёмник io.Discard выбрасывает байты: меряется именно цена сборки события, а не диск. Флаг -benchmem добавит B/op и allocs/op — на стандартном пути zerolog даст ноль аллокаций, а ветка disabled покажет, сколько стоит вызов на отключённом логгере.
Цифры из README zerolog — ориентир для порядка величин, а не обещание. BenchmarkDisabled: 4.07 наносекунды на событие и ноль аллокаций — отключённый логгер почти ничего не стоит. Пустое событие без полей — 19.1 ns/op, Info с сообщением — 42.5, Info с четырьмя полями — 184: поля добавляют десятки наносекунд каждая, но аллокаций всё ещё ноль. Ещё две строки той же таблицы: запись с логгером, у которого десять полей уже в контексте, — 52 ns/op и ноль аллокаций; статичная строка без полей — 50. Предзаданные поля хранятся готовыми байтами и почти ничего не добавляют. В сравнении zap-бенчмарка «сообщение и 10 полей» zerolog пишет 767 ns/op при 552 B/op и 6 аллокациях — сюда входит форматирование времени, — zap показывает 848 ns/op и 2 аллокации, sugared-zap 1363 ns/op и 20, а logrus 5661 ns/op и 78. Эти числа сняты на чужой машине чужой версии Go, поэтому трактовать их надо так: разница между логгерами — множители, разница между включённым и Disabled — два порядка, и именно второй факт влияет на дизайн горячего пути. zap — отличный логгер, и в большинстве сервисов разница не видна; zerolog выигрывает там, где события пишутся на каждом тике.
Disabled и nil-событие: цена горячего пути#
Порог Disabled — не «очень высокий уровень», а самый верхний из восьми: метод should сначала проверяет nil-writer и сравнивает уровень события с порогом — локальным и глобальным, — и на Disabled не проходит ни один вызов. Инфо-цепочка на отключённом логгере возвращает nil-событие, и вся остальная цепочка становится no-op: Str на nil возвращает nil, Msg на nil просто выходит. Отсюда 4 наносекунды из бенчмарка — цена нескольких сравнений. Включается режим копией: quiet := logger.Level(zerolog.Disabled), — и value-семантика делает это безопасным: базовый логгер продолжает писать как раньше. Это отличие от SetGlobalLevel(zerolog.Disabled), глушащего все логгеры разом: копия отключает один путь, глобальный порог — весь сервис. Полезное следствие — код горячего пути не нуждается в if вокруг каждой записи: debug-трассы можно оставлять в коде, а глушить уровнем, переключая копию при старте или по сигналу. Для тестов есть zerolog.Nop() — отключённый логгер одним вызовом. И следствие обратное: nil-событие экономит запись и сериализацию, но не ваш код вокруг цепочки — об этом «живое место» ниже.
Вызов logger.Debug().Str("dump", buildDump()).Msg("x") на отключённом логгере всё равно вызывает buildDump() — Go вычисляет аргументы до вызова Str, даже если Str на nil-событии ничего не сделает. nil-событие экономит запись в writer и сериализацию, но не вашу дорогую работу: дамп конфига, сериализацию прото-сообщения, обход дерева. На проде с Info-порогом такие debug-строки умножают CPU на ноль полезного результата. Лечится guard-ом if e := logger.Debug(); e.Enabled() { ... } — он защищает и запись, и вычисление аргументов. Диагностика проста: поставьте счётчик внутрь buildDump и посмотрите на график под нагрузкой — если счётчик растёт на Info-пороге, guard где-то забыт. Тот же счётчик показывает и обратное: на Debug-пороге он обязан расти — если нет, guard стоит слишком высоко, и полезная ветка отключила сама себя.
Bool-хелперы и Enabled(): дорогие поля под контролем#
Guard из «живого места» — это Event.Enabled(): метод возвращает false у nil-события, и форма if e := logger.Debug(); e.Enabled() стала идиомой zerolog. Дорогая работа прячется внутрь условия целиком — и поля, и вычисления. Для флагов есть.Bool(key, b): один типизированный вызов вместо условных конструкций «если флаг — писать поле, иначе не писать», и событие всегда имеет одинаковую схему, что ценят дашборды; приёмы условных полей разобраны в уроке про условные поля. Время тоже стоит денег: RFC3339-строка форматируется каждый вызов, а zerolog.TimeFieldFormat = zerolog.TimeFormatUnix пишет целое число секунд — дешевле, и системе сбора так же удобно. По той же логике целые миллисекунды для Dur включаются флагом DurationFieldInteger, а точность дробных полей подрезает zerolog.FloatingPointPrecision — оба меняют формат, не трогая код записи. И контраст с ConsoleWriter: там на каждую запись идёт json.Unmarshal для колонок — на горячем пути он съедает весь выигрыш, поэтому его место строго в dev, как разобрано в уроке про красивый вывод.
Приёмы горячего пути одним списком#
- один логгер, общие поля в контексте With — собираются один раз, а не на каждом событии
- горячий путь — копия .Level(zerolog.Disabled): 4 наносекунды и ноль аллокаций на событие
- дорогие поля — только под guard if e := logger.Debug(); e.Enabled()
- флаги — Bool(key, b): одна схема события без условных цепочек
- время — zerolog.TimeFieldFormat = zerolog.TimeFormatUnix: целое дешевле RFC3339-строки
- ConsoleWriter — только dev: Unmarshal каждой записи съедает выигрыш
- шумные ветки — семплер из следующего урока, а не ручные счётчики
- замер — go test -bench . -benchmem на своём железе, чужие цифры — только ориентир
Guard вокруг дорогих полей
GOfunc planScan(root string, logger zerolog.Logger) {
if e := logger.Debug(); e.Enabled() {
e.Str("root", root).
Int("files", countFiles(root)).
Msg("scan planned")
}
logger.Info().Bool("cached", root == lastRoot).Msg("scan scheduled")
}Guard вокруг дорогих полей: countFiles вызывается только когда debug включён — nil-событие не спасает аргументы, а Enabled() спасает. Флаг cached пишется Bool-хелпером одним вызовом, и схема события одинакова для каждой записи. Форма if с инициализацией ограничивает e телом условия: записать что-то мимо guard-а случайно невозможно.
Как мерить самому: b.Run и -benchmem#
Бенчмарк из урока — шаблон, который стоит скопировать. Три правила честного замера. Первое: sink — io.Discard, иначе вы меряете диск и терминал, а не логгер; если нужен writer с реальным форматированием времени — оставьте With().Timestamp(), но сравнивайте варианты на одинаковом логгере. Второе: -benchmem обязателен — наносекунды без аллокаций рассказывают половину истории, а GC-давление живёт именно в B/op и allocs/op. Третье: прогоняйте несколько раз и берите стабильные цифры — планировщик, кэши и соседние процессы дают разброс; -benchtime помогает, если ветки слишком короткие. Альтернатива флагу — b.ReportAllocs() внутри самой ветки b.Run: аллокации печатаются всегда, даже если коллега запустил бенчмарк без -benchmem. Сравнивайте только свои со своими: цифры README сняты на другой машине, и «в три раза быстрее» между логгерами на вашем железе может оказаться «на двадцать процентов». Отдельный приём — добавить в b.Run вариант с ConsoleWriter против чистого JSON: спор о читаемости против скорости решается за минуту, когда оба варианта стоят рядом в одном выводе. Тот же приём работает для уровней: Info и Debug рядом в одном бенчмарке дают точную цену debug-ветки на Info-пороге — наносекунды, о которых спорят в ревью.
Стоимость события zerolog (бенчмарки README)#
| Сценарий | Время | Аллокации |
|---|---|---|
| Отключённый логгер (Disabled) | 4.07 ns/op | 0 B / 0 allocs |
| Пустое событие Log().Msg("") | 19.1 ns/op | 0 B / 0 allocs |
| Info с сообщением | 42.5 ns/op | 0 B / 0 allocs |
| Info с четырьмя полями | 184 ns/op | 0 B / 0 allocs |
| Сообщение и 10 полей (zap-бенчмарк) | 767 ns/op | 552 B / 6 allocs |
| То же на logrus — для контраста | 5661 ns/op | 6092 B / 78 allocs |
Бенчмарки в песочнице не живут: песочница — тематическая программа на чистом Go, она собирает события в буфер и печатает JSON, чтобы механика полей была видна построчно. Замеры go test -bench . -benchmem идут локальным Go: цифры на вашем железе будут отличаться от README — и это нормально, сравнивайте только свои со своими.
Проверка: аллокации
Сколько аллокаций делает Info().Str(...).Msg(...) на стандартном пути zerolog?
Проверка: аргументы nil-события
Что происходит с buildDump() в вызове logger.Debug().Str("dump", buildDump()).Msg("x") на отключённом логгере?
Проверка: дорогой writer
Какой writer дороже всего на горячем пути?
Что выйдет на отключённом логгере?
Прочитайте код и выберите, что он выведет:
quiet := logger.Level(zerolog.Disabled)
quiet.Info().Str("op", "scan").Msg("tick")Поставьте guard
Восстановите идиому: событие, проверка и типизированное поле.
Программа с Disabled
Расставьте строки в правильном порядке: импорты, отключённый логгер и guard-нутая запись.
Строки
Ваша программа
Нажимайте на строки слева, чтобы собрать программу
Карточки: производительность
Что дальше по курсу#
Скорость — половина дела; вторая половина — объём. Sampling покажет, как прореживать поток, когда отключить нельзя: BurstSampler пропускает всплеск и режет хвост. Дальше — горутины: потокобезопасность логгера и то, почему ноль аллокаций не мешает писать из сотни воркеров одновременно. Приём из этого урока, который стоит забрать в каждый сервис: debug-записи живут в коде, а решает их судьбу порог — поэтому включение подробных логов на деградирующем инстансе не требует релиза, только смены уровня. Справочное закрепление: возьмите свой самый горячий обработчик, добавьте debug-запись с дорогим полем без guard-а и замерьте через b.Run-бенчмарк на Info-пороге — разница между guard-нутой и голой версией станет аргументом для ревью, который не нужно объяснять словами.
Песочница урока
Редактируйте код и запускайте его прямо здесь — интерпретатор работает в браузере, ничего устанавливать не нужно. За каждый запуск — +2 XP.
Запустите код, чтобы увидеть вывод.
Коротко: что запомнить
- Событие собирается в буфере из sync.Pool: ноль аллокаций на стандартном пути.
- Disabled — верхний порог: should отсекает событие до создания; копия .Level(zerolog.Disabled) стоит 4 ns/op.
- nil-событие делает цепочку no-op, но не отменяет вычисление аргументов.
- Guard if e := logger.Debug(); e.Enabled() защищает и запись, и дорогие поля.
- Bool(key, b) — флаги одной схемой события; условные цепочки ломают схему.
- TimeFormatUnix пишет время целым — дешевле RFC3339 при каждом вызове.
- ConsoleWriter на горячем пути съедает выигрыш: Unmarshal каждой записи.
- Чужие цифры — ориентир: замеряйте b.Run с -benchmem на своём железе.
Домашнее задание
Скопируйте бенчмарк урока, добавьте третий вариант b.Run с полями Str и Int — и сравните info против disabled против fields на своём железе. Возьмите свой горячий обработчик и поставьте в него debug-запись с дорогим полем без guard-а: замерьте, затем оберните в if e.Enabled() и замерьте снова — разницу запишите в PR. Переключите TimeFieldFormat на TimeFormatUnix и посмотрите на JSON: время стало целым. Наконец, добавьте в бенчмарк вариант с ConsoleWriter и убедитесь, что Unmarshal каждой записи виден в наносекундах даже на io.Discard. Сравните десять полей в контексте With против тех же полей на событии — разница ns/op покажет, что контекст собирается один раз.
Личные заметкиПусто
Вопросы и ответы по уроку
Почему zerolog не делает аллокаций?
Событие — это байтовый буфер из внутреннего sync.Pool: поля дописываются сразу как JSON-байты без промежуточных структур и рефлексии, буфер уходит writer-у одним Write и возвращается в пул. Контекст логгера хранится готовыми байтами и копируется в событие, поэтому предзаданные поля почти бесплатны. Исключение — дорогой Any с произвольным интерфейсом: он идёт через json.Marshal, и на горячем пути его заменяют типизированными методами.
Как полностью отключить логгер на горячем пути?
Копией с порогом Disabled: quiet := logger.Level(zerolog.Disabled). Сравнение уровня с порогом в should отказывает до создания события — 4 ns/op и ноль аллокаций. Для тестов есть zerolog.Nop(). Базовый логгер при этом продолжает писать: копия ничего не меняет у родителя.
Зачем Enabled(), если nil-событие и так no-op?
nil-событие отменяет запись и сериализацию, но Go вычисляет аргументы до вызова: buildDump() в Str("dump", buildDump()) выполнится всегда. Guard if e := logger.Debug(); e.Enabled() защищает и вычисление аргументов — это единственный способ не платить за дорогие debug-поля на Info-пороге.
Термины урока
Ключевые понятия из этого урока — короткие определения в глоссарии. Наведите на термин, чтобы вспомнить, откройте карточку для подробностей и ссылки на практику.
Изучайте дальше
Следующая ступень учебного пути
Валидация в Go: go-playground/validator
Курс validator для Go: теги required/min/max, email, dive, вложенные структуры, свои валидаторы, Gin и Echo, русские сообщения, тесты. 25 уроков.
- Валидировать структуры тегами binding и validate
- Понимать ValidationErrors и писать понятные сообщения
- Работать с вложенностью, срезами и картами через dive
- Писать свои функции-валидаторы и StructLevel-правила