Chapter 81 -- Profiling Go on Linux: pprof, the execution tracer, and perf

Build it in Go (30 min) -- find two planted bugs

// profiled: a service with two planted bugs -- a CPU hot spot and a goroutine
// leak -- and the profiling endpoints that find them.
//
//	go run ./profiled -load 8 &          # serve, and hammer ourselves with 8 clients
//	go tool pprof -top -seconds 5 http://localhost:6060/debug/pprof/profile
//	curl -s 'localhost:6060/debug/pprof/goroutine?debug=1' | head -20
package main

import (
	"flag"
	"fmt"
	"io"
	"log"
	"net/http"
	_ "net/http/pprof" // registers /debug/pprof/* on the default mux
	"regexp"
	"runtime"
	"time"
)

func main() {
	load := flag.Int("load", 0, "also run N client goroutines against ourselves")
	flag.Parse()

	// BUG 1: the regexp is compiled on EVERY request. Correct code compiles it
	// once, at package level: var emailRE = regexp.MustCompile(...)
	http.HandleFunc("/validate", func(w http.ResponseWriter, r *http.Request) {
		re := regexp.MustCompile(`^[a-zA-Z0-9._%+-]+@[a-zA-Z0-9.-]+\.[a-zA-Z]{2,}$`)
		fmt.Fprintln(w, re.MatchString(r.URL.Query().Get("email")))
	})

	// BUG 2: a goroutine waits for a reply that never comes. Each request leaks
	// one goroutine (and everything it references), forever.
	http.HandleFunc("/notify", func(w http.ResponseWriter, r *http.Request) {
		reply := make(chan string) // unbuffered, and nobody ever sends
		go func() {
			select {
			case msg := <-reply:
				log.Println(msg)
				// FIX: add `case <-time.After(5 * time.Second): return` or a context
			}
		}()
		fmt.Fprintln(w, "queued")
	})

	go func() { // a cheap "leak alarm": watch the goroutine count
		for range time.Tick(5 * time.Second) {
			log.Printf("goroutines: %d", runtime.NumGoroutine())
		}
	}()
	// Keep-alive pool big enough for every client goroutine. With Go's default
	// of 2 idle connections per host, the load generator itself would spend
	// its time opening and closing connections -- and dominate the profile.
	client := &http.Client{Transport: &http.Transport{MaxIdleConnsPerHost: 64}}
	for i := 0; i < *load; i++ {
		go func() {
			time.Sleep(200 * time.Millisecond) // let the server start
			for n := 0; ; n++ {
				path := "/validate?email=user@example.com"
				if n%10 == 0 {
					path = "/notify"
				}
				if resp, err := client.Get("http://localhost:6060" + path); err == nil {
					io.Copy(io.Discard, resp.Body)
					resp.Body.Close()
				}
			}
		}()
	}
	log.Println("listening on :6060 -- profiles at /debug/pprof/")
	log.Fatal(http.ListenAndServe("localhost:6060", nil)) // NEVER expose pprof publicly
}

$ go run ./profiled -load 8 &
$ go tool pprof -top -cum -seconds 5 http://localhost:6060/debug/pprof/profile
Duration: 5s, Total samples = 39.26s (784.98%)
     0.01s 0.025% 44.75%      4.47s 11.39%  main.main.func4          <- the load generator
         0     0% 53.36%      3.05s  7.77%  main.main.func1          <- the /validate handler
         0     0% 53.46%      2.62s  6.67%  regexp.MustCompile       <- 86% of the handler!
     0.01s 0.025% 53.49%      2.62s  6.67%  regexp.compile

$ curl -s 'localhost:6060/debug/pprof/goroutine?debug=1' | head -3
goroutine profile: total 493
489 @ 0x100ce1a7c 0x100c76a10 0x100c76584 0x100e94b88 0x100ce9094
#	0x100e94b87	main.main.func2.1+0x27	.../profiled/main.go:34      <- the leak, with its line number

What to notice:

• Read the cumulative (-cum) column for your own functions. The handler (func1) spent 3.05 s, and 2.62 s of that, 86%, was compiling a regexp that should have been compiled once at startup. The rest of the profile is loopback networking, because the load generator runs in the same process.
• The goroutine profile groups identical stacks: "489 @ ..." means 489 goroutines are stuck at the same place, main.go:34, the select waiting on a channel nobody sends to. The log line "goroutines: 243 → 491" in five seconds is the alarm. The profile is the diagnosis.
• An earlier version of this lab generated load with curl in a shell loop, and the CPU profile showed almost nothing: the bottleneck was starting curl processes, not the service. Then the in-process load generator used Go's default MaxIdleConnsPerHost of 2, and connection churn dominated the profile. Profiles describe the system as it's loaded. Make sure the load is realistic.
• Never expose /debug/pprof publicly. Profiles leak internals and are expensive. Bind to localhost or an admin port, as here.

Exercises:

1. Fix both bugs (compile the regexp once; add a timeout case to the select), rerun, and compare profiles: go tool pprof -diff_base old.pb.gz new.pb.gz.
2. Take a heap profile under load and run top -inuse_space. Where does the leaked goroutines' memory show up?
3. On Linux, run perf record -g -p $(pgrep profiled) -- sleep 5 and perf report. How much time is in the kernel's TCP stack?