Mientras que pprof te dice qué parte de tu código está consumiendo CPU (un enfoque basado en muestreo), go tool trace te dice por qué tu programa no está ejecutándose de forma eficiente (un enfoque basado en eventos). Si pprof es una foto de dónde se gasta la energía, trace es el video de cómo se mueven las piezas.
Esta herramienta captura eventos de baja latencia del runtime: cuándo se crea una goroutine, cuándo se bloquea una llamada al sistema, cuándo el Garbage Collector (GC) inicia una fase de ayuda (assist) y cómo el scheduler mueve las goroutines entre los P (procesadores lógicos). Se usa para diagnosticar problemas de latencia, contención de bloqueos o cuellos de botella en el network poller que no se ven simplemente mirando el uso de CPU.
Cuando el uso de CPU es bajo, pero tu latencia es alta o el throughput es pobre, es el momento de usar trace. Si intentas usar pprof para entender por qué tus goroutines pasan la mitad del tiempo en estado Waiting a pesar de que el CPU está al 10%, no encontrarás la respuesta; ahí es donde trace brilla. Sin embargo, ten cuidado: debido a que la recolección de eventos tiene un costo de CPU y memoria, el acto de rastrear puede alterar ligeramente el comportamiento de la concurrencia (el “efecto observador”), especialmente en race conditions extremadamente sensibles.
package main
import (
"fmt"
"os"
"runtime/trace"
"sync"
"time"
)
func main() {
// Creamos el archivo donde se guardará el trace
f, err := os.Create("trace.out")
if err != nil {
panic(err)
}
defer f.Close()
// Iniciamos el rastreo. Esto activa la recolección de eventos
// de la runtime en el scheduler y el GC.
trace.Start(f)
defer trace.Stop()
var wg sync.WaitGroup
var mu sync.Mutex
sharedCounter := 0
// Simulamos una carga de trabajo con alta contención de mutex
// y cambios de contexto frecuentes.
for i := 0; i < 50; i++ {
wg.Add(1)
go func(workerID int) {
defer wg.Done()
for j := 0; j < 100; j++ {
// El bloqueo de este mutex causará que las goroutines
// entren en estado "Waiting" en el trace.
mu.Lock()
sharedCounter++
time.Sleep(time.Microsecond * 10) // Forzamos el cambio de contexto
mu.Unlock()
// Un pequeño sleep para asegurar que el scheduler tenga
// múltiples goroutines en la cola "Runnable"
time.Sleep(time.Microsecond * 5)
}
fmt.Printf("Worker %d finalizado\n", workerID)
}(i)
}
wg.Wait()
}
Al ejecutar este programa con go run main.go, generarás un archivo trace.out. Para analizarlo, necesitas ejecutar go tool trace trace.out en tu terminal; esto abrirá una interfaz en tu navegador.
En el ejemplo, la variable sharedCounter protegida por mu (el sync.Mutex) es el centro del problema. Al abrir la vista de “Goroutine analysis”, verás que la gran mayoría del tiempo no está en Running, sino en Waiting. El trace te permitirá ver exactamente en qué momento una goroutine intenta adquirir el mutex y cómo el scheduler la pone en pausa, liberando el P para que otra tarea corra, o dejándolo ocioso si no hay nadie listo.
Fíjate en la sección de “Procs” (los procesadores lógicos). Si ves grandes bloques de color gris o espacios vacíos donde los P están en estado idle mientras tus goroutines están en estado Runnable, tienes un problema de scheduling latency: el scheduler no está asignando goroutines a los procesadores lo suficientemente rápido, o las goroutines están bloqueadas esperando recursos de hardware o syscalls.
El uso de time.Sleep en el bucle es clave: en un programa real, esto sería una operación de red o una espera de canal. En el trace, verás cómo la goroutine se mueve de la ejecución a una espera del Network Poller o un timer, y cómo el scheduler reacciona inmediatamente para aprovechar ese hueco.
El error frecuente es intentar usar go tool trace para optimizar algoritmos matemáticos o funciones con alto uso de CPU. Si tu función CalcularPi() es lenta porque requiere muchos ciclos de reloj, trace solo te mostrará una línea larga de ejecución continua. Para eso, necesitas pprof para identificar la instrucción o la función exacta. trace es para la orquestación, no para el cálculo.
N° 166