Перейти к содержимому
ГоМастер

Поиск по урокам

Найдите урок, курс, термин или раздел

Урок 13 из 25 ~18 мин +50 XP

Производительность: ноль аллокаций

Производительность zerolog держится на нуле аллокаций: событие собирается в переиспользуемый байтовый буфер и уходит writer-ом одним вызовом. Разберём, откуда берётся скорость, что стоит Disabled на горячем пути, как guard-ить дорогие поля и как мерить всё это b.Run-бенчмарками на своём железе.

Содержание урока · 10 разделов

Логгер на горячем пути — это сотни тысяч событий в секунду, и каждая аллокация в них платит дважды: памятью под объект и работой сборщика мусора, который потом всё это собирает. Отсюда правило быстрого логирования: цена записи должна быть не «маленькой», а предсказуемой и не зависящей от нагрузки. Быстрое логирование в 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: включено и отключено

GO
package 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 . -benchmem

b.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-событие экономит запись и сериализацию, но не ваш код вокруг цепочки — об этом «живое место» ниже.

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 вокруг дорогих полей

GO
func 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/op0 B / 0 allocs
Пустое событие Log().Msg("")19.1 ns/op0 B / 0 allocs
Info с сообщением42.5 ns/op0 B / 0 allocs
Info с четырьмя полями184 ns/op0 B / 0 allocs
Сообщение и 10 полей (zap-бенчмарк)767 ns/op552 B / 6 allocs
То же на logrus — для контраста5661 ns/op6092 B / 78 allocs

Проверка: аллокации

Сколько аллокаций делает 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

Восстановите идиому: событие, проверка и типизированное поле.

func scan(logger zerolog.Logger) { if e := logger.(); e.() { e.("dump", buildDump()).Msg("scan planned") } }

Программа с Disabled

Расставьте строки в правильном порядке: импорты, отключённый логгер и guard-нутая запись.

Строки

Ваша программа

Нажимайте на строки слева, чтобы собрать программу

Карточки: производительность

Термин

sync.Pool события

нажмите, чтобы перевернуть
Определение

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

1 / 6

Что дальше по курсу#

Скорость — половина дела; вторая половина — объём. 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 · Производительность: ноль аллокаций)

Вопросы и ответы по уроку

Почему 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-пороге.

Термины урока

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

Следующая ступень учебного пути

Validator25 уроков~11 чпрактика25 уроков уже доступны

Валидация в Go: go-playground/validator

Курс validator для Go: теги required/min/max, email, dive, вложенные структуры, свои валидаторы, Gin и Echo, русские сообщения, тесты. 25 уроков.

  • Валидировать структуры тегами binding и validate
  • Понимать ValidationErrors и писать понятные сообщения
  • Работать с вложенностью, срезами и картами через dive
  • Писать свои функции-валидаторы и StructLevel-правила