Finding an allocation leak with Go's pprof

One of our services had a memory graph that looked like a staircase. RSS climbed a few megabytes an hour, never came back down, and after about nine days the OOM killer stepped in. A restart reset the clock. Classic slow leak, and the kind that's annoying precisely because nothing is obviously wrong.

Go makes this one easier than it has any right to be, because net/http/pprof is basically free to turn on. If you already run an HTTP server, you add one import for its side effects:

import _ "net/http/pprof"

func main() {
    go func() {
        log.Println(http.ListenAndServe("127.0.0.1:6060", nil))
    }()
    // ... the real server
}

I bind it to 127.0.0.1 deliberately — the profiling endpoints should never be reachable from outside the box. On a server I reach them over an SSH tunnel.

Two snapshots, one diff

A single heap profile tells you what's allocated right now, which is noisy. What you actually want is the difference between two points in time. So I grabbed a baseline shortly after a restart, waited a couple of hours for the leak to accumulate, and grabbed a second one:

curl -s http://127.0.0.1:6060/debug/pprof/heap > heap.0
sleep 7200
curl -s http://127.0.0.1:6060/debug/pprof/heap > heap.1

go tool pprof -base heap.0 heap.1

The -base flag is the whole trick. It subtracts the first profile from the second, so everything that was steady-state cancels out and only the growth remains. Inside the interactive prompt, top sorts by the biggest contributors:

(pprof) top
Showing nodes accounting for 412MB, 98.1% of 420MB total
      flat  flat%   sum%        cum   cum%
     402MB 95.7%  95.7%      402MB 95.7%  example/cache.(*Store).Put
         ...

By default the heap profile shows inuse_space — memory still live at the time of the sample. That's what you want for a leak. If you're chasing allocation churn (GC pressure rather than a leak), switch to -sample_index=alloc_space instead, which counts everything ever allocated.

The actual bug

The list command annotates source lines with their allocations. Pointing it at the offender was immediate:

(pprof) list Store.Put
    .          .    func (s *Store) Put(key string, v []byte) {
    .          .        s.mu.Lock()
    .          .        defer s.mu.Unlock()
 402MB      402MB        s.items[key] = entry{v, time.Now()}
    .          .    }

An in-memory cache with a TTL field on every entry — and nothing that ever read that field to evict anything. The expiry had been written, the sweeper never had. The map only grew. The fix was a dozen lines: a background goroutine that walks the map on a ticker and deletes expired keys under the lock.

If you prefer pictures to tables, go tool pprof -http=:8080 -base heap.0 heap.1 opens a flame graph in the browser, which makes a deep call stack much easier to read than top. For a flat leak like this one the text view was enough.

What I'd tell past me

• Always diff two profiles. A lone snapshot sends you chasing allocations that are perfectly healthy.
• Know which sample index you're looking at. inuse_space for leaks, alloc_space for GC pressure. They tell different stories.
• Bind the pprof listener to localhost and reach it through a tunnel. It exposes more than you'd want public.
• The leak is usually a map or a slice that only appends. When memory only goes up, look for the thing that only grows.

Total time from "the graph looks wrong" to merged fix was about half an hour, most of it waiting for the second snapshot to accumulate. For a class of bug that used to mean staring at code hoping to spot the one missing delete, that's a good trade.