29.09.2025 10:30
python_leader 0 642 Источник

Команда Go for Devs подготовила перевод статьи о новом инструменте диагностики в Go 1.25 — flight recorder. Он позволяет заглянуть в последние секунды работы приложения уже после того, как произошла проблема, и точно понять, что случилось «под капотом». Отличный способ находить тонкие баги и задержки в долгоживущих сервисах без гигабайтов бесполезных трассировок.

В 2024 году мы представили миру более мощные трассировки выполнения Go. В той статье мы бегло рассказали о некоторых новых возможностях, которые можно было реализовать с помощью нашего нового трассировщика выполнения, включая Fligh Recorder. Мы рады объявить, что Fligh Recorder теперь доступен в Go 1.25 и является мощным новым инструментом в арсенале средств диагностики Go!

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

Сначала кратко напомним о трассировках выполнения Go.

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

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

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

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

Запись по принципу бортового самописца

Мы подошли к Fligh Recorder.

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

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

Пример

Давайте научимся использовать "бортовой самописец" (Fligh Recorder) на примере. В частности, применим его для диагностики проблемы производительности HTTP-сервера, реализующего игру "Угадай число". Сервер предоставляет эндпоинт /guess-number, который принимает целое число и сообщает вызывающей стороне, угадала ли она правильное число. Также имеется горутина, которая раз в минуту отправляет отчет обо всех угаданных числах другому сервису посредством HTTP-запроса.

// bucket — это простой счетчик, защищенный мьютексом.
type bucket struct {
    mu      sync.Mutex
    guesses int
}

func main() {
    // Создаем по одному bucket для каждого допустимого числа, которое может угадать клиент.
    // HTTP-обработчик будет находить bucket по угаданному числу,
    // используя это число как индекс среза.
    buckets := make([]bucket, 100)

    // Каждую минуту отправляем отчет о том, сколько раз каждое число было угадано.
    go func() {
        for range time.Tick(1 * time.Minute) {
            sendReport(buckets)
        }
    }()

    // Выбираем число, которое нужно угадать.
    answer := rand.Intn(len(buckets))

    http.HandleFunc("/guess-number", func(w http.ResponseWriter, r *http.Request) {
        start := time.Now()

        // Получаем число из параметра URL "guess" и конвертируем его в int.
        // Затем проверяем корректность значения.
        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
        }

        // Выбираем нужный bucket и безопасно увеличиваем его значение.
        b := &buckets[guess]
        b.mu.Lock()
        b.guesses++
        b.mu.Unlock()

        // Отправляем клиенту ответ с числом и информацией, правильно ли оно угадано.
        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 отправляет текущее состояние buckets на удаленный сервис.
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
    }

    // Сериализуем данные отчета в JSON.
    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

Прежде чем продолжить, уделите минуту и попробуйте найти проблему!

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

Сначала в main мы настроим и запустим Fligh Recorder:

// Настраиваем flight recorder
fr := trace.NewFlightRecorder(trace.FlightRecorderConfig{
    MinAge:   200 * time.Millisecond, // минимальная продолжительность события для записи
    MaxBytes: 1 << 20,                // максимальный размер буфера (1 МиБ)
})
fr.Start()

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

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

var once sync.Once

// captureSnapshot делает снимок (snapshot) данных flight recorder.
func captureSnapshot(fr *trace.FlightRecorder) {
    // once.Do гарантирует, что переданная функция будет выполнена только один раз.
    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() // игнорируем ошибку при закрытии

        // WriteTo записывает данные flight recorder в переданный io.Writer.
        _, err = fr.WriteTo(f)
        if err != nil {
            log.Printf("writing snapshot to file %s failed: %s", f.Name(), err)
            return
        }

        // Останавливаем flight recorder после создания снимка.
        fr.Stop()
        log.Printf("captured a flight recorder snapshot to %s", f.Name())
    })
}

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

// Создаем снимок (snapshot), если ответ занял больше 100 мс.
// Только первый вызов окажет эффект (остальные будут проигнорированы).
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, b := range buckets {
    b.mu.Lock()
    defer b.mu.Unlock()

    counts[index] = b.value
}

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

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

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

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

Русскоязычное Go сообщество

Друзья! Эту статью подготовила команда «Go for Devs» — сообщества, где мы делимся практическими кейсами, инструментами для разработчиков и свежими новостями из мира Go. Подписывайтесь, чтобы быть в курсе и ничего не упустить!

Комментарии (0)