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

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

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

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

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

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

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

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

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

Трассировки

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

Большинство из них очень простые. Трассировки, связанные со сборщиком мусора, обозначены синим 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, которые позволяют проводить непрерывное профилирование на продакшене, сохраняя при этом расход вычислительных ресурсов в приложении на невысоком уровне.