Go: трассировочный пакет

ℹ️ В статье речь идёт о Go 1.13.

В Go имеется инструмент для проведения трассировки и получения подробного представления о работе программы во время её выполнения. Он активируется с помощью флага -trace с тестами из pprof для проведения трассировки в режиме реального времени или в любом месте кода благодаря пакету trace. Этот инструмент можно сделать ещё более мощным за счёт включения в него собственных трассировок. Посмотрим, как он работает.

Логика работы

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

Это даёт возможность Go впоследствии правильно составлять жизненный цикл каждой горутины. Вот последовательность действий на этом этапе:

Фаза инициализации перед трассировкой

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

Трассировка: сбор событий на P

Теперь трассировщику нужно как-то сформировать дамп этих трассировок. Для этого при запуске трассировки Go создаёт горутину. Эта горутина формирует дамп данных по мере готовности и приостанавливается в ожидании следующих трассировок. Вот как всё это выглядит:

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

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

Трассировки

После того как трассировка сгенерирована, можно сделать её визуализацию. Для этого используем команду go tool trace my-output.out. В качестве примера возьмём несколько трассировок:

Трассировки из go tool

Большинство из них очень простые. Трассировки, связанные со сборщиком мусора, обозначены синим GC:

Трассировки сборщика мусора

Попробуем в них разобраться:

STW — это две фазы «остановки мира» в сборщике мусора. Здесь горутины останавливаются;
GC (idle) — это горутины, которые помечают память, когда у них нет работы;
MARK ASSIST — это горутины, которые помогают помечать память во время её выделения;
GXX runtime.bgsweep — это фаза очистки памяти после завершения работы сборщика мусора;
GXX runtime.gcBgMarkWorker — это выделенные фоновые горутины, которые помогают помечать память.

Но есть трассировки, в которых разобраться совсем нелегко. Рассмотрим некоторые из них:

proc start вызывается, когда процессор связан с потоком. Это происходит при запуске нового потока или при выходе из системного вызова;

proc stop вызывается, когда поток не связан с текущим процессором. Это происходит при блокировании потока в системном вызове или при завершении потока;

syscall вызывается, когда горутина выполняет системный вызов;

unblock вызывается, когда горутина разблокирована от системного вызова — в этом случае от блокированного канала придёт пометка (sysexit) и т.д.:

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

Пользовательские трассировки

Трассировки, которые мы можем определять, имеют два иерархических уровня:

верхний уровень с задачей, началом и концом;
подуровень с регионом.

Вот простой пример:

func main() {
	ctx, task := trace.NewTask(context.Background(), "main start")

	var wg sync.WaitGroup
	wg.Add(2)

	go func() {
		defer wg.Done()
		r := trace.StartRegion(ctx, "reading file")
		defer r.End()

		ioutil.ReadFile(`n1.txt`)
	}()

	go func() {
		defer wg.Done()
		r := trace.StartRegion(ctx, "writing file")
		defer r.End()

		ioutil.WriteFile(`n2.txt`, []byte(`42`), 0644)
	}()

	wg.Wait()

	defer task.End()
}

Эти новые трассировки можно визуализировать прямо из инструмента для проведения трассировки go tool через меню User-defined tasks (задачи, определённые пользователем):

Пользовательские задачи и регионы

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

ctx, task := trace.NewTask(context.Background(), "main start")
trace.Log(ctx, "category", "I/O file")
trace.Log(ctx, "goroutine", "2")

Эти логи окажутся в горутине, занимающейся настройкой задачи:

Пользовательские логи в трассировке

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

Влияние на производительность

Понять влияние трассировок на производительность может помочь простой бенчмарк-тест. Один запустится с флагом -trace, а другой без флага. Вот какие результаты даёт бенчмарк-тест функции ioutil.ReadFile() с большим количеством событий:

name         time/op
ReadFiles-8  48.1µs ± 0%

name         time/op
ReadFiles-8  63.5µs ± 0%  // с трассировкой

Здесь влияние составляет приблизительно 35% и может варьироваться в зависимости от приложения. Однако существуют инструменты, такие как StackDriver, которые позволяют проводить непрерывное профилирование на продакшене, сохраняя при этом расход вычислительных ресурсов в приложении на невысоком уровне.

Перевод статьи Vincent Blanchon: Go: Discovery of the Trace Package

Поделиться статьей:

Вернуться к статьям

Go: трассировочный пакет

Логика работы

Трассировки

Пользовательские трассировки

Влияние на производительность

Комментарии