Gravador de Voo: Um Novo Traçador de Execução Go

Em 2024, apresentámos ao mundo rastreamentos de execução Go mais poderosos. Nesse post do blog, demos uma amostra de algumas das novas funcionalidades que poderíamos desbloquear com o nosso novo rastreador de execução, incluindo gravação de voo. Estamos felizes em anunciar que a gravação de voo já está disponível no Go 1.25, e é uma nova ferramenta poderosa na caixa de ferramentas de diagnóstico do Go.

Rastreamentos de execução

Primeiro, uma rápida recapitulação sobre rastreamentos de execução Go.

\ O runtime do Go pode ser configurado para escrever um registo de muitos dos eventos que ocorrem durante a execução de uma aplicação Go. Esse registo é chamado de rastreamento de execução do runtime. Os rastreamentos de execução do Go contêm uma infinidade de informações sobre como as goroutines interagem entre si e com o sistema subjacente. Isso os torna muito úteis para depurar problemas de latência, pois informam quando suas goroutines estão em execução e, crucialmente, quando não estão.

\ O pacote runtime/trace fornece uma API para coletar um rastreamento de execução durante uma janela de tempo específica, chamando runtime/trace.Start e runtime/trace.Stop. Isso funciona bem se o código que você está rastreando é apenas um teste, microbenchmark ou ferramenta de linha de comando. Você pode coletar um rastreamento da execução completa de ponta a ponta, ou apenas das partes que lhe interessam.

\ No entanto, em serviços web de longa duração, os tipos de aplicações pelos quais o Go é conhecido, isso não é suficiente. Os servidores web podem ficar ativos por dias ou até semanas, e coletar um rastreamento de toda a execução produziria dados demais para analisar. Frequentemente, apenas uma parte da execução do programa dá errado, como uma solicitação expirando ou uma verificação de saúde falhando. Quando isso acontece, já é tarde demais para chamar Start!

\ Uma maneira de abordar esse problema é amostrar aleatoriamente rastreamentos de execução em toda a frota. Embora essa abordagem seja poderosa e possa ajudar a encontrar problemas antes que se tornem interrupções, ela requer muita infraestrutura para começar. Grandes quantidades de dados de rastreamento de execução precisariam ser armazenadas, triadas e processadas, muitas das quais não conterão nada interessante. E quando você está tentando chegar ao fundo de um problema específico, isso não é viável.

Gravação de voo

Isso nos leva ao gravador de voo.

\ Um programa frequentemente sabe quando algo deu errado, mas a causa raiz pode ter acontecido há muito tempo. O gravador de voo permite coletar um rastreamento dos últimos segundos de execução que levaram ao momento em que um programa detecta que houve um problema.

\ O gravador de voo coleta o rastreamento de execução normalmente, mas em vez de escrevê-lo em um socket ou arquivo, ele armazena em buffer os últimos segundos do rastreamento na memória. A qualquer momento, o programa pode solicitar o conteúdo do buffer e capturar exatamente a janela de tempo problemática. O gravador de voo é como um bisturi cortando diretamente para a área do problema.

Exemplo

Vamos aprender como usar o gravador de voo com um exemplo. Especificamente, vamos usá-lo para diagnosticar um problema de desempenho com um servidor HTTP que implementa um jogo de "adivinhe o número". Ele expõe um endpoint /guess-number que aceita um número inteiro e responde ao chamador informando se eles adivinharam o número correto.

\ Também há uma goroutine que, uma vez por minuto, envia um relatório de todos os números adivinhados para outro serviço via uma solicitação 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 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) } }

Aqui está o código completo para o servidor: https://go.dev/play/p/rX1eyKtVglF, e para um cliente simples: https://go.dev/play/p/2PjQ-1ORPiw. Para evitar um terceiro processo, o "cliente" também implementa o servidor de relatórios, embora em um sistema real isso seria separado.

\ Vamos supor que após implantar a aplicação em produção, recebemos reclamações dos usuários de que algumas chamadas /guess-number estavam demorando mais do que o esperado. Quando olhamos para os nossos logs, vemos que às vezes os tempos de resposta excedem 100 milissegundos, enquanto a maioria das chamadas está na ordem de microssegundos.

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

Antes de continuarmos, tire um minuto e veja se consegue identificar o que está errado!

\ Independentemente de você ter encontrado o problema ou não, vamos mergulhar mais fundo e ver como podemos encontrar o problema a partir dos primeiros princípios. Em particular, seria ótimo se pudéssemos ver o que a aplicação estava fazendo no tempo que antecedeu a resposta lenta. É exatamente para isso que o gravador de voo foi criado! Vamos usá-lo para capturar um rastreamento de execução assim que virmos a primeira resposta excedendo 100 milissegundos.

\ Primeiro, em main, vamos configurar e iniciar o gravador de voo:

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

MinAge configura a duração pela qual os dados de rastreamento são retidos de forma confiável, e sugerimos configurá-lo para cerca de 2x a janela de tempo do evento. Por exemplo, se você está depurando um timeout de 5 segundos, configure-o para 10 segundos. MaxBytes configura o tamanho do rastreamento em buffer para que você não estoure o uso de memória. Em média, você pode esperar que alguns MB de dados de rastreamento sejam produzidos por segundo de execução, ou 10 MB/s para um serviço ocupado.

\ Em seguida, adicionaremos uma função auxiliar para capturar o snapshot e escrevê-lo em um arquivo:

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()) }) }

\ E finalmente, logo antes de registrar uma solicitação concluída, acionaremos o snapshot se a solicitação demorar mais de 100 milissegundos:

// 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) }

\ Aqui está o código completo para o servidor, agora instrumentado com o gravador de voo: https://go.dev/play/p/3V33gfIpmjG

\ Agora, executamos o servidor novamente e enviamos solicitações até obtermos uma solicitação lenta que acione um snapshot.

\ Depois de obtermos um rastreamento, precisaremos de uma ferramenta que nos ajude a examiná-lo. A cadeia de ferramentas Go fornece uma ferramenta de análise de rastreamento de execução integrada através do comando go tool trace. Execute go tool trace snapshot.trace para iniciar a ferramenta, que inicia um servidor web local, e depois abra o URL exibido no seu navegador (se a ferramenta não abrir seu navegador automaticamente).

\ Esta ferramenta nos dá algumas maneiras de olhar para o rastreamento, mas vamos nos concentrar na visualização do rastreamento para ter uma ideia do que está acontecendo. Clique em "View trace by proc" para fazer isso.

\ Nesta visualização, o rastreamento é apresentado como uma linha do tempo de eventos. No topo da página, na seção "STATS", podemos ver um resumo do estado da aplicação, incluindo o número de threads, o tamanho do heap e a contagem de goroutines.

\ Abaixo disso, na seção "PROCS", podemos ver como a execução das goroutines é mapeada para GOMAXPROCS (o número de threads do sistema operacional criados pela aplicação Go). Podemos ver quando e como cada goroutine inicia, executa e finalmente para de executar.

\ Por enquanto, vamos voltar nossa atenção para esta enorme lacuna na execução no lado direito do visualizador. Por um período de tempo, cerca de 100ms, nada está acontecendo!

Ao selecionar a ferramenta zoom (ou pressionar 3), podemos inspecionar a seção do rastreamento logo após a lacuna com mais detalhes.

\ Além da atividade de cada goroutine individual, podemos ver como as goroutines interagem através de "eventos de fluxo". Um evento de fluxo de entrada indica o que aconteceu para fazer uma goroutine começar a executar. Uma borda de fluxo de saída indica qual efeito uma goroutine teve sobre outra. Habilitar a visualização de todos os eventos de fluxo frequentemente fornece pistas que indicam a fonte de um problema.

Neste caso, podemos ver que muitas das goroutines têm uma conexão direta com uma única goroutine logo após a pausa na atividade.

\ Clicar na goroutine única mostra uma tabela de eventos preenchida com eventos de fluxo de saída, o que corresponde ao que vimos quando a visualização de fluxo foi habilitada.

\ O que aconteceu quando esta goroutine foi executada? Parte das informações armazenadas no rastreamento é uma visualização do rastreamento de pilha em diferentes pontos no tempo. Quando olhamos para a goroutine, podemos ver que o rastreamento de pilha inicial mostra que ela estava esperando a solicitação HTTP ser concluída quando a goroutine foi agendada para execução. E o rastreamento de pilha final mostra que a função sendReport já havia retornado e estava esperando pelo ticker para o próximo horário agendado para enviar o relatório.

\ Entre o início e o fim da execução desta goroutine, vemos um grande número de "fluxos de saída", onde ela interage com outras goroutines. Clicar em uma das entradas Outgoing flow nos leva a uma visualização da interação.

\ Este fluxo implica o Unlock em sendReport:

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

\ Em sendReport, pretendíamos adquirir um bloqueio em cada bucket e liberar o bloqueio após copiar o valor.

\ Mas aqui está o problema: não liberamos o bloqueio imediatamente após copiar o valor contido em bucket.guesses. Como usamos uma instrução defer para liberar o bloqueio, essa liberação não acontece até que a função retorne. Mantemos o bloqueio não apenas além do final do loop, mas até depois que a solicitação HTTP é concluída. Esse é um erro sutil que pode ser difícil de rastrear em um grande sistema de produção.

\ Felizmente, o rastreamento de execução nos ajudou a identificar o problema. No entanto, se tentássemos usar o rastreador de execução em um servidor de longa duração sem o novo modo de gravação de voo, provavelmente acumularíamos uma enorme quantidade de dados de rastreamento de execução, que um operador teria que armazenar, transmitir e analisar. O gravador de voo nos dá o poder da retrospectiva. Ele nos permite capturar exatamente o que deu errado, depois que já aconteceu, e rapidamente identificar a causa.

\ O gravador de voo é apenas a mais recente adição à caixa de ferramentas do desenvolvedor Go para diagnosticar o funcionamento interno de aplicações em execução. Temos melhorado constantemente o rastreamento nas últimas versões. O Go 1.21 reduziu significativamente a sobrecarga de tempo de execução do rastreamento. O formato de rastreamento tornou-se mais robusto e também divisível na versão Go 1.22, levando a recursos como o gravador de voo. Ferramentas de código aberto como gotraceui e a próxima capacidade de analisar programaticamente os rastreamentos de execução são mais maneiras de aproveitar o poder dos rastreamentos de execução. A página Diagnósticos lista muitas ferramentas adicionais à sua disposição. Esperamos que você faça uso delas ao escrever e refinar suas aplicações Go.

Agradecimentos

Gostaríamos de aproveitar um momento para agradecer aos membros da comunidade que têm sido ativos nas reuniões de diagnóstico, contribuído para os designs e fornecido feedback ao longo dos anos: Felix Geisendörfer (@felixge.de), Nick Ripley (@nsrip-dd), Rhys Hiltner (@rhysh), Dominik Honnef (@dominikh), Bryan Boreham (@bboreham) e PJ Malloy (@thepudds).

\ As discussões, feedback e trabalho que todos vocês investiram têm sido fundamentais para nos impulsionar para um futuro de diagnóstico melhor. Obrigado!

Carlos Amedee e Michael Knyszek

\ Este artigo está disponível no The Go Blog sob uma licença CC BY 4.0 DEED.

\ Foto de Lukas Souza no Unsplash

\