Модуль: Runtime и память · Уровень: Senior+

TL;DR#

runtime/trace (execution tracer) пишет поток событий планировщика, GC, syscalls и блокировок с наносекундными таймстампами — в отличие от pprof, который даёт агрегированную статистику. Он отвечает на вопрос «почему конкретная горутина простояла 8 мс именно в этот момент», а не «куда в среднем уходит CPU». С Go 1.21 трейсер переписан на низкооверхедный формат (snapshot-free, ~1-2% overhead), а Go 1.25 принёс trace.FlightRecorder — кольцевой буфер для post-mortem диагностики редких событий. Дополняется неинвазивной диагностикой через GODEBUG (gctrace, schedtrace, inittrace).

Теория#

Чем execution tracer отличается от pprof#

pprof — это семплирующий профайлер: раз в ~10 мс (CPU profile) snapshot стеков, потом агрегация. Он отвечает на «где горит CPU суммарно». Execution tracer — это event log: каждое значимое событие рантайма пишется в буфер с таймстампом, ничего не теряется и не усредняется.

Главное правило: pprof говорит ЧТО потребляет ресурс, tracer говорит ПОЧЕМУ и КОГДА что-то задержалось. Классический кейс для трейсера — хвостовые задержки (p99 latency), которые pprof не объясняет, потому что они вызваны не «горячим кодом», а планированием: горутина была runnable, но Р был занят, или попала под STW, или ждала syscall.

Сбор трейса: три способа#

1. Программно через runtime/trace:

package main

import (
	"os"
	"runtime/trace"
)

func main() {
	f, err := os.Create("trace.out")
	if err != nil {
		panic(err)
	}
	defer f.Close()

	if err := trace.Start(f); err != nil {
		panic(err)
	}
	defer trace.Stop()

	// ... рабочая нагрузка ...
}

2. Через тесты/бенчмарки:

go test -trace=trace.out -bench=. ./...

3. Через HTTP-эндпоинт (самый частый в проде):

import (
	"net/http"
	_ "net/http/pprof" // регистрирует /debug/pprof/* включая /trace
)

func main() {
	go func() {
		// ВАЖНО: эндпоинт даёт полный доступ к диагностике — закрывайте его
		// от внешнего мира (отдельный порт, mTLS, ACL).
		http.ListenAndServe("localhost:6060", nil)
	}()
	// ...
}

Снять трейс за 5 секунд:

curl -o trace.out 'http://localhost:6060/debug/pprof/trace?seconds=5'
go tool trace trace.out   # откроет браузер с UI

go tool trace: какие view и что в них искать#

go tool trace поднимает локальный веб-сервер. Ключевые разделы:

• View trace by proc / by thread — таймлайн событий по процессорам (P) или OS-потокам (M). Здесь видно, как горутины мигрируют между P, где STW-паузы (вся строка проваливается), где GC mark workers.
• Goroutine analysis — для каждого типа горутины разбивка времени: Execution, Scheduler wait (runnable, но не запущена — главный индикатор нехватки P/CPU), Sync block (каналы/мьютексы), Block syscall, GC sweeping, GC pause.
• Network blocking / Syscall blocking / Scheduler latency profiles — это flame-graph’ы, но построенные из событий трейса (можно скачать как pprof).
• User-defined tasks / regions — ваши собственные tasks/regions (см. ниже).
• Minimum mutator utilization (MMU) — кривая: какую долю CPU приложение реально отдаёт «полезной работе» (mutator) на окне заданной длины. Провал MMU = GC съедает CPU.

Что искать на senior-уровне:

• Длинные полосы Scheduler wait = недостаток P (GOMAXPROCS) или CPU throttling (cgroups в k8s).
• Регулярные узкие вертикальные провалы по всем P = STW GC паузы.
• Горутина блокируется на канале, в то время как producer спит = проблема backpressure.
• Много Syscall blocking + рост числа M = блокирующие syscalls плодят потоки.

User tasks / regions / log: связь домена с трейсом#

Трейсер сам по себе не знает про ваши «запросы». Аннотации связывают бизнес-логику с событиями рантайма.

import (
	"context"
	"runtime/trace"
)

func handleRequest(ctx context.Context, id string) error {
	// Task — логическая операция, может пересекать горутины,
	// привязана к context. Имеет начало и конец.
	ctx, task := trace.NewTask(ctx, "handleRequest")
	defer task.End()

	trace.Logf(ctx, "request", "id=%s", id) // событие-метка с категорией

	// Region — участок ВНУТРИ одной горутины (не пересекает границы).
	region := trace.StartRegion(ctx, "db.query")
	rows, err := queryDB(ctx)
	region.End()
	if err != nil {
		return err
	}

	// Идиома: defer-friendly region
	defer trace.StartRegion(ctx, "render").End()
	return render(rows)
}

Различия, которые любят спрашивать:

В go tool trace → User-defined tasks появляется распределение latency ваших задач, и можно кликнуть на самый медленный экземпляр, провалиться в его таймлайн и увидеть, на чём именно он стоял. trace.IsEnabled() позволяет не платить за форматирование, когда трейс выключен.

Overhead и переписанный трейсер (Go 1.21+)#

До 1.21 трейсер имел заметный overhead и неприятную особенность: при старте трейса делался STW-снапшот всех горутин, что давало паузу, растущую с числом горутин (проблема для сервисов с сотнями тысяч G). Формат был «монолитным» и плохо стримился/парсился.

Go 1.21 принёс переписанный трейсер (proposal #60773):

• Overhead снижен примерно до ~1-2% (раньше мог быть 10-20%+).
• Формат стал партиционированным (generations): трейс делится на самодостаточные куски, можно парсить потоково, без удержания всего файла в памяти.
• Убрана глобальная STW при старте на весь набор горутин — синхронизация per-P, паузы стали короткими и не зависящими от числа G.
• Появился публичный парсер golang.org/x/exp/trace (позже internal/trace v2), на котором и построен FlightRecorder.

Практический вывод: на современном Go execution tracing достаточно дёшев, чтобы держать его наготове в проде (особенно через flight recorder), а не только включать «когда уже всё сломалось».

GODEBUG: неинвазивная диагностика без перекомпиляции#

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

GODEBUG=gctrace=1,schedtrace=1000,inittrace=1 ./app

Полезные ключи:

Разбор строки gctrace=1 по полям#

Пример строки:

gc 42 @8.301s 3%: 0.018+1.2+0.004 ms clock, 0.29+0.51/2.1/0+0.064 ms cpu, 41->42->22 MB, 43 MB goal, 0 MB stacks, 0 MB globals, 16 P

Разбор каждого поля:

• gc 42 — порядковый номер цикла GC с момента старта программы.
• @8.301s — время от старта программы до начала этого цикла.
• 3% — суммарная доля CPU, потраченная на GC с момента старта (накопительно). Это тот самый GC CPU overhead; устойчивый рост к 25%+ — тревога (GC borrows до 25% CPU как hard limit мягко, плюс mark assist).
• 0.018+1.2+0.004 ms clock — wall-clock время по фазам:
  • 0.018 — STW sweep termination (завершение sweep предыдущего цикла, мир остановлен).
  • 1.2 — concurrent mark and scan (маркировка идёт параллельно с приложением).
  • 0.004 — STW mark termination (финальная остановка мира). Вот эти два STW-числа (первое и последнее) — и есть ваши GC-паузы. Здесь паузы ~0.022 мс суммарно — отлично.
• 0.29+0.51/2.1/0+0.064 ms cpu — CPU-время (суммарно по всем ядрам) по тем же фазам:
  • 0.29 — STW sweep termination CPU.
  • 0.51/2.1/0 — concurrent mark CPU, разбитое на: assist (mutator-горутины принудительно помогают GC, когда аллоцируют быстрее, чем GC успевает), background (выделенные GC-воркеры), idle (воркеры на простаивающих P). Большой assist = приложение аллоцирует слишком агрессивно и тормозит само себя.
  • 0.064 — STW mark termination CPU.
• 41->42->22 MB — heap в трёх точках: до GC (heap при старте mark, 41) → в пике на момент mark termination (42) → live heap после GC (22, выжившие объекты). Разница 42→22 = собранный мусор.
• 43 MB goal — целевой размер heap для триггера следующего GC, вычисляется как live * (1 + GOGC/100). При GOGC=100 и live=22 цель ~44 MB.
• 0 MB stacks — память под стеки горутин, просканированная GC.
• 0 MB globals — размер просканированных глобальных переменных.
• 16 P — число процессоров (GOMAXPROCS), участвовавших в этом GC.

Если строка заканчивается на (forced) — это GC, вызванный вручную через runtime.GC() или debug.FreeOSMemory().

Связь с GOGC и GOMEMLIMIT: goal напрямую зависит от GOGC. Если выставлен GOMEMLIMIT, рантайк может запускать GC чаще (goal искусственно снижается), чтобы не превысить лимит — в gctrace это видно как уменьшение goal и рост частоты gc#.

Разбор schedtrace#

SCHED 1003ms: gomaxprocs=8 idleprocs=6 threads=12 spinningthreads=1 idlethreads=4 runqueue=0 [0 0 1 0 0 0 0 0]

• gomaxprocs=8 — число P.
• idleprocs=6 — сколько P сейчас простаивают (нет работы). Много idle при «тормозит» = работа не параллелится.
• threads=12 — всего M (OS threads), созданных рантаймом.
• spinningthreads — M, активно ищущие работу (spinning перед сном).
• runqueue=0 — длина глобальной очереди runnable-горутин. Рост = голодание по P.
• [0 0 1 0 0 0 0 0] — длины локальных runqueue каждого P. Перекос (одна большая, остальные нули) = плохой work-stealing/локальность.

С scheddetail=1 каждая строка раскрывается до состояния каждого G/M/P (status, очереди, привязки).

Flight Recorder (Go 1.25): post-mortem трейсинг#

Проблема: редкое событие (раз в день p99.99 latency spike) поймать обычным трейсом нельзя — не знаешь, когда включать, а держать запись постоянно = терабайты. Решение — кольцевой буфер: трейсер пишет в память постоянно, но хранит только последние N секунд / M байт. Когда происходит «интересное» событие — снимаем содержимое буфера.

import (
	"os"
	"runtime/trace"
)

func main() {
	fr := trace.NewFlightRecorder(trace.FlightRecorderConfig{
		MinAge:   5 * time.Second, // хранить минимум столько недавней истории
		MaxBytes: 10 << 20,        // ограничение буфера
	})
	if err := fr.Start(); err != nil {
		panic(err)
	}
	defer fr.Stop()

	// ... работа; где-то в обработчике детектим аномалию ...
	if latency > slo {
		f, _ := os.Create("incident.trace")
		// WriteTo сбрасывает текущее содержимое кольцевого буфера на диск
		if _, err := fr.WriteTo(f); err != nil {
			log.Println(err)
		}
		f.Close()
	}
}

Ключевые свойства:

• Можно держать включённым в проде (overhead тот же ~1-2% низкооверхедного трейсера).
• WriteTo даёт валидный трейс-файл, открываемый обычным go tool trace.
• MinAge / MaxBytes — компромисс глубины истории против памяти; реально буфер хранит >= MinAge, но не больше MaxBytes.
• Идеален для записи «что было ДО» падения/спайка, чего обычный реактивный trace.Start не даёт.

До 1.25 этот паттерн делали руками поверх golang.org/x/exp/trace.FlightRecorder (экспериментальный API с ~Go 1.22).

Подводные камни / gotchas#

• /debug/pprof/trace без защиты = дыра. Эндпоинт раскрывает структуру выполнения и даёт нагрузку на сбор. Не вешайте net/http/pprof на публичный listener; используйте отдельный internal-порт.
• Объём трейса. Под высокой нагрузкой трейс растёт на мегабайты в секунду. seconds=60 на нагруженном сервисе = сотни МБ, которые go tool trace парсит в память. Снимайте короткие окна (2-5 сек).
• go tool trace и старые трейсы. Формат менялся (особенно в 1.21). Трейс, снятый на одной версии Go, корректно открывается соответствующей версией go tool trace. Не смешивайте.
• Regions не пересекают горутины. Если запустить StartRegion в одной горутине, а End() вызвать в другой — поведение некорректно. Для сквозной семантики используйте Task.
• allocfreetrace=1 парализует приложение — stacktrace на каждую аллокацию. Только на игрушечных нагрузках; в свежих версиях Go удалён.
• gctrace показывает накопительный CPU %, а не мгновенный. Низкий процент в начале и рост со временем — нормально для прогрева; смотрите тренд.
• madvdontneed и метрики RSS. На Linux Go по умолчанию использует MADV_FREE — освобождённая память остаётся в RSS, пока ОС не понадобится. Мониторинг по RSS «врёт», пока не выставите madvdontneed=1 (ценой производительности). Это частая причина ложных алертов «утечка памяти».
• Трейс не заменяет pprof. Для «куда уходит CPU суммарно» трейс неудобен и дорог — это работа CPU-профайла. Инструменты комплементарны.
• Включённый трейсер влияет на тайминги. Хоть overhead и мал, в микробенчмарках он искажает результаты; не трейсьте то, что измеряете на наносекундах.

Вопросы на собеседовании#

В: Когда execution tracer нужен, а pprof бессилен? О: Когда вопрос содержит «когда» и «почему задержалось», а не «сколько суммарно». pprof агрегирует и не имеет оси времени — он покажет горячие функции, но не объяснит хвостовую latency, вызванную планированием: горутина была runnable, но все P заняты (Scheduler wait), попала под STW-паузу GC, ждала разблокировки канала/мьютекса или висела в syscall. Трейсер пишет каждое такое событие с таймстампом, поэтому можно взять конкретный медленный запрос и увидеть его полный жизненный цикл по времени. Также только трейсер показывает поведение планировщика (миграция G между P, work-stealing, рост числа M) и пофазные тайминги GC.

В: Разберите строку gctrace: gc 5 @0.1s 1%: 0.02+0.5+0.01 ms clock, ... 4->5->2 MB, 8 MB goal, ... 8 P. О: Это 5-й цикл GC, начавшийся через 0.1с после старта; на GC ушёл 1% CPU накопительно. Тайминги clock — три фазы: STW sweep termination 0.02 мс, concurrent mark 0.5 мс, STW mark termination 0.01 мс; реальные паузы приложения — первое и последнее число (~0.03 мс суммарно). Heap: 4 МБ на старте mark, 5 МБ в пике на mark termination, 2 МБ живых объектов после сборки (собрано 3 МБ). Goal 8 МБ — порог триггера следующего GC, при GOGC=100 это примерно live*(1+GOGC/100) = 2*2 ≈ 4, но с учётом накладных и round-up рантайм взял 8. 8 P — столько процессоров участвовало.

В: Чем Task отличается от Region? О: Task — логическая сквозная операция (например, HTTP-запрос), которая может пересекать границы горутин и привязана к context.Context; создаётся trace.NewTask, имеет начало и task.End(). Region — это участок работы строго внутри одной горутины (фаза вроде «db.query»), не пересекает горутины, создаётся trace.StartRegion(ctx, ...). В UI Task даёт распределение latency операции и связь событий, разбросанных по горутинам; Region детализирует, на что ушло время внутри одной горутины. Log/Logf — точечные метки в потоке.

В: Что изменилось в трейсере в Go 1.21? О: Трейсер переписали: overhead упал примерно до 1-2% (раньше десятки процентов в плохих случаях); убрали глобальную STW-паузу при старте трейса, которая раньше росла с числом горутин (синхронизация стала per-P); формат стал партиционированным на самодостаточные generations, что позволяет потоковый парсинг без загрузки всего файла в память, и появился стабильный публичный парсер. Практическое следствие — трейсинг стал достаточно дёшев для постоянного использования в проде, на чём построен flight recorder.

В: Что такое FlightRecorder и зачем он, если есть trace.Start? О: trace.FlightRecorder (Go 1.25) — кольцевой буфер в памяти, в который трейсер пишет постоянно, храня только последние N секунд/M байт. trace.Start реактивен: чтобы поймать событие, надо знать момент заранее. Редкий спайк (p99.99 раз в сутки) так не поймать — а держать полную запись нельзя из-за объёма. FlightRecorder решает это: он всегда «крутится» с малым overhead, а когда код детектирует аномалию, вызывается WriteTo, сбрасывающий текущий буфер в валидный трейс-файл. Главное преимущество — он сохраняет то, что было ДО события, чего реактивный подход не даёт.

В: Сервис тормозит, idleprocs в schedtrace высокий, runqueue растёт. Диагноз? О: Противоречие кажущееся: высокий idleprocs (P простаивают) при растущей runqueue (есть готовые горутины) обычно означает, что горутины не могут попасть на P — например, из-за блокировок на общем мьютексе/канале (готовы, но сериализованы), либо из-за того, что горутины часто уходят в блокирующие syscalls и рантайм не успевает раскидать работу, либо CPU throttling в cgroups (P формально есть, но ядро не даёт квоту — рантайм видит P свободными, а реального CPU нет). Проверяю трейсом: Goroutine analysis покажет, где время — Sync block (мьютекс), Syscall block, или Scheduler wait. Если в k8s — сверяю GOMAXPROCS с CPU limit.

В: Почему RSS не падает после освобождения памяти, и при чём тут madvdontneed? О: На Linux рантайм Go по умолчанию отдаёт страницы ядру через MADV_FREE: страницы помечаются как освобождаемые, но ядро забирает их физически только под давлением памяти, поэтому RSS остаётся высоким. Это не утечка — память доступна ОС. Чтобы RSS отражал реальное потребление сразу, ставят GODEBUG=madvdontneed=1, переключая на MADV_DONTNEED (страницы возвращаются немедленно, ценой более дорогих будущих аллокаций). Частая причина ложных алертов про утечку при мониторинге по RSS.

В: Как снять трейс с прод-сервиса и на что смотреть в go tool trace? О: Через net/http/pprof на закрытом порту: curl -o t.out 'http://localhost:6060/debug/pprof/trace?seconds=3', окно короткое из-за объёма. Открываю go tool trace t.out. Смотрю: Goroutine analysis — разбивку времени по типам горутин (Execution vs Scheduler wait vs Sync/Syscall block); View by proc — STW-паузы (синхронные провалы по всем P) и миграции; MMU — не съедает ли GC мутатор; User tasks — распределение latency моих операций, проваливаюсь в самый медленный экземпляр и смотрю его таймлайн. Network/Syscall blocking профили скачиваю как pprof для flame-graph.

В: Что показывает inittrace=1 и зачем это на проде? О: Выводит по строке на каждый пакет: время выполнения его init() и сколько он нааллоцировал. Используется для диагностики медленного старта сервиса (важно для cold start, k8s readiness, FaaS) — часто оказывается, что какой-то пакет в init() читает конфиг/строит большие таблицы/коннектится к сети, раздувая время запуска. Это видно только так, потому что init выполняется до main и обычным профайлером не покрывается удобно.

На что копают на senior+#

• Модель данных трейсера. Понимаете ли вы, что это event log с per-P буферами, а не семплинг; почему отсюда берётся overhead и объём; что значит партиционирование на generations и почему оно убрало STW при старте.
• Фазы GC и их отражение в gctrace/трейсе. Sweep termination, concurrent mark, mark termination, что из них STW; что такое mark assist и почему рост assist — симптом избыточных аллокаций; связь goal с GOGC и GOMEMLIMIT.
• Pacer и тонкая настройка. Как GOGC/GOMEMLIMIT сдвигают goal и частоту GC, как это читать построчно в gctrace, когда GOMEMLIMIT приводит к death spiral (GC крутится постоянно у лимита).
• Планировщик через призму schedtrace/трейса. Состояния G, work-stealing, spinning threads, рост M из-за блокирующих syscalls, влияние cgroups CPU limit на восприятие GOMAXPROCS (и почему automaxprocs/GOMAXPROCS-by-default в 1.25 важны).
• Latency-аналитика по конкретной горутине. Способность взять p99-запрос, через user tasks провалиться в его таймлайн и атрибутировать задержку к scheduler wait / GC / блокировке, а не к коду.
• FlightRecorder в проде. Когда применять, как выбирать MinAge/MaxBytes, чем отличается от continuous profiling, как интегрировать с алертами/триггерами на SLO-нарушение.
• Комплементарность инструментов. Чёткое понимание, что pprof, execution trace, GODEBUG и runtime/metrics решают разные задачи, и умение выбрать правильный для конкретного симптома, а не «включить всё».
• Overhead-осознанность. Где трейсер искажает измерения, почему нельзя трейсить наносекундные бенчи, как оценить стоимость постоянного трейсинга для конкретного сервиса.