runtime/pprof: WriteHeapProfile example is not strictly equivalent to testing memprofile

[seehuhn]

Go version

go version go1.21.6 darwin/arm64

Output of go env in your module/workspace:

GO111MODULE=''
GOARCH='arm64'
GOBIN=''
GOCACHE='/Users/voss/Library/Caches/go-build'
GOENV='/Users/voss/Library/Application Support/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFLAGS=''
GOHOSTARCH='arm64'
GOHOSTOS='darwin'
GOINSECURE=''
GOMODCACHE='/Users/voss/go/pkg/mod'
GONOPROXY=''
GONOSUMDB=''
GOOS='darwin'
GOPATH='/Users/voss/go'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/usr/local/go'
GOSUMDB='sum.golang.org'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/usr/local/go/pkg/tool/darwin_arm64'
GOVCS=''
GOVERSION='go1.21.6'
GCCGO='gccgo'
AR='ar'
CC='clang'
CXX='clang++'
CGO_ENABLED='1'
GOMOD='/Users/voss/Desktop/xxx/go.mod'
GOWORK=''
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
PKG_CONFIG='pkg-config'
GOGCCFLAGS='-fPIC -arch arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -ffile-prefix-map=/var/folders/r0/d6scpgjj0h797bphr5dcmv5c0000gn/T/go-build3536875256=/tmp/go-build -gno-record-gcc-switches -fno-common'

What did you do?

I followed the instructions at https://pkg.go.dev/runtime/pprof#hdr-Profiling_a_Go_program , trying to get a memory profile of my program. Here is a short program, which illustrates the problem:

package main

import (
    "flag"
    "fmt"
    "log"
    "os"
    "runtime"
    "runtime/pprof"
)

var memprofile = flag.String("memprofile", "", "write memory profile to `file`")

func main() {
    flag.Parse()

    c := make(chan []float64)
    go func() {
        for i := 0; i < 1000; i++ {
            data := make([]float64, 16*1024)
            data[0] = float64(i)
            c <- data
        }
        close(c)
    }()

    var sum float64
    for data := range c {
        sum += data[0]
    }
    fmt.Println(sum)

    if *memprofile != "" {
        f, err := os.Create(*memprofile)
        if err != nil {
            log.Fatal("could not create memory profile: ", err)
        }
        defer f.Close() // error handling omitted for example
        runtime.GC()    // get up-to-date statistics
        if err := pprof.WriteHeapProfile(f); err != nil {
            log.Fatal("could not write memory profile: ", err)
        }
    }
}

What did you see happen?

The profiler did not report the memory allocations:

voss@dumpling [~/Desktop/xxx] go run . -memprofile=mem.prof
499500
voss@dumpling [~/Desktop/xxx] go tool pprof mem.prof
Type: inuse_space
Time: Jan 27, 2024 at 12:42pm (GMT)
No samples were found with the default sample value type.
Try "sample_index" command to analyze different sample values.
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 0, 0% of 0 total
      flat  flat%   sum%        cum   cum%

What did you expect to see?

I would have expected the line data := make([]float64, 16*1024) to feature prominently in the go tool pprof output.

[seehuhn]

There is some additional discussion (from long ago) on the golang-nuts mailing list: https://groups.google.com/g/golang-nuts/c/Bzgcn-9o1Yg/m/gLxGmXm-AAAJ

[dominikh]

Type: inuse_space

You are looking at the in-use space, of which there won't be any by the time you are taking the profile. Try go tool pprof --alloc_space mem.prof

[seehuhn]

Then, isn't the documentation at https://pkg.go.dev/runtime/pprof#hdr-Profiling_a_Go_program wrong, or at least very unhelpful?

[seehuhn]

Turns out the documentation is wrong! When I turn my code into a unit test, then go tool pprof mem.prof (without the extra option) shows the allocations, and the documentation claims that the code I used would "add equivalent profiling support to a standalone program", when my experiment shows it is different.

Here is my new code:

func TestMemprofile(t *testing.T) {
    c := make(chan []float64)
    go func() {
        for i := 0; i < 1000; i++ {
            data := make([]float64, 16*1024)
            data[0] = float64(i)
            c <- data
        }
        close(c)
    }()

    var sum float64
    for data := range c {
        sum += data[0]
    }
    fmt.Println(sum)
}

And here is how the pprof call now works as described in the docs (i.e. without the extra option):

voss@dumpling [~/Desktop/xxx] go test -memprofile=mem.prof
499500
PASS
ok      example.com/m   0.208s
voss@dumpling [~/Desktop/xxx] go tool pprof mem.prof
Type: alloc_space
Time: Jan 27, 2024 at 4:58pm (GMT)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 104.54MB, 100% of 104.54MB total
      flat  flat%   sum%        cum   cum%
  104.54MB   100%   100%   104.54MB   100%  example.com/m.TestMemprofile.func1

[dominikh]

You're correct that there is a slight difference between the behavior of testing and the suggested code snippet. testing writes a memory profile that defaults to alloc_sace, whereas pprof.WriteHeapProfile writes a memory profile that defaults to inuse_space. Both write the same profile that includes both sample types, but they default to different types.

[seehuhn]

Maybe this could be explained in the documentation: Maybe the example code in the documentation could be changed to match what testing is going? Or the difference between testing and the example code could be explained there, together with the --alloc_space option?

Or maybe WriteHeapProfile could be changed to be a shorthand for Lookup("allocs") instead of Lookup("heap")? After all, this function is documented as being "preserved for backwards compatibility", and the change would restore the original behaviour of this function and also would make the code on https://go.dev/blog/pprof work again.

[dominikh]

I have no opinions on that, but have reopened the issue so it'll be on the radar of the other team members.

[mknyszek]

In triage, we should probably align the default sample_index for the two profiles, but this problem doesn't seem too severe. (Ignoring the discoverability of different sample_index values; perhaps that should be mentioned in the documentation, if it isn't already.)

EDIT: Though, perhaps there are arguments for not aligning the two. I'm not sure.

[aclements]

I'm not sure we can/should align the two.

The testing package writes an alloc profile because the inuse profile is expected to be essentially empty and thus useless in tests.

On the other hand, pprof.WriteHeapProfile is documented to report a heap profile (aka inuse), so a change here would not be backwards compatible.

I agree that https://pkg.go.dev/runtime/pprof#hdr-Profiling_a_Go_program is a little misleading and could be improved.

[gopherbot]

Change https://go.dev/cl/597980 mentions this issue: runtime/pprof: note different between go test -memprofile and WriteHeapProfile