Profiling Go mit pprof: CPU-, Speicher- und Goroutine-Engpässe finden

1. Übersicht

Wenn ein Go-Service langsam läuft oder zu viel RAM verbraucht, führt Rätselraten oft zu Zeitverschwendung und häufig falschen Ergebnissen. Go hat das Werkzeug pprof bereits in der Standardbibliothek. Dieses Werkzeug zeigt dir genau, welche Funktion CPU-Zeit frisst, wo Speicher allokiert wird und welche Goroutine steckenbleibt.

Nach diesem Artikel wirst du wissen, wie man pprof für HTTP-Services aktiviert, Profile von Benchmarks und CLI-Programmen erfasst, Ergebnisse mit go tool pprof liest und zwei Profile vergleicht, um eine Optimierung zu verifizieren.

2. Was ist pprof und welche Arten von Profilen gibt es

pprof besteht aus zwei Teilen:

• Erfassungsseite: Die Pakete runtime/pprof und net/http/pprof aus der Standardbibliothek. Sie schreiben Profile im Protobuf-Format.
• Analyseseite: Der Befehl go tool pprof. Dieser Befehl liest eine Profildatei oder eine URL und zeigt die Ergebnisse als Tabelle, Quellcode oder Web-Interface an.

Häufig verwendete Profile:

Profil	Misst	Standardmäßig aktiviert?
profile (CPU)	CPU-Zeit nach Funktion, 100 Stichproben/Sekunde	Ja, auf Anfrage
heap	Derzeit lebender Speicher und insgesamt allokiert	Ja
allocs	Wie heap, aber zeigt standardmäßig gesamte Allokationen	Ja
goroutine	Stack Traces aller aktuellen Goroutinen	Ja
block	Wartezeit auf Channel, select, sync.Cond	Nein
mutex	Konflikte auf sync.Mutex/RWMutex	Nein
trace	Detailliertes Event-Tracing (nutze go tool trace)	Ja, auf Anfrage

3. pprof für HTTP-Services aktivieren

Der schnellste Weg ist, net/http/pprof zu importieren, um den Side-Effect zu nutzen. Dieses Paket registriert Handler /debug/pprof/* bei http.DefaultServeMux.

package main

import (
	"log"
	"net/http"
	_ "net/http/pprof" // registriert /debug/pprof/* bei DefaultServeMux
)

func main() {
	// Separater pprof-Server, lauscht nur auf localhost
	go func() {
		log.Println(http.ListenAndServe("localhost:6060", nil))
	}()

	// Anwendungs-Server nutzt eigenes Mux, exponiert pprof nicht
	appMux := http.NewServeMux()
	appMux.HandleFunc("GET /invoice", invoiceHandler)
	log.Fatal(http.ListenAndServe(":8080", appMux))
}

Ein paar Dinge zu beachten:

• Die Zeile _ "net/http/pprof" registriert nur Handler, du rufst keine Funktion aus diesem Paket auf.
• Der pprof-Server übergibt nil als Handler, d.h. er nutzt DefaultServeMux, das die pprof-Routes enthält.
• Die Hauptanwendung nutzt ein eigenes appMux, also hat Port 8080 kein /debug/pprof.

Schnelle Überprüfung:

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

Hinweis: Exponiere /debug/pprof niemals ins Internet. Dieser Endpoint offenbart Stack Traces und Code-Struktur. Böswillige Akteure können es auch nutzen, um den Service zu überlasten (ein 30-Sekunden-CPU-Profil kostet Ressourcen). Bind es an localhost oder platziere es hinter einem internen Netzwerk und einer Authentifizierungsschicht.

4. CPU-Profile erfassen und lesen

Angenommen, der Service hat eine Funktion zur Rechnungserstellung wie diese:

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
}

Bei jeder Iteration erstellt s += ... einen neuen String und kopiert den gesamten alten Inhalt hinüber. Bei Bestellungen mit vielen Zeilen wächst der Aufwand nach O(n²).

Während der Service unter Last läuft (z.B. wenn du mit hey oder wrk Requests an /invoice sendest), erfasse das CPU-Profil für 30 Sekunden:

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

Nach der Erfassung betrittst du den interaktiven Modus. Gib top ein:

(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

So liest du die zwei wichtigsten Spalten:

• flat: CPU-Zeit, die sich direkt in dieser Funktion aufhält.
• cum (cumulative): Zeit dieser Funktion plus alle Funktionen, die sie aufruft.

Hier hat main.BuildInvoice kleines flat, aber cum nahe 88%. Die meiste Zeit geht in memmove und concatstrings, d.h. String-Verkettung. Um Details jeder Zeile zu sehen, nutze 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:	}

Zeile 21 ist der Schuldige. Wenn du einen Flame Graph sehen möchtest, öffne die Web-Oberfläche:

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

Der Browser öffnet die Ansichten Top, Graph, Flame Graph und Source. In einem Flame Graph verbraucht ein größerer Block mehr CPU.

Die optimierte Version nutzt strings.Builder und fmt.Fprintf:

func BuildInvoiceFast(o Order) string {
	var b strings.Builder
	b.Grow(len(o.Items) * 32) // schätzungsweise vorgeben, mehrfaches Wachsen vermeiden
	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. Heap-Profil: Wer behält den Speicher?

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

Ein Heap-Profil enthält vier “sample index”. Du wählst den Index mit dem Flag -sample_index:

• inuse_space (Standard): Bytes, die derzeit am Leben sind beim letzten GC. Nutze dies, um Memory Leaks zu finden.
• inuse_objects: Anzahl der Objekte, die derzeit am Leben sind.
• alloc_space: Gesamtzahl der Bytes, die jemals allokiert wurden seit Programmbeginn. Nutze dies, um Druck auf den GC zu finden.
• alloc_objects: Gesamtzahl der Objekte, die jemals allokiert wurden.

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

Die Ausgabe zeigt, dass BuildInvoice insgesamt 1.84GB allokiert hat, obwohl der derzeit lebende Speicher sehr klein sein könnte. Das ist ein Zeichen, dass der GC viel arbeiten muss. Diese Situation passt zur Menge von runtime.mallocgc und runtime.scanobject, die du in dem CPU-Profil in Abschnitt 4 sehen kannst.

Hinweis: Heap-Profile sind auch Stichprobendaten (standardmäßig etwa 1 Stichprobe pro 512KB Allokation), daher sind die Zahlen nur Schätzungen. Vergleiche nicht einzelne Bytes, sondern schaue auf die Verhältnisse.

6. Goroutine-Profil: Goroutine Leaks erkennen

Wenn die Anzahl der Goroutinen ständig steigt, kannst du sie schnell im Browser oder mit curl anschauen, ohne go tool pprof zu brauchen:

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

Es gibt 10.398 Goroutinen, die alle bei payment.go:57 stecken. Das ist fast sicher ein Leak. Der fehlerhafte Code sieht normalerweise so aus:

func (s *PaymentService) notify(ctx context.Context, p Payment) {
	result := make(chan error) // unbuffered
	go func() {
		result <- s.gateway.Send(p) // steckt fest, wenn niemand empfängt
	}()
	select {
	case err := <-result:
		log.Println(err)
	case <-ctx.Done():
		return // innere Goroutine wird verlassen
	}
}

Wenn ctx vorher abläuft, liest niemand mehr result, daher bleibt die innere Goroutine für immer bei dem Send-Befehl stecken. Der einfache Fix ist make(chan error, 1), damit der Send-Befehl niemals blockiert.

Mit debug=2 druckt der Endpoint vollständige Stack Traces jeder Goroutine aus, mit Wartezeiten (z.B. [chan send, 42 minutes]). Diese Information ist sehr nützlich bei der Untersuchung von Deadlocks.

7. Block und Mutex Profile

Diese beiden Profile sind standardmäßig deaktiviert, da sie Kosten verursachen. Du aktivierst sie in main:

import "runtime"

func init() {
	// Erfasse durchschnittlich 1 Mutex-Contention-Ereignis von 5
	runtime.SetMutexProfileFraction(5)
	// Sample 1 Block-Ereignis für jeweils 10µs Blockierung
	runtime.SetBlockProfileRate(10_000)
}

Dann erfasst du Profile wie gewöhnlich:

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

Das Mutex-Profil zeigt, welche Locks Goroutinen warten lassen, z.B. ein sync.Mutex, das einen gemeinsamen Cache map[int]Customer schützt. Das Block-Profil zeigt, auf welchem Channel oder select Goroutinen lange warten.

Hinweis: SetBlockProfileRate(1) erfasst jedes Block-Ereignis. Diese Rate passt nur zum lokalen Debugging. In der Produktion nutze eine höhere Rate, oder aktiviere es nur vorübergehend.

8. Profiling von Benchmarks

Für eine bestimmte Funktion ist der kürzeste Weg, einen Benchmark zu schreiben und go test Profile generieren zu lassen. Der Code unten nutzt b.Loop(), daher braucht man Go 1.24 oder höher.

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("Ausgabe unterscheidet sich:\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)
	}
}

Der Test TestBuildInvoiceFastMatchesOriginal stellt sicher, dass die optimierte Version das gleiche Ergebnis wie die alte Version liefert. Überspringe diesen Schritt nicht: eine Optimierung, die falsche Ergebnisse liefert, ist sinnlos. Führe Benchmarks mit Profilen durch:

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

Die Version mit strings.Builder ist etwa 12-mal schneller und allokiert etwa 170-mal weniger. Das Flag -run='^$' überspringt normale Tests, um nur Benchmarks auszuführen. Die Dateien cpu.out und mem.out werden geöffnet mit:

go tool pprof -http=:8081 cpu.out

9. Profiling von CLI-Programmen mit runtime/pprof

Bei Werkzeugen, die einmal laufen und dann beenden, z.B. ein Job zum Importieren von Bestellungen, nutzt du direkt 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") // Hauptaufgabe

	memFile, err := os.Create("mem.out")
	if err != nil {
		log.Fatal(err)
	}
	defer memFile.Close()
	runtime.GC() // Aktualisiere inuse-Statistiken vor dem Schreiben
	if err := pprof.WriteHeapProfile(memFile); err != nil {
		log.Fatal(err)
	}
}

Zwei häufige Fehler sind hier:

• Das Aufrufen von log.Fatal oder os.Exit nach StartCPUProfile überspringt defer. Dann läuft StopCPUProfile nicht und die Profildatei ist leer oder beschädigt.
• Vergessen von runtime.GC() vor WriteHeapProfile. Die inuse_*-Statistiken werden nur nach jedem GC aktualisiert, daher kann das Profil einen alten Zustand widerspiegeln.

10. Vergleich zweier Profile

Nach der Optimierung solltest du erneut messen, anstatt dich auf ein Gefühl zu verlassen. Das Flag -diff_base subtrahiert das alte Profil vom neuen:

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

Negative Werte bedeuten, dass die Zeit gesunken ist. Damit die Ergebnisse aussagekräftig sind, müssen beide Profile unter den gleichen Bedingungen erfasst werden: gleiche Last, gleiche Dauer, gleiche Maschine.

Darüber hinaus dienen CPU-Profile ab Go 1.21 auch zur Profile-Guided Optimization (PGO). Du erfasst ein repräsentatives CPU-Profil aus der Produktion, benennst es default.pgo im main-Package-Verzeichnis, und go build nutzt dieses Profil automatisch, um Hot-Code-Pfade zu inlinen und zu optimieren. Die Verbesserungen liegen normalerweise bei wenigen Prozenten, und du musst keinen Code ändern.

11. Häufige Fehler und wann man pprof nicht verwenden sollte

• Zu kurze oder unlastete Profile. CPU-Profile samplen bei 100Hz. Wenn du nur 2 Sekunden während Service-Idle erfasst, siehst du nur runtime und Rauschen.
• flat mit cum verwechseln. Eine Funktion mit hohem cum ist nicht zwingend der Schuldige, möglicherweise ruft sie nur den Schuldigen auf.
• inuse_space mit alloc_space verwechseln. Zum Finden von Leaks schaue auf inuse. Um GC-Druck zu reduzieren, schaue auf alloc.
• I/O mit CPU-Profil messen. Die Zeit, in der eine Goroutine auf die Datenbank oder HTTP wartet, verbraucht keine CPU und erscheint nicht im CPU-Profil. Nutze stattdessen das Block-Profil, go tool trace oder verteiltes Tracing.
• pprof auf dem öffentlichen Anwendungs-Port exponieren. Siehe wieder Abschnitt 3.

Hinweis: pprof beantwortet die Frage “wo wird Ressource verbraucht”, nicht “sollte man optimieren”. Wenn ein Endpoint bereits SLA erfüllt und eine Funktion nur 2% CPU verbraucht, lohnt es sich normalerweise nicht, sie komplexer umzuschreiben.

12. Fazit

In diesem Artikel hast du:

• net/http/pprof sicher auf einem separaten Server bei localhost aktiviert;
• CPU-Profile mit top und list gelesen und flat von cum unterschieden;
• Heap-Profile mit inuse_space und alloc_space genutzt;
• Goroutine Leaks mit debug=1 und debug=2 erkannt;
• Block und Mutex Profile aktiviert;
• Profile von Benchmarks und CLI-Programmen generiert;
• Vorher-/Nachher-Profile mit -diff_base verglichen.

Der effektivste Prozess ist immer noch: messen → Hot Spots finden → reparieren → Tests schreiben, um Verhalten zu erhalten → erneut messen. Mit pprof in der Standardbibliothek brauchst du keine zusätzliche Installation, um zu beginnen.