Profiling en Go con pprof: encuentra cuellos de botella en CPU, memoria y goroutine

1. Tổng quan

Cuando un servicio de Go se ejecuta lentamente o consume mucha RAM, la suposición aleatoria generalmente consume tiempo y es propensa a errores. Go tiene la herramienta pprof integrada en la biblioteca estándar. Esta herramienta te dice exactamente qué función consume CPU, dónde se asigna memoria y qué goroutine está atascada.

Después de leer este artículo, sabrás cómo habilitar pprof para un servicio HTTP, recopilar perfiles desde benchmarks y programas CLI, leer resultados usando go tool pprof, y comparar dos perfiles para verificar una optimización.

2. Qué es pprof y qué tipos de perfiles hay

pprof tiene dos partes:

• Lado de recopilación: paquete runtime/pprof y net/http/pprof en la biblioteca estándar. Registran perfiles en formato protobuf.
• Lado de análisis: comando go tool pprof. Este comando lee archivos de perfil o URLs y muestra resultados en forma de tabla, código fuente o interfaz web.

Tipos de perfiles comúnmente utilizados:

Perfil	Mide qué	¿Habilitado por defecto?
profile (CPU)	Tiempo de CPU por función, muestreo 100 veces/seg	Sí, cuando se solicita
heap	Memoria viva y total asignada	Sí
allocs	Como heap, pero por defecto ve la asignación total	Sí
goroutine	Stack trace de todas las goroutines actuales	Sí
block	Tiempo de espera en canal, select, sync.Cond	No
mutex	Contención en sync.Mutex/RWMutex	No
trace	Evento trace detallado (usar go tool trace)	Sí, cuando se solicita

3. Habilitar pprof para servicios HTTP

La forma más rápida es importar net/http/pprof para obtener el efecto secundario. Este paquete registra los handlers /debug/pprof/* en http.DefaultServeMux.

package main

import (
	"log"
	"net/http"
	_ "net/http/pprof" // registra /debug/pprof/* en DefaultServeMux
)

func main() {
	// Servidor pprof separado, escucha solo en localhost
	go func() {
		log.Println(http.ListenAndServe("localhost:6060", nil))
	}()

	// Servidor de aplicación usa mux separado, no expone pprof
	appMux := http.NewServeMux()
	appMux.HandleFunc("GET /invoice", invoiceHandler)
	log.Fatal(http.ListenAndServe(":8080", appMux))
}

Algunos puntos a tener en cuenta:

• La línea _ "net/http/pprof" solo registra handlers, no llamas a ninguna función en este paquete.
• El servidor pprof pasa nil como handler, es decir, usa DefaultServeMux, que contiene las rutas pprof.
• La aplicación principal usa appMux separado, por lo que el puerto 8080 no tiene /debug/pprof.

Verificación rápida:

curl -s http://localhost:6060/debug/pprof/ | head -n 20

Nota: Nunca expongas /debug/pprof a Internet. Este endpoint expone stack traces y la estructura del código. Los atacantes también pueden usarlo para sobrecargar el servicio (el perfil de CPU durante 30 segundos consume recursos). Vincula a localhost o colócalo detrás de una red interna y una capa de autenticación.

4. Recopilar y leer perfil de CPU

Supongamos que el servicio tiene una función para crear facturas así:

type Item struct {
	SKU   string
	Price float64
	Qty   int
}

type Order struct {
	ID    int
	Items []Item
}

func BuildInvoice(o Order) string {
	s := ""
	for _, it := range o.Items {
		s += fmt.Sprintf("%s x%d = %.2f\n", it.SKU, it.Qty, it.Price*float64(it.Qty))
	}
	return s
}

En cada iteración, s += ... crea una nueva cadena y copia todo el contenido anterior. Con pedidos con muchas líneas, el costo aumenta en O(n²).

Mientras el servicio recibe carga (por ejemplo, usas hey o wrk para enviar solicitudes a /invoice), recopila el perfil de CPU durante 30 segundos:

go tool pprof "http://localhost:6060/debug/pprof/profile?seconds=30"

Después de recopilar, entras en modo interactivo. Escribe top:

(pprof) top 8
Showing nodes accounting for 2.41s, 85.46% of 2.82s total
      flat  flat%   sum%        cum   cum%
     0.92s 32.62% 32.62%      0.92s 32.62%  runtime.memmove
     0.41s 14.54% 47.16%      1.38s 48.94%  runtime.concatstrings
     0.33s 11.70% 58.87%      0.33s 11.70%  runtime.memclrNoHeapPointers
     0.27s  9.57% 68.44%      0.71s 25.18%  runtime.mallocgc
     0.18s  6.38% 74.82%      0.52s 18.44%  fmt.(*pp).doPrintf
     0.13s  4.61% 79.43%      0.13s  4.61%  strconv.fmtF
     0.10s  3.55% 82.98%      2.47s 87.59%  main.BuildInvoice
     0.07s  2.48% 85.46%      0.21s  7.45%  runtime.scanobject

Cómo leer las dos columnas más importantes:

• flat: tiempo de CPU que está directamente dentro de esa función.
• cum (acumulativo): tiempo de esa función más todas las funciones que llama.

Aquí main.BuildInvoice tiene flat pequeño pero cum cerca del 88%. La mayoría del tiempo se gasta en memmove y concatstrings, es decir, la concatenación de cadenas. Para ver detalles línea por línea, usa list:

(pprof) list BuildInvoice
ROUTINE ======================== main.BuildInvoice in /app/invoice.go
     100ms      2.47s (flat, cum) 87.59% of Total
         .          .     18:func BuildInvoice(o Order) string {
         .          .     19:	s := ""
      10ms       10ms     20:	for _, it := range o.Items {
      90ms      2.46s     21:		s += fmt.Sprintf("%s x%d = %.2f\n", ...)
         .          .     22:	}

La línea 21 es el culpable. Si quieres ver un gráfico de llamas, abre la interfaz web:

go tool pprof -http=:8081 "http://localhost:6060/debug/pprof/profile?seconds=30"

El navegador abrirá vistas de Top, Graph, Flame Graph y Source. En el gráfico de llamas, los bloques más anchos consumen más CPU.

Solución usando strings.Builder y fmt.Fprintf:

func BuildInvoiceFast(o Order) string {
	var b strings.Builder
	b.Grow(len(o.Items) * 32) // estima de antemano, evita crecer muchas veces
	for _, it := range o.Items {
		fmt.Fprintf(&b, "%s x%d = %.2f\n", it.SKU, it.Qty, it.Price*float64(it.Qty))
	}
	return b.String()
}

5. Perfil de heap: ¿quién está retiendo memoria?

go tool pprof http://localhost:6060/debug/pprof/heap

Un perfil de heap contiene cuatro “índices de muestra”. Seleccionas el índice con la bandera -sample_index:

• inuse_space (predeterminado): número de bytes vivos actualmente en el momento del GC más reciente. Úsalo para encontrar memory leaks.
• inuse_objects: número de objetos vivos.
• alloc_space: total de bytes asignados desde que se inició el programa. Úsalo para encontrar lo que presiona el GC.
• alloc_objects: número total de objetos asignados.

go tool pprof -sample_index=alloc_space http://localhost:6060/debug/pprof/heap

(pprof) top 3
      flat  flat%   sum%        cum   cum%
    1.84GB 91.20% 91.20%     1.84GB 91.20%  main.BuildInvoice
    0.12GB  5.95% 97.15%     0.12GB  5.95%  fmt.Sprintf
    0.03GB  1.49% 98.64%     0.03GB  1.49%  encoding/json.Marshal

El resultado muestra que BuildInvoice ha asignado 1,84 GB en total, aunque la cantidad viva puede ser muy pequeña. Esto es una señal de que el GC tiene que trabajar mucho. Esta situación coincide con la cantidad de runtime.mallocgc y runtime.scanobject que ves en el perfil de CPU en la sección 4.

Nota: El perfil de heap también es un muestreo (por defecto alrededor de 1 muestra cada 512KB asignados), por lo que los números son solo estimaciones. No compares byte por byte, mira los porcentajes.

6. Perfil de goroutine: detectar goroutine leaks

Si el número de goroutines solo sigue aumentando, puedes echar un vistazo rápido a través del navegador o curl sin necesidad de go tool pprof:

curl -s "http://localhost:6060/debug/pprof/goroutine?debug=1" | head -n 15

goroutine profile: total 10432
10398 @ 0x43a5d6 0x4071c5 0x406d78 0x6b2f45 0x46c0e1
#	0x6b2f44	main.(*PaymentService).notify+0x64	/app/payment.go:57

10.398 goroutines están atrapadas en payment.go:57. Esto es casi seguro un leak. El código que causa el error generalmente se ve así:

func (s *PaymentService) notify(ctx context.Context, p Payment) {
	result := make(chan error) // sin búfer
	go func() {
		result <- s.gateway.Send(p) // atrapada para siempre si nadie recibe
	}()
	select {
	case err := <-result:
		log.Println(err)
	case <-ctx.Done():
		return // goroutine interna se queda atrás
	}
}

Cuando ctx expira primero, nadie más lee result, así que la goroutine interna se queda atrapada permanentemente en el envío. La solución simple es usar make(chan error, 1) para que el envío nunca se bloquee.

Con debug=2, el endpoint imprime el stack trace completo de cada goroutine, incluyendo el tiempo de espera (por ejemplo, [chan send, 42 minutes]). Esta información es muy útil al investigar deadlocks.

7. Perfil de block y mutex

Estos dos perfiles están deshabilitados por defecto porque tienen costo. Los habilitas en main:

import "runtime"

func init() {
	// Registra en promedio 1 evento de contencion de mutex de cada 5
	runtime.SetMutexProfileFraction(5)
	// Muestrea 1 evento de bloqueo por cada 10µs bloqueados
	runtime.SetBlockProfileRate(10_000)
}

Después recopila el perfil como de costumbre:

go tool pprof http://localhost:6060/debug/pprof/mutex
go tool pprof http://localhost:6060/debug/pprof/block

El perfil de mutex te dice qué lock hace que las goroutines esperen en cola, por ejemplo un sync.Mutex protegiendo un caché compartido map[int]Customer. El perfil de block te dice dónde las goroutines esperan en un canal o select.

Nota: SetBlockProfileRate(1) registra cada evento de bloqueo. Este nivel solo es apropiado para depuración local. En producción, usa una tasa mayor o habilita solo temporalmente.

8. Profiling desde benchmark

Para una función específica, la forma más concisa es escribir un benchmark y dejar que go test genere el perfil. El código a continuación usa b.Loop() que requiere Go 1.24 o superior.

package main

import (
	"fmt"
	"testing"
)

func sampleOrder(n int) Order {
	items := make([]Item, n)
	for i := range items {
		items[i] = Item{SKU: fmt.Sprintf("SKU-%04d", i), Price: 19.99, Qty: i%5 + 1}
	}
	return Order{ID: 1, Items: items}
}

func TestBuildInvoiceFastMatchesOriginal(t *testing.T) {
	order := sampleOrder(200)
	if got, want := BuildInvoiceFast(order), BuildInvoice(order); got != want {
		t.Fatalf("salida diferente:\n got=%q\nwant=%q", got, want)
	}
}

func BenchmarkBuildInvoice(b *testing.B) {
	order := sampleOrder(500)
	b.ReportAllocs()
	for b.Loop() {
		BuildInvoice(order)
	}
}

func BenchmarkBuildInvoiceFast(b *testing.B) {
	order := sampleOrder(500)
	b.ReportAllocs()
	for b.Loop() {
		BuildInvoiceFast(order)
	}
}

El test TestBuildInvoiceFastMatchesOriginal asegura que la versión optimizada produzca exactamente el mismo resultado que la versión anterior. No omitas este paso: optimizar pero producir resultados incorrectos es inútil. Ejecuta el benchmark con perfil:

go test -run='^$' -bench=BuildInvoice -cpuprofile=cpu.out -memprofile=mem.out

BenchmarkBuildInvoice-8        1543    772410 ns/op   6342817 B/op    1002 allocs/op
BenchmarkBuildInvoiceFast-8   19821     60318 ns/op     36472 B/op     504 allocs/op

La versión que usa strings.Builder es aproximadamente 12 veces más rápida y asigna aproximadamente 170 veces menos. La bandera -run='^$' salta las pruebas normales para ejecutar solo los benchmarks. Los archivos cpu.out y mem.out se abren con:

go tool pprof -http=:8081 cpu.out

9. Profiling de un programa CLI con runtime/pprof

Para una herramienta que se ejecuta una sola vez y luego sale, como un trabajo de importación de pedidos, usas directamente runtime/pprof:

package main

import (
	"log"
	"os"
	"runtime"
	"runtime/pprof"
)

func main() {
	cpuFile, err := os.Create("cpu.out")
	if err != nil {
		log.Fatal(err)
	}
	defer cpuFile.Close()

	if err := pprof.StartCPUProfile(cpuFile); err != nil {
		log.Fatal(err)
	}
	defer pprof.StopCPUProfile()

	importOrders("orders.csv") // trabajo principal

	memFile, err := os.Create("mem.out")
	if err != nil {
		log.Fatal(err)
	}
	defer memFile.Close()
	runtime.GC() // actualiza estadísticas inuse antes de escribir
	if err := pprof.WriteHeapProfile(memFile); err != nil {
		log.Fatal(err)
	}
}

Dos errores comunes aquí:

• Llamar a log.Fatal u os.Exit después de StartCPUProfile omitirá los defer. En este caso, StopCPUProfile no se ejecuta y el archivo de perfil está vacío o corrupto.
• Olvidar runtime.GC() antes de WriteHeapProfile. Las estadísticas de inuse_* solo se actualizan después de cada GC, por lo que el perfil puede reflejar un estado antiguo.

10. Comparar dos perfiles

Después de optimizar, deberías medir nuevamente en lugar de confiar en tu intuición. La bandera -diff_base resta el perfil anterior del nuevo:

go tool pprof -diff_base=cpu_before.out cpu_after.out

(pprof) top 3
      flat  flat%   sum%        cum   cum%
    -0.89s 31.56% 31.56%     -0.89s 31.56%  runtime.memmove
    -0.40s 14.18% 45.74%     -1.35s 47.87%  runtime.concatstrings
    -0.25s  8.87% 54.61%     -0.66s 23.40%  runtime.mallocgc

Los valores negativos significan que el tiempo ha disminuido. Para que los resultados sean significativos, los dos perfiles deben recopilarse bajo las mismas condiciones: misma carga, misma duración, misma máquina.

Además, desde Go 1.21, el perfil de CPU también sirve para Profile-Guided Optimization (PGO). Recopila un perfil de CPU representativo de producción, llámalo default.pgo en el directorio del paquete main, y go build lo usará automáticamente para inline y optimizar los caminos de código caliente. La mejora generalmente es de algunos puntos porcentuales, y no necesitas cambiar ninguna línea de código.

11. Errores comunes y cuándo no usar

• Perfil demasiado corto o sin carga. El perfil de CPU muestrea a 100Hz. Si solo recopila 2 segundos cuando el servicio está inactivo, solo verá runtime y ruido.
• Confundir flat con cum. Una función con cum alto no es necesariamente el culpable, podría simplemente estar llamando al culpable.
• Confundir inuse_space con alloc_space. Para encontrar leaks, mira inuse. Para reducir la presión de GC, mira alloc.
• Medir I/O con perfil de CPU. El tiempo que las goroutines esperan en la base de datos o HTTP no consume CPU, por lo que no aparece en el perfil de CPU. Usa el perfil de block, go tool trace o trazado distribuido.
• Dejar pprof público en el puerto de la aplicación. Ver sección 3.

Nota: pprof responde a la pregunta “dónde se gasta”, no “¿debería optimizar esto?”. Si un endpoint ya cumple con el SLA y una función solo consume el 2% de CPU, reescribirla para hacerla más compleja generalmente no vale la pena.

12. Conclusión

En este artículo has:

• habilitado net/http/pprof de forma segura en un servidor separado en localhost;
• leído el perfil de CPU con top y list, y distinguido flat de cum;
• usado el perfil de heap con inuse_space y alloc_space;
• detectado goroutine leaks a través de debug=1 y debug=2;
• habilitado perfiles de block y mutex;
• generado perfiles desde benchmarks y programas CLI;
• comparado antes/después usando -diff_base.

El proceso más efectivo sigue siendo: medir → encontrar puntos calientes → arreglar → escribir pruebas para mantener el comportamiento correcto → medir de nuevo. Con pprof disponible en la biblioteca estándar, no necesitas instalar nada para comenzar.