runtime/pprof: ReadMemStats before writing heap profile

[josharian]

$ compilebench -run=Flate -alloc
BenchmarkFlate 1 174337267 ns/op 203717000 user-ns/op 24668880 B/op 238572 allocs/op
$ compilebench -run=Flate -alloc -memprofilerate=128
BenchmarkFlate 1 5448433394 ns/op 5393039000 user-ns/op 153120624 B/op 4721861 allocs/op
$ compilebench -run=Flate -alloc -memprofilerate=256
BenchmarkFlate 1 2914825084 ns/op 2869159000 user-ns/op 109857056 B/op 3202958 allocs/op

The allocs/op numbers should be more or less unchanged by memprofilerate. All that compilebench does is read the Mallocs number printed by the compiler, and the compiler's Mallocs number comes directly from runtime.ReadMemStats.

My simple attempts to reproduce directly using only runtime.ReadMemStats in a simple program have failed, though, and I'm out of time to investigate.

I'd be delighted if anyone reading this was willing to investigate enough to at least rule out a bug in runtime.ReadMemStats.

[nussjustin]

runtime.ReadMemStats works as expected. It's the pprof package that could be considered as wrong.

The problem you see is that writeHeap allocates some memory itself before reading the memstats. The amount of memory allocated basically only depends on the number of profile records, which depend on runtime.MemProfileRate.

When calling compilebench without -memprofilerate, compile uses the default runtime.MemProfileRate of 512KB, which will result in much less records in the profile as when setting it to 128 or 256. So with a factor of 4096 or 2048 (in your example) in difference between the profiling rates, it's clear that the allocations will be way higher.

If you move the call to runtime.ReadMemStats to the top, the resulting memstats will not include those extra allocations.

diff --git a/src/runtime/pprof/pprof.go b/src/runtime/pprof/pprof.go
index 21ea25ce36..1de9efc6d3 100644
--- a/src/runtime/pprof/pprof.go
+++ b/src/runtime/pprof/pprof.go
@@ -476,6 +476,8 @@ func countHeap() int {
 
 // writeHeap writes the current runtime heap profile to w.
 func writeHeap(w io.Writer, debug int) error {
+       s := new(runtime.MemStats)
+       runtime.ReadMemStats(s)
        // Find out how many records there are (MemProfile(nil, true)),
        // allocate that many records, and get the data.
        // There's a race—more records might be added between
@@ -538,8 +540,6 @@ func writeHeap(w io.Writer, debug int) error {
 
        // Print memstats information too.
        // Pprof will ignore, but useful for people
-       s := new(runtime.MemStats)
-       runtime.ReadMemStats(s)
        fmt.Fprintf(w, "\n# runtime.MemStats\n")
        fmt.Fprintf(w, "# Alloc = %d\n", s.Alloc)
        fmt.Fprintf(w, "# TotalAlloc = %d\n", s.TotalAlloc)

[josharian]

Thanks, Justin!

Marking as 1.10, since this doesn't appear to be a regression from 1.8.

[gopherbot]

Change https://golang.org/cl/80739 mentions this issue: runtime/pprof: read memstats earlier in profile handler