92/100 Dias de Golang - Profiling com pprof

2025-12-09

/posts/golang/092-golang/ map[name:Victor Stein]

#Golang

Table of Contents

# Profiling com pprof

No dia 27 vimos testes de benchmark, que respondem à pergunta “quão rápido é esse código?”. Mas quando o benchmark mostra que algo está lento, a próxima pergunta é: “lento onde?”. Dá para tentar adivinhar, sair colocando time.Now() pelo código… ou usar um profiler.

Um profiler observa o programa enquanto ele roda e mostra onde o tempo e a memória estão sendo gastos. O Go já vem com um, o pprof, sem precisar instalar nada.

# O código lento

Vamos usar uma função que recebe linhas de log e extrai os IPs, devolvendo tudo separado por vírgula:

package logs

import (
	"regexp"
	"strings"
)

// ExtrairIPs recebe linhas de log e retorna os IPs encontrados, separados por vírgula
func ExtrairIPs(linhas []string) string {
	resultado := ""
	for _, linha := range linhas {
		re := regexp.MustCompile(`\b\d{1,3}\.\d{1,3}\.\d{1,3}\.\d{1,3}\b`)
		ip := re.FindString(linha)
		if ip != "" {
			if resultado != "" {
				resultado += ","
			}
			resultado += ip
		}
	}
	return resultado
}

Talvez você já tenha visto os problemas dessa função, mas vamos fingir que não e deixar o profiler mostrar para a gente.

O benchmark, com 5.000 linhas de log no formato 2025-12-09 10:00:00 GET /api/usuarios 200 192.168.0.1:

package logs

import (
	"fmt"
	"testing"
)

func gerarLinhas(n int) []string {
	linhas := make([]string, n)
	for i := range n {
		linhas[i] = fmt.Sprintf("2025-12-09 10:00:00 GET /api/usuarios 200 192.168.%d.%d", i%256, (i/256)%256)
	}
	return linhas
}

var linhas = gerarLinhas(5000)

func BenchmarkExtrairIPs(b *testing.B) {
	for b.Loop() {
		ExtrairIPs(linhas)
	}
}

O b.Loop() é a forma nova de escrever benchmarks, disponível desde o Go 1.24. Ele substitui o for i := 0; i < b.N; i++ que usamos no dia 27.

# Gerando o profile

O go test já sabe gerar os profiles, basta passar as flags -cpuprofile e -memprofile:

go test -bench=. -benchmem -cpuprofile cpu.out -memprofile mem.out

BenchmarkExtrairIPs-24     25    47748258 ns/op    412879259 B/op    320882 allocs/op

Cada execução leva 47ms, aloca 412MB e faz 320 mil alocações, para processar só 5.000 linhas. Tem alguma coisa muito errada.

Além do resultado, foram criados os arquivos cpu.out e mem.out. Vamos analisá-los com o go tool pprof.

# Analisando a CPU

O comando -top mostra as funções que mais gastaram tempo. Usando -cum ordenamos pelo tempo acumulado, ou seja, o tempo da função somado ao de todas as funções que ela chama:

go tool pprof -top -cum cpu.out

      flat  flat%   sum%        cum   cum%
         0     0%     0%     1280ms 55.17%  logs/logs.BenchmarkExtrairIPs
         0     0%     0%     1280ms 55.17%  logs/logs.ExtrairIPs
         0     0%     0%     1280ms 55.17%  testing.(*B).run1.func1
         0     0%     0%     1280ms 55.17%  testing.(*B).runN
         0     0%     0%      880ms 37.93%  runtime.systemstack
         0     0%     0%      670ms 28.88%  runtime.gcBgMarkWorker
         0     0%     0%      590ms 25.43%  regexp.Compile (inline)
         0     0%     0%      590ms 25.43%  regexp.MustCompile
         0     0%     0%      590ms 25.43%  regexp.compile

As colunas:

flat: tempo gasto dentro da própria função;
cum: tempo da função mais as funções que ela chamou.

Duas coisas chamam atenção:

regexp.MustCompile consome 25% do tempo total. Compilar uma expressão regular é caro, e estamos fazendo isso 5.000 vezes por execução, uma para cada linha.
runtime.gcBgMarkWorker consome quase 29%. Esse é o garbage collector. Quase um terço do tempo o programa está limpando memória, ou seja, estamos criando lixo demais.

Para ver exatamente quais linhas são o problema, usamos o -list com o nome da função:

go tool pprof -list 'ExtrairIPs$' cpu.out

         0      1.28s (flat, cum) 55.17% of Total
         .          .      9:func ExtrairIPs(linhas []string) string {
         .          .     10:	resultado := ""
         .          .     11:	for _, linha := range linhas {
         .      590ms     12:		re := regexp.MustCompile(`\b\d{1,3}\.\d{1,3}\.\d{1,3}\.\d{1,3}\b`)
         .      170ms     13:		ip := re.FindString(linha)
         .          .     14:		if ip != "" {
         .          .     15:			if resultado != "" {
         .      240ms     16:				resultado += ","
         .          .     17:			}
         .      280ms     18:			resultado += ip
         .          .     19:		}
         .          .     20:	}
         .          .     21:	return resultado
         .          .     22:}

Agora fica bem claro: a linha 12 (compilar a regex) e as linhas 16 e 18 (concatenar strings) são os gargalos. A busca em si, que é o que a função realmente deveria fazer, gasta só 170ms.

# Analisando a memória

O profile de memória responde a outra pergunta: quem está alocando? Com -sample_index=alloc_space vemos o total alocado durante o benchmark:

go tool pprof -sample_index=alloc_space -list 'ExtrairIPs$' mem.out

    7.30GB     8.08GB (flat, cum) 99.88% of Total
         .   719.28MB     12:		re := regexp.MustCompile(`\b\d{1,3}\.\d{1,3}\.\d{1,3}\.\d{1,3}\b`)
         .    76.53MB     13:		ip := re.FindString(linha)
    3.66GB     3.66GB     16:				resultado += ","
    3.64GB     3.64GB     18:			resultado += ip

7,3GB alocados só nas duas linhas de concatenação! Isso acontece porque strings em Go são imutáveis (falamos de strings no dia 37). Cada += cria uma string nova, copia todo o conteúdo antigo para ela e adiciona o pedaço novo. Conforme o resultado cresce, cada cópia fica maior. É por isso que o GC aparecia tanto no profile de CPU: ele estava limpando todas essas strings intermediárias.

O -sample_index aceita quatro valores:

alloc_space / alloc_objects: tudo que foi alocado (em bytes / em quantidade) durante a execução;
inuse_space / inuse_objects: o que ainda estava em uso no momento do profile. É o que usamos para caçar memory leaks.

# Corrigindo

Com os gargalos encontrados, a correção é direta:

Compilar a regex uma única vez, numa variável do pacote;
Trocar a concatenação por um strings.Builder, que vai escrevendo num buffer que cresce conforme necessário, sem recopiar tudo a cada passo.

var ipRegex = regexp.MustCompile(`\b\d{1,3}\.\d{1,3}\.\d{1,3}\.\d{1,3}\b`)

// ExtrairIPsOtimizado faz o mesmo que ExtrairIPs, sem os gargalos
func ExtrairIPsOtimizado(linhas []string) string {
	var sb strings.Builder
	for _, linha := range linhas {
		ip := ipRegex.FindString(linha)
		if ip != "" {
			if sb.Len() > 0 {
				sb.WriteByte(',')
			}
			sb.WriteString(ip)
		}
	}
	return sb.String()
}

Rodando os dois benchmarks lado a lado:

BenchmarkExtrairIPs-24             	      25	  47748258 ns/op	412879259 B/op	  320882 allocs/op
BenchmarkExtrairIPsOtimizado-24    	     296	   4023847 ns/op	    285895 B/op	      21 allocs/op

	Antes	Depois
Tempo por execução	47,7ms	4ms
Memória por execução	412MB	285KB
Alocações	320.882	21

12x mais rápido e 1.400x menos memória. E não precisamos adivinhar nada: o profiler apontou as linhas exatas.

Antes de otimizar, vale escrever um teste garantindo que as duas versões retornam o mesmo resultado. Otimização que muda o comportamento é bug.

# Interface web e flame graph

Ler a saída no terminal funciona, mas o pprof também tem uma interface web bem mais agradável:

go tool pprof -http=:8080 cpu.out

Ela abre no navegador com várias visualizações. A mais útil é o flame graph (menu View → Flame Graph): cada barra é uma função, a largura é o tempo gasto e as barras de baixo são chamadas pelas de cima. Barras largas são os gargalos, dá para encontrá-los de relance.

A visualização em grafo (View → Graph) precisa do Graphviz instalado (sudo apt install graphviz); o flame graph funciona sem ele.

# Profiling de uma aplicação rodando

Benchmarks são ótimos para analisar uma função isolada, mas às vezes o problema só aparece com a aplicação de verdade, recebendo tráfego real. Para isso existe o pacote net/http/pprof. Basta importá-lo:

package main

import (
	"fmt"
	"log"
	"net/http"
	_ "net/http/pprof"

	"logs/logs"
)

var linhas []string

func init() {
	for i := range 5000 {
		linhas = append(linhas, fmt.Sprintf("2025-12-09 10:00:00 GET /api/usuarios 200 192.168.%d.%d", i%256, (i/256)%256))
	}
}

func ipsHandler(w http.ResponseWriter, r *http.Request) {
	ips := logs.ExtrairIPs(linhas)
	fmt.Fprintf(w, "%d bytes de IPs\n", len(ips))
}

func main() {
	http.HandleFunc("/ips", ipsHandler)
	log.Println("servidor rodando em :8092")
	log.Fatal(http.ListenAndServe(":8092", nil))
}

O _ no import significa que importamos o pacote só pelos efeitos colaterais: na inicialização ele registra as rotas /debug/pprof/ no http.DefaultServeMux. Acessando http://localhost:8092/debug/pprof/ temos a lista de profiles disponíveis: allocs, block, goroutine, heap, mutex, profile, trace…

Com o servidor recebendo requisições, coletamos 5 segundos de CPU direto da aplicação:

go tool pprof -top -cum 'http://localhost:8092/debug/pprof/profile?seconds=5'

      flat  flat%   sum%        cum   cum%
     0.01s 0.093% 0.093%      5.25s 48.66%  runtime.systemstack
         0     0% 0.093%      4.92s 45.60%  logs/logs.ExtrairIPs
         0     0% 0.093%      4.92s 45.60%  main.ipsHandler
         0     0% 0.093%      4.92s 45.60%  net/http.(*ServeMux).ServeHTTP
         ...
         0     0% 0.093%      4.07s 37.72%  runtime.gcBgMarkWorker

O mesmo diagnóstico, agora com a aplicação rodando: ExtrairIPs e o garbage collector dominando. O pprof também salva uma cópia do profile em ~/pprof/, para analisar depois.

Outros profiles úteis:

# memória em uso agora (memory leaks)
go tool pprof http://localhost:8092/debug/pprof/heap

# todas as goroutines e onde estão paradas (goroutine leaks, deadlocks)
curl 'http://localhost:8092/debug/pprof/goroutine?debug=1'

O profile de goroutines é muito útil para encontrar goroutines que nunca terminam, como aquela do exemplo de WithTimeout do dia 89 se o channel não tivesse buffer.

## Cuidado em produção

As rotas do pprof mostram detalhes internos da aplicação e permitem que qualquer um dispare um profile, que consome recursos. Nunca exponha o /debug/pprof publicamente. O mais comum é rodar o pprof num servidor separado, escutando só em localhost, enquanto a aplicação usa seu próprio ServeMux:

go func() {
	log.Println(http.ListenAndServe("localhost:6060", nil))
}()

mux := http.NewServeMux()
mux.HandleFunc("/ips", ipsHandler)
log.Fatal(http.ListenAndServe(":8092", mux))

Como as rotas do pprof foram registradas no DefaultServeMux, elas só existem no servidor da porta 6060, que não é acessível de fora da máquina.

# Execution tracer

O pprof funciona por amostragem: algumas vezes por segundo ele “fotografa” o que o programa está fazendo. Isso é ótimo para encontrar onde o tempo é gasto, mas não mostra quando as coisas acontecem. Para problemas de concorrência, como goroutines esperando demais por um lock, um channel travando tudo ou o GC pausando no pior momento, existe o execution tracer, que registra cada evento do runtime.

Pode ser gerado pelo go test ou pela aplicação rodando:

go test -bench=. -trace=trace.out
# ou
curl -o trace.out 'http://localhost:8092/debug/pprof/trace?seconds=2'

E visualizado com:

go tool trace trace.out

Ele abre no navegador uma linha do tempo mostrando, para cada processador, qual goroutine estava rodando a cada instante, quando o GC entrou em ação e quanto tempo cada goroutine ficou bloqueada. É uma ferramenta mais avançada, que conversa bastante com o que vimos no dia 34 sobre como o runtime gerencia as goroutines.

victorstein.dev