Flight Recorder: Новый трассировщик выполнения Go

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

Трассировки выполнения

Сначала краткий обзор трассировок выполнения Go.

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

\ Пакет runtime/trace предоставляет API для сбора трассировки выполнения в течение заданного временного окна путем вызова runtime/trace.Start и runtime/trace.Stop. Это хорошо работает, если код, который вы трассируете, является просто тестом, микробенчмарком или инструментом командной строки. Вы можете собрать трассировку полного сквозного выполнения или только тех частей, которые вас интересуют.

\ Однако в долго работающих веб-сервисах, тех типах приложений, для которых известен Go, этого недостаточно. Веб-серверы могут работать днями или даже неделями, и сбор трассировки всего выполнения привел бы к слишком большому объему данных для просеивания. Часто только одна часть выполнения программы идет не так, например, истекает время ожидания запроса или не проходит проверка работоспособности. К тому времени, когда это происходит, уже слишком поздно вызывать Start!

\ Один из способов решения этой проблемы - случайно выбирать трассировки выполнения по всему флоту. Хотя этот подход мощный и может помочь найти проблемы до того, как они станут сбоями, он требует много инфраструктуры для начала работы. Большие объемы данных трассировки выполнения нужно будет хранить, сортировать и обрабатывать, большая часть которых вообще не будет содержать ничего интересного. И когда вы пытаетесь добраться до сути конкретной проблемы, это не подходит.

Запись полета

Это приводит нас к регистратору полета.

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

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

Пример

Давайте научимся использовать регистратор полета на примере. В частности, давайте используем его для диагностики проблемы с производительностью HTTP-сервера, который реализует игру "угадай число". Он предоставляет конечную точку /guess-number, которая принимает целое число и отвечает вызывающему, сообщая, угадали ли они правильное число.

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

// bucket is a simple mutex-protected counter. type bucket struct { mu sync.Mutex guesses int } func main() { // Make one bucket for each valid number a client could guess. // The HTTP handler will look up the guessed number in buckets by // using the number as an index into the slice. buckets := make([]bucket, 100) // Every minute, we send a report of how many times each number was guessed. go func() { for range time.Tick(1 * time.Minute) { sendReport(buckets) } }() // Choose the number to be guessed. answer := rand.Intn(len(buckets)) http.HandleFunc("/guess-number", func(w http.ResponseWriter, r *http.Request) { start := time.Now() // Fetch the number from the URL query variable "guess" and convert it // to an integer. Then, validate it. guess, err := strconv.Atoi(r.URL.Query().Get("guess")) if err != nil || !(0 <= guess && guess < len(buckets)) { http.Error(w, "invalid 'guess' value", http.StatusBadRequest) return } // Select the appropriate bucket and safely increment its value. b := &buckets[guess] b.mu.Lock() b.guesses++ b.mu.Unlock() // Respond to the client with the guess and whether it was correct. fmt.Fprintf(w, "guess: %d, correct: %t", guess, guess == answer) log.Printf("HTTP request: endpoint=/guess-number guess=%d duration=%s", guess, time.Since(start)) }) log.Fatal(http.ListenAndServe(":8090", nil)) } // sendReport posts the current state of buckets to a remote service. func sendReport(buckets []bucket) { counts := make([]int, len(buckets)) for index := range buckets { b := &buckets[index] b.mu.Lock() defer b.mu.Unlock() counts[index] = b.guesses } // Marshal the report data into a JSON payload. b, err := json.Marshal(counts) if err != nil { log.Printf("failed to marshal report data: error=%s", err) return } url := "http://localhost:8091/guess-number-report" if _, err := http.Post(url, "application/json", bytes.NewReader(b)); err != nil { log.Printf("failed to send report: %s", err) } }

Вот полный код для сервера: https://go.dev/play/p/rX1eyKtVglF, и для простого клиента: https://go.dev/play/p/2PjQ-1ORPiw. Чтобы избежать третьего процесса, "клиент" также реализует сервер отчетов, хотя в реальной системе это было бы отдельно.

\ Предположим, что после развертывания приложения в производстве мы получили жалобы от пользователей, что некоторые вызовы /guess-number занимают больше времени, чем ожидалось. Когда мы смотрим на наши логи, мы видим, что иногда время ответа превышает 100 миллисекунд, в то время как большинство вызовов занимает порядка микросекунд.

2025/09/19 16:52:02 HTTP request: endpoint=/guess-number guess=69 duration=625ns 2025/09/19 16:52:02 HTTP request: endpoint=/guess-number guess=62 duration=458ns 2025/09/19 16:52:02 HTTP request: endpoint=/guess-number guess=42 duration=1.417µs 2025/09/19 16:52:02 HTTP request: endpoint=/guess-number guess=86 duration=115.186167ms 2025/09/19 16:52:02 HTTP request: endpoint=/guess-number guess=0 duration=127.993375ms

Прежде чем продолжить, потратьте минуту и посмотрите, сможете ли вы обнаружить, что не так!

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

\ Сначала в main мы настроим и запустим регистратор полета:

// Set up the flight recorder fr := trace.NewFlightRecorder(trace.FlightRecorderConfig{ MinAge: 200 * time.Millisecond, MaxBytes: 1 << 20, // 1 MiB }) fr.Start()

MinAge настраивает продолжительность, в течение которой данные трассировки надежно сохраняются, и мы предлагаем установить ее примерно в 2 раза больше временного окна события. Например, если вы отлаживаете 5-секундный тайм-аут, установите его на 10 секунд. MaxBytes настраивает размер буферизованной трассировки, чтобы вы не исчерпали память. В среднем можно ожидать, что несколько МБ данных трассировки будет производиться в секунду выполнения, или 10 МБ/с для загруженного сервиса.

\ Далее мы добавим вспомогательную функцию для захвата снимка и записи его в файл:

var once sync.Once // captureSnapshot captures a flight recorder snapshot. func captureSnapshot(fr *trace.FlightRecorder) { // once.Do ensures that the provided function is executed only once. once.Do(func() { f, err := os.Create("snapshot.trace") if err != nil { log.Printf("opening snapshot file %s failed: %s", f.Name(), err) return } defer f.Close() // ignore error // WriteTo writes the flight recorder data to the provided io.Writer. _, err = fr.WriteTo(f) if err != nil { log.Printf("writing snapshot to file %s failed: %s", f.Name(), err) return } // Stop the flight recorder after the snapshot has been taken. fr.Stop() log.Printf("captured a flight recorder snapshot to %s", f.Name()) }) }

\ И наконец, непосредственно перед логированием завершенного запроса, мы запустим снимок, если запрос занял более 100 миллисекунд:

// Capture a snapshot if the response takes more than 100ms. // Only the first call has any effect. if fr.Enabled() && time.Since(start) > 100*time.Millisecond { go captureSnapshot(fr) }

\ Вот полный код для сервера, теперь инструментированный с регистратором полета: https://go.dev/play/p/3V33gfIpmjG

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

\ После того, как мы получили трассировку, нам понадобится инструмент, который поможет нам ее изучить. Инструментарий Go предоставляет встроенный инструмент анализа трассировки выполнения через команду go tool trace. Запустите go tool trace snapshot.trace, чтобы запустить инструмент, который запускает локальный веб-сервер, затем откройте отображаемый URL в вашем браузере (если инструмент не открывает ваш браузер автоматически).

\ Этот инструмент дает нам несколько способов просмотра трассировки, но давайте сосредоточимся на визуализации трассировки, чтобы понять, что происходит. Нажмите "View trace by proc", чтобы сделать это.

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

\ Ниже, в разделе "PROCS", мы можем увидеть, как выполнение горутин отображается на GOMAXPROCS (количество потоков операционной системы, созданных приложением Go). Мы можем видеть, когда и как каждая горутина запускается, выполняется и, наконец, прекращает выполнение.

\ Пока что давайте обратим внимание на этот огромный пробел в выполнении в правой части просмотрщика. В течение некоторого времени, около 100 мс, ничего не происходит!

Выбрав инструмент zoom (или нажав 3), мы можем более подробно изучить раздел трассировки сразу после пробела.

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

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

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

\ Что произошло, когда эта горутина выполнялась? Часть информации, хранящейся в трассировке, - это просмотр трассировки стека в разные моменты времени. Когда мы смотрим на горутину, мы можем видеть, что начальная трассировка стека показывает, что она ожидала завершения HTTP-запроса, когда горутина была запланирована для выполнения. А конечная трассировка стека показывает, что функция sendReport уже вернулась, и она ожидала тикера для следующего запланированного времени отправки отчета.

\ Между началом и концом выполнения этой горутины мы видим огромное количество "исходящих потоков", где она взаимодействует с другими горутинами. Нажатие на одну из записей Outgoing flow приводит нас к просмотру взаимодействия.

\ Этот поток указывает на Unlock в sendReport:

for index := range buckets { b := &buckets[index] b.mu.Lock() defer b.mu.Unlock() counts[index] = b.guesses }

\ В sendReport мы намеревались получить блокировку на каждом ведре и освободить блокировку после копирования значения.

\ Но вот проблема: мы на самом деле не освобождаем блокировку сразу после копирования значения, содержащегося в bucket.guesses. Поскольку мы использовали оператор defer для освобождения блокировки, это освобождение не происходит до тех пор, пока функция не вернется. Мы удерживаем блокировку не только после окончания цикла, но и до завершения HTTP-запроса. Это тонкая ошибка, которую может быть трудно отследить в большой производственной системе.

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

\ Регистратор полета - это лишь последнее дополнение к набору инструментов разработчика Go для диагностики внутренней работы запущенных приложений. Мы постоянно улучшали трассировку в течение последних нескольких выпусков. Go 1.21 значительно снизил накладные расходы времени выполнения трассировки. Формат трассировки стал более надежным и также разделяемым в выпуске Go 1.22, что привело к таким функциям, как регистратор полета. Инструменты с открытым исходным кодом, такие как gotraceui, и предстоящая возможность программно анализировать трассировки выполнения - это еще больше способов использовать мощь трассировок выполнения. На странице Диагностики перечислены многие дополнительные инструменты в вашем распоряжении. Мы надеемся, что вы будете использовать их при написании и совершенствовании ваших приложений Go.

Благодарности

Мы хотели бы уделить момент, чтобы поблагодарить тех членов сообщества, которые были активны на встречах по диагностике, вносили вклад в дизайн и предоставляли обратную связь на протяжении многих лет: Felix Geisendörfer (@felixge.de), Nick Ripley (@nsrip-dd), Rhys Hiltner (@rhysh), Dominik Honnef (@dominikh), Bryan Boreham (@bboreham) и PJ Malloy (@thepudds).

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

---

Carlos Amedee и Michael Knyszek

\ Эта статья доступна на The Go Blog под лицензией CC BY 4.0 DEED.

\ Фото Lukas Souza на Unsplash

\