Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
seehuhn opened this issue Jan 27, 2024 · 10 comments
Labels
compiler/runtime Issues related to the Go compiler and/or runtime. Documentation help wanted NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone

Comments

@seehuhn
Copy link

seehuhn commented Jan 27, 2024

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
Copy link
Author

seehuhn commented Jan 27, 2024

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
Copy link
Member

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

@seankhliao seankhliao closed this as not planned Won't fix, can't repro, duplicate, stale Jan 27, 2024
@seehuhn
Copy link
Author

seehuhn commented Jan 27, 2024

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

@seehuhn
Copy link
Author

seehuhn commented Jan 27, 2024

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
Copy link
Member

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
Copy link
Author

seehuhn commented Jan 27, 2024

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 dominikh reopened this Jan 27, 2024
@dominikh
Copy link
Member

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

@seankhliao seankhliao changed the title memory profiling does not work as documented runtime/pprof: WriteHeapProfile example is not strictly equivalent to testing memprofile Jan 27, 2024
@gopherbot gopherbot added the compiler/runtime Issues related to the Go compiler and/or runtime. label Jan 27, 2024
@seankhliao seankhliao added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Jan 27, 2024
@mknyszek
Copy link
Contributor

mknyszek commented Feb 7, 2024

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.

@mknyszek mknyszek added this to the Backlog milestone Feb 7, 2024
@aclements
Copy link
Member

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
Copy link
Contributor

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
compiler/runtime Issues related to the Go compiler and/or runtime. Documentation help wanted NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
Development

No branches or pull requests

6 participants