Ramblings of an aging IT geek
← Ramblings of an aging IT geek
golang

where a go service actually spends its time

A quick note on attaching pprof to a Go service under real load and being surprised by where the CPU went.

A terminal showing code

A service was burning more CPU than its job warranted, and I had a theory. I always have a theory. It was the database layer, obviously, or the JSON marshalling, one of the two.

It was neither. I wired in net/http/pprof, hit the service with a load generator, and pulled a thirty-second CPU profile with go tool pprof. The flame graph put nearly a fifth of the time in time.Format, of all things. We were stamping a formatted timestamp onto every single log line, on the hot path, for logs nobody read at that volume.

The fix was to log at a sensible level and drop the per-request timestamp string in favour of letting the log backend add it once. CPU fell by roughly that same fifth, no clever algorithm required.

The lesson is the old one, and I keep relearning it. My intuition about where the time goes is worth nothing. The profiler is worth everything, and it takes two minutes to attach. Measure first, then be embarrassed, then fix the thing that was actually there.