Grabadora de vuelo: Un nuevo trazador de ejecución de Go

En 2024 presentamos al mundo trazas de ejecución de Go más potentes. En esa entrada del blog, dimos un adelanto de algunas de las nuevas funcionalidades que podríamos desbloquear con nuestro nuevo trazador de ejecución, incluyendo la grabación de vuelo. Nos complace anunciar que la grabación de vuelo ya está disponible en Go 1.25, y es una poderosa nueva herramienta en la caja de herramientas de diagnóstico de Go.

Trazas de ejecución

Primero, un rápido repaso sobre las trazas de ejecución de Go.

El tiempo de ejecución de Go puede configurarse para escribir un registro de muchos de los eventos que ocurren durante la ejecución de una aplicación Go. Ese registro se llama traza de ejecución en tiempo de ejecución. Las trazas de ejecución de Go contienen una gran cantidad de información sobre cómo las goroutines interactúan entre sí y con el sistema subyacente. Esto las hace muy útiles para depurar problemas de latencia, ya que te indican tanto cuándo tus goroutines están ejecutándose como, crucialmente, cuándo no lo están.

El paquete runtime/trace proporciona una API para recopilar una traza de ejecución durante un período de tiempo determinado llamando a runtime/trace.Start y runtime/trace.Stop. Esto funciona bien si el código que estás trazando es solo una prueba, un microbenchmark o una herramienta de línea de comandos. Puedes recopilar una traza de la ejecución completa de principio a fin, o solo de las partes que te interesan.

Sin embargo, en servicios web de larga duración, el tipo de aplicaciones por las que Go es conocido, eso no es suficiente. Los servidores web pueden estar activos durante días o incluso semanas, y recopilar una traza de toda la ejecución produciría demasiados datos para examinar. A menudo, solo una parte de la ejecución del programa falla, como una solicitud que agota el tiempo de espera o una verificación de estado fallida. ¡Para cuando ocurre, ya es demasiado tarde para llamar a Start!

Una forma de abordar este problema es muestrear aleatoriamente trazas de ejecución de toda la flota. Si bien este enfoque es potente y puede ayudar a encontrar problemas antes de que se conviertan en interrupciones, requiere mucha infraestructura para comenzar. Sería necesario almacenar, clasificar y procesar grandes cantidades de datos de trazas de ejecución, gran parte de los cuales no contendrán nada interesante. Y cuando estás tratando de llegar al fondo de un problema específico, es un punto muerto.

Grabación de vuelo

Esto nos lleva al grabador de vuelo.

Un programa a menudo sabe cuándo algo ha salido mal, pero la causa raíz puede haber ocurrido hace mucho tiempo. El grabador de vuelo te permite recopilar una traza de los últimos segundos de ejecución previos al momento en que un programa detecta que ha habido un problema.

El grabador de vuelo recopila la traza de ejecución de manera normal, pero en lugar de escribirla en un socket o un archivo, almacena en búfer los últimos segundos de la traza en memoria. En cualquier momento, el programa puede solicitar el contenido del búfer y capturar exactamente la ventana de tiempo problemática. El grabador de vuelo es como un bisturí que corta directamente hacia el área del problema.

Ejemplo

Aprendamos a usar el grabador de vuelo con un ejemplo. Específicamente, usémoslo para diagnosticar un problema de rendimiento con un servidor HTTP que implementa un juego de "adivina el número". Expone un endpoint /guess-number que acepta un entero y responde al llamador informándole si adivinó el número correcto.

También hay una goroutine que, una vez por minuto, envía un informe de todos los números adivinados a otro servicio a través de una solicitud 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) } }

Aquí está el código completo para el servidor: https://go.dev/play/p/rX1eyKtVglF, y para un cliente simple: https://go.dev/play/p/2PjQ-1ORPiw. Para evitar un tercer proceso, el "cliente" también implementa el servidor de informes, aunque en un sistema real esto estaría separado.

Supongamos que después de implementar la aplicación en producción, recibimos quejas de los usuarios de que algunas llamadas a /guess-number estaban tardando más de lo esperado. Cuando miramos nuestros registros, vemos que a veces los tiempos de respuesta superan los 100 milisegundos, mientras que la mayoría de las llamadas son del orden de microsegundos.

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 continuar, tómate un minuto y mira si puedes detectar qué está mal.

Independientemente de si encontraste el problema o no, profundicemos y veamos cómo podemos encontrar el problema desde los primeros principios. En particular, sería genial si pudiéramos ver qué estaba haciendo la aplicación en el tiempo previo a la respuesta lenta. ¡Esto es exactamente para lo que se creó el grabador de vuelo! Lo usaremos para capturar una traza de ejecución una vez que veamos la primera respuesta que supere los 100 milisegundos.

Primero, en main, configuraremos e iniciaremos el grabador de vuelo:

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

MinAge configura la duración durante la cual los datos de traza se retienen de manera confiable, y sugerimos establecerla en aproximadamente 2 veces la ventana de tiempo del evento. Por ejemplo, si estás depurando un tiempo de espera de 5 segundos, configúralo en 10 segundos. MaxBytes configura el tamaño de la traza almacenada en búfer para que no agotes tu uso de memoria. En promedio, puedes esperar que se produzcan unos pocos MB de datos de traza por segundo de ejecución, o 10 MB/s para un servicio ocupado.

A continuación, agregaremos una función auxiliar para capturar la instantánea y escribirla en un archivo:

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

Y finalmente, justo antes de registrar una solicitud completada, activaremos la instantánea si la solicitud tomó más de 100 milisegundos:

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

Aquí está el código completo para el servidor, ahora instrumentado con el grabador de vuelo: https://go.dev/play/p/3V33gfIpmjG

Ahora, ejecutamos el servidor nuevamente y enviamos solicitudes hasta obtener una solicitud lenta que active una instantánea.

Una vez que hemos obtenido una traza, necesitaremos una herramienta que nos ayude a examinarla. La cadena de herramientas de Go proporciona una herramienta de análisis de trazas de ejecución incorporada a través del comando go tool trace. Ejecuta go tool trace snapshot.trace para iniciar la herramienta, que inicia un servidor web local, luego abre la URL mostrada en tu navegador (si la herramienta no abre tu navegador automáticamente).

Esta herramienta nos da algunas formas de ver la traza, pero centrémonos en visualizar la traza para tener una idea de lo que está sucediendo. Haz clic en "View trace by proc" para hacerlo.

En esta vista, la traza se presenta como una línea de tiempo de eventos. En la parte superior de la página, en la sección "STATS", podemos ver un resumen del estado de la aplicación, incluido el número de hilos, el tamaño del montón y el recuento de goroutines.

Debajo de eso, en la sección "PROCS", podemos ver cómo la ejecución de goroutines se mapea en GOMAXPROCS (el número de hilos del sistema operativo creados por la aplicación Go). Podemos ver cuándo y cómo cada goroutine comienza, se ejecuta y finalmente deja de ejecutarse.

Por ahora, centremos nuestra atención en esta enorme brecha en la ejecución en el lado derecho del visor. ¡Durante un período de tiempo, alrededor de 100 ms, no está sucediendo nada!

Al seleccionar la herramienta zoom (o presionar 3), podemos inspeccionar la sección de la traza justo después de la brecha con más detalle.

Además de la actividad de cada goroutine individual, podemos ver cómo las goroutines interactúan a través de "eventos de flujo". Un evento de flujo entrante indica qué sucedió para hacer que una goroutine comience a ejecutarse. Un borde de flujo saliente indica qué efecto tuvo una goroutine sobre otra. Habilitar la visualización de todos los eventos de flujo a menudo proporciona pistas que sugieren la fuente de un problema.

En este caso, podemos ver que muchas de las goroutines tienen una conexión directa con una sola goroutine justo después de la pausa en la actividad.

Al hacer clic en la goroutine única, se muestra una tabla de eventos llena de eventos de flujo salientes, que coincide con lo que vimos cuando se habilitó la vista de flujo.

¿Qué sucedió cuando se ejecutó esta goroutine? Parte de la información almacenada en la traza es una vista de la traza de la pila en diferentes puntos en el tiempo. Cuando miramos la goroutine, podemos ver que la traza de la pila inicial muestra que estaba esperando a que se completara la solicitud HTTP cuando la goroutine estaba programada para ejecutarse. Y la traza de la pila final muestra que la función sendReport ya había regresado y estaba esperando el ticker para el próximo tiempo programado para enviar el informe.

Entre el inicio y el final de la ejecución de esta goroutine, vemos una gran cantidad de "flujos salientes", donde interactúa con otras goroutines. Hacer clic en una de las entradas de Outgoing flow nos lleva a una vista de la interacción.

Este flujo implica el Unlock en sendReport:

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

En sendReport, teníamos la intención de adquirir un bloqueo en cada bucket y liberar el bloqueo después de copiar el valor.

Pero aquí está el problema: en realidad no liberamos el bloqueo inmediatamente después de copiar el valor contenido en bucket.guesses. Debido a que usamos una declaración defer para liberar el bloqueo, esa liberación no ocurre hasta que la función regresa. Mantenemos el bloqueo no solo más allá del final del bucle, sino hasta después de que se complete la solicitud HTTP. Es un error sutil que puede ser difícil de rastrear en un sistema de producción grande.

Afortunadamente, el trazado de ejecución nos ayudó a identificar el problema. Sin embargo, si intentáramos usar el trazador de ejecución en un servidor de larga duración sin el nuevo modo de grabación de vuelo, probablemente acumularía una gran cantidad de datos de trazas de ejecución, que un operador tendría que almacenar, transmitir y examinar. El grabador de vuelo nos da el poder de la retrospectiva. Nos permite capturar exactamente lo que salió mal, después de que ya ha sucedido, y rápidamente centrarnos en la causa.

El grabador de vuelo es solo la última adición a la caja de herramientas del desarrollador de Go para diagnosticar el funcionamiento interno de las aplicaciones en ejecución. Hemos estado mejorando constantemente el trazado durante los últimos lanzamientos. Go 1.21 redujo enormemente la sobrecarga de tiempo de ejecución del trazado. El formato de traza se volvió más robusto y también divisible en el lanzamiento de Go 1.22, lo que condujo a características como el grabador de vuelo. Herramientas de código abierto como gotraceui y la próxima capacidad de analizar programáticamente las trazas de ejecución son más formas de aprovechar el poder de las trazas de ejecución. La página de Diagnósticos enumera muchas herramientas adicionales a tu disposición. Esperamos que las utilices mientras escribes y refinas tus aplicaciones Go.

Agradecimientos

Nos gustaría tomarnos un momento para agradecer a aquellos miembros de la comunidad que han estado activos en las reuniones de diagnóstico, han contribuido a los diseños y han proporcionado comentarios a lo largo de los años: Felix Geisendörfer (@felixge.de), Nick Ripley (@nsrip-dd), Rhys Hiltner (@rhysh), Dominik Honnef (@dominikh), Bryan Boreham (@bboreham) y PJ Malloy (@thepudds).

Las discusiones, comentarios y trabajo que todos han aportado han sido fundamentales para impulsarnos hacia un mejor futuro de diagnóstico. ¡Gracias!

---

Carlos Amedee y Michael Knyszek

Este artículo está disponible en The Go Blog bajo una licencia CC BY 4.0 DEED.

Foto de Lukas Souza en Unsplash