Пакет runtime/trace содержит мощный инструмент для понимания программ Go и устранения неполадок. Функциональность внутри позволяет создавать трассировку исполнения каждой горутины за определенный период времени. С помощью go tool trace (или превосходного инструмента gotraceui с открытым исходным кодом) можно визуализировать и исследовать данные в этих трассировках.

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

Разработчики Go даже могут инструментировать свои собственные программы с помощью tasks, regions и logs, которые они могут использовать для корреляции своих высокоуровневых проблем с низкоуровневыми деталями выполнения.

Проблемы

К сожалению, огромное количество информации в трассировках может быть недоступно. Исторически этому мешали четыре большие проблемы.

• Трассировки имели высокие накладные расходы.

• Трассировки плохо масштабируются и могут стать слишком большими для анализа.

• Часто было неясно, когда начинать трассировку, чтобы зафиксировать конкретное неправильное поведение.

• Только самые смелые гоферы могли программно анализировать трассировки, учитывая отсутствие общедоступного пакета для анализа и интерпретации трассировок.

Если вы пользовались трассировками в последние несколько лет, то, скорее всего, вас расстраивала одна или несколько из этих проблем. Но мы рады поделиться тем, что за последние две версии Go мы добились большого прогресса во всех четырех этих областях.

Трассировка с низкими накладными расходами

До Go 1.21 накладные расходы на трассировку во время выполнения составляли 10-20% CPU для многих приложений, что ограничивало трассировку ситуативным использованием, а не постоянным, как при профилировании CPU. Оказалось, что большая часть затрат на трассировку приходится на трейсбеки(tracebacks). Многие события, создаваемые средой выполнения, содержат трассировку стека, что неоценимо для определения того, что горутины делали в ключевые моменты своего выполнения.

Благодаря работе Felix Geisendörfer и Nick Ripley над оптимизацией эффективности трейсбеков, накладные расходы процессора на трассировку значительно сократились, до 1-2% для многих приложений. Подробнее о проделанной работе вы можете прочитать в замечательном посте Феликса в блоге на эту тему.

Масштабируемые трассировки

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

Этот проблема, к сожалению, является фундаментальной для способа генерации трасс. Чтобы снизить накладные расходы во время выполнения, все события записываются в эквивалент локальных буферов потока(thread-local buffers). Но это означает, что события появляются не в своем истинном порядке, и на инструментарий трассировки ложится нагрузка по выяснению того, что произошло на самом деле.

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

Исправление всего этого потребовало переосмысления и переписывания многих основ реализации трассировки. Мы рады сообщить, что эта работа была завершена в Go 1.22 и теперь общедоступна. Появилось множество приятных улучшений, включая также некоторые улучшения в go tool trace command. Если вам интересно, все подробности описаны в проектном документе.

(Примечание: go tool trace по-прежнему загружает полную трассировку в память, но теперь можно снять это ограничение для трассировок, создаваемых программами Go 1.22+.)

Flight recording

Предположим, вы работаете над веб-сервисом, и RPC занимает очень много времени. Вы не могли начать трассировку в тот момент, когда уже знали, что RPC занимает много времени, потому что первопричина медленного запроса уже произошла и не была зафиксирована.

В этом может помочь технология под названием flight recording, с которой вы, возможно, уже знакомы по другим средам программирования. Суть flight recording в том, чтобы постоянно отслеживать и всегда сохранять самые последние данные трассировки, на всякий случай. Затем, как только произойдет что-то интересное, программа может просто записать все, что у нее есть!

До появления возможности разделения трасс это было практически невозможно. Но поскольку непрерывная трассировка стала жизнеспособной благодаря низким накладным расходам, а также тому факту, что время выполнения теперь может разделять трассы в любое время, оказалось, что реализовать flight recording проще простого.

В результате мы рады объявить об эксперименте с flight recorder, который доступен в golang.org/x/exp/trace.

Пожалуйста, попробуйте! Ниже приведен пример, который устанавливает flight recording для захвата долгого HTTP-запроса, чтобы вам было с чего начать.

// Set up the flight recorder.
fr := trace.NewFlightRecorder()
fr.Start()

// Set up and run an HTTP server.
var once sync.Once
http.HandleFunc("/my-endpoint", func(w http.ResponseWriter, r *http.Request) {
	start := time.Now()

	// Do the work...
	doWork(w, r)

	// We saw a long request. Take a snapshot!
	if time.Since(start) > 300*time.Millisecond {
		// Do it only once for simplicity, but you can take more than one.
		once.Do(func() {
			// Grab the snapshot.
			var b bytes.Buffer
			_, err = fr.WriteTo(&b)
			if err != nil {
				log.Print(err)
				return
			}
			// Write it to a file.
			if err := os.WriteFile("trace.out", b.Bytes(), 0o755); err != nil {
				log.Print(err)
				return
			}
		})
	}
})
log.Fatal(http.ListenAndServe(":8080", nil))

Если у вас есть какие-либо отзывы, положительные или отрицательные, пожалуйста, поделитесь ими в proposal issue!

Trace reader API

Вместе с переработкой реализации трассировки была предпринята попытка навести порядок в других внутренних компонентах, таких как go tool trace. Это породило попытку создать API для чтения трасс, который был бы достаточно хорош для совместного использования и мог бы сделать трассы более доступными.

Как и в случае с flight recorder, мы рады сообщить, что у нас также есть экспериментальный API для чтения трассировок, которым мы хотели бы поделиться. Он доступен в том же пакете, что и flight recorder, golang.org/x/exp/trace.

Мы считаем, что он достаточно хорош, чтобы начать строить на его основе что-то новое, так что, пожалуйста, попробуйте! Ниже приведен пример, который измеряет долю событий блокировки горутин, которые заблокированы для ожидания в сети.

// Start reading from STDIN.
r, err := trace.NewReader(os.Stdin)
if err != nil {
	log.Fatal(err)
}

var blocked int
var blockedOnNetwork int
for {
	// Read the event.
	ev, err := r.ReadEvent()
	if err == io.EOF {
		break
	} else if err != nil {
		log.Fatal(err)
	}

	// Process it.
	if ev.Kind() == trace.EventStateTransition {
		st := ev.StateTransition()
		if st.Resource.Kind == trace.ResourceGoroutine {
			id := st.Resource.Goroutine()
			from, to := st.GoroutineTransition()

			// Look for goroutines blocking, and count them.
			if from.Executing() && to == trace.GoWaiting {
				blocked++
				if strings.Contains(st.Reason, "network") {
					blockedOnNetwork++
				}
			}
		}
	}
}
// Print what we found.
p := 100 * float64(blockedOnNetwork) / float64(blocked)
fmt.Printf("%2.3f%% instances of goroutines blocking were to block on the network\n", p)

И точно так же, как с flight recorder, существует proposal issue для ваших отзывов!

Мы хотели бы особо отметить Dominik Honnef как человека, который опробовал его на ранних этапах, предоставил отличные отзывы и внес свой вклад в поддержку старых версий API.

Спасибо!

Эта работа была завершена, в немалой степени, благодаря помощи тех, кто входит в рабочую группу диагностики, начатую более года назад в рамках сотрудничества заинтересованных сторон из всего сообщества Go и открытую для общественности.

Мы хотели бы воспользоваться моментом, чтобы поблагодарить тех членов сообщества, которые регулярно посещали собрания в течение последнего года: Felix Geisendörfer, Nick Ripley, Rhys Hiltner, Dominik Honnef, Bryan Boreham, thepudds.

Обсуждения, отзывы и работа, которую вы все проделали, помогли нам достичь того уровня, на котором мы находимся сейчас. Спасибо!