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

cmd/go: tool pprof gives no samples #24443

Closed
robpike opened this issue Mar 19, 2018 · 19 comments
Closed

cmd/go: tool pprof gives no samples #24443

robpike opened this issue Mar 19, 2018 · 19 comments
Labels
FrozenDueToAge NeedsDecision Feedback is required from experts, contributors, and/or the community before a change can be made.
Milestone

Comments

@robpike
Copy link
Contributor

robpike commented Mar 19, 2018

Title says it all. Here is evidence. Applies to other packages too.

dunnart=% go test -bench=. -run=X -memprofile=mem.profile -benchtime=2s
goos: darwin
goarch: amd64
pkg: fmt
BenchmarkSprintfPadding-4                  	20000000	       154 ns/op
BenchmarkSprintfEmpty-4                    	200000000	        14.1 ns/op
BenchmarkSprintfString-4                   	100000000	        39.7 ns/op
BenchmarkSprintfTruncateString-4           	50000000	        71.0 ns/op
BenchmarkSprintfSlowParsingPath-4          	50000000	        47.1 ns/op
BenchmarkSprintfQuoteString-4              	10000000	       276 ns/op
BenchmarkSprintfInt-4                      	100000000	        32.0 ns/op
BenchmarkSprintfIntInt-4                   	50000000	        61.1 ns/op
BenchmarkSprintfPrefixedInt-4              	30000000	        76.4 ns/op
BenchmarkSprintfFloat-4                    	30000000	       109 ns/op
BenchmarkSprintfComplex-4                  	10000000	       291 ns/op
BenchmarkSprintfBoolean-4                  	100000000	        33.9 ns/op
BenchmarkSprintfHexString-4                	30000000	        84.3 ns/op
BenchmarkSprintfHexBytes-4                 	30000000	       103 ns/op
BenchmarkSprintfBytes-4                    	20000000	       217 ns/op
BenchmarkSprintfStringer-4                 	20000000	       179 ns/op
BenchmarkSprintfStructure-4                	 5000000	       624 ns/op
BenchmarkManyArgs-4                        	20000000	       230 ns/op
BenchmarkFprintInt-4                       	50000000	        68.8 ns/op
BenchmarkFprintfBytes-4                    	30000000	        99.9 ns/op
BenchmarkFprintIntNoAlloc-4                	50000000	        67.9 ns/op
BenchmarkScanInts-4                        	   10000	    339172 ns/op
BenchmarkScanRecursiveInt-4                	     100	  37335596 ns/op
BenchmarkScanRecursiveIntReaderWrapper-4   	     100	  38010257 ns/op
PASS
ok  	fmt	83.410s
dunnart=% go tool pprof fmt.test mem.profile
File: fmt.test
Type: inuse_space
Time: Mar 19, 2018 at 3:17pm (AEDT)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top5
Showing nodes accounting for 0, 0% of 0 total
      flat  flat%   sum%        cum   cum%
(pprof) dunnart=% ls -l mem.profile 
-rw-r--r--  1 r  eng  3174 Mar 19 15:17 mem.profile
dunnart=% 

Please answer these questions before submitting your issue. Thanks!

What version of Go are you using (go version)?

go version devel +baf3eb1625 Tue Mar 6 01:11:26 2018 +0000 darwin/amd64

Does this issue reproduce with the latest release?

Not tested.

What operating system and processor architecture are you using (go env)?

GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/r/Library/Caches/go-build"
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/r"
GORACE=""
GOROOT="/Users/r/go"
GOTMPDIR=""
GOTOOLDIR="/Users/r/go/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/bf/qmf6xmzn7vs1gzv6g7mq_wfr0004fc/T/go-build412122499=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

See above.

@ALTree
Copy link
Member

ALTree commented Mar 19, 2018

The samples are there, but the inuse_space default for the memprofile is... unfortunate. It can be changed using the sample_index command.

$ go tool pprof fmt.test mem.profile
File: fmt.test
Type: inuse_space
Time: Mar 19, 2018 at 9:51am (CET)
Entering interactive mode (type "help" for commands, "o" for options)

(pprof) top5       
Showing nodes accounting for 0, 0% of 0 total
      flat  flat%   sum%        cum   cum%

(pprof) sample_index = alloc_space

(pprof) top5
Showing nodes accounting for 11051.10MB, 94.73% of 11666.12MB total
Dropped 22 nodes (cum <= 58.33MB)
Showing top 5 nodes out of 33
      flat  flat%   sum%        cum   cum%
 9026.02MB 77.37% 77.37%  9838.06MB 84.33%  fmt.Sprintf
  676.52MB  5.80% 83.17%  2286.14MB 19.60%  fmt_test.BenchmarkSprintfHexBytes.func1
  655.52MB  5.62% 88.79%   655.52MB  5.62%  fmt_test.BenchmarkFprintfBytes
  359.03MB  3.08% 91.87%   359.03MB  3.08%  reflect.mapiterinit
  334.01MB  2.86% 94.73%  1009.05MB  8.65%  fmt_test.BenchmarkSprintfBytes.func1

@mvdan
Copy link
Member

mvdan commented Mar 19, 2018

I tend to do go tool pprof -alloc_space (but apparently those flags are legacy?)

@andybons andybons added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Mar 19, 2018
@andybons andybons added this to the Go1.11 milestone Mar 19, 2018
@andybons
Copy link
Member

@hyangah

@robpike
Copy link
Contributor Author

robpike commented Mar 19, 2018

/cc @adg

@josharian
Copy link
Contributor

Related: google/pprof#182

Could we make pprof require a flag for memory profiles indicating which kind is wanted instead of defaulting to inuse_space (which is almost never what I want)? The default seems to be a source of significant, persistent confusion.

@hyangah
Copy link
Contributor

hyangah commented Mar 19, 2018

For live server profiling inuse_space is more meaningful than the alloc_space.
Moreover, memory profiling libraries for other languages (e.g. C++) often choose to report only inuse_* equivalent metrics.

@ALTree
Copy link
Member

ALTree commented Mar 19, 2018 via email

@cespare
Copy link
Contributor

cespare commented Mar 19, 2018

For live server profiling inuse_space is more meaningful than the alloc_space.

@hyangah this doesn't match my experience. I run memory profiles on live servers with alloc_space more often than with inuse_space. The most common reason that I run a memory profile is as part of performance optimizations and reducing allocations is a really common optimization. inuse_space is useful for debugging leaks (and, rarely, surprisingly-large-but-not-growing heaps), which I do less often.

This might be different from C++ where it's easier to write memory leaks.

@hyangah
Copy link
Contributor

hyangah commented Mar 19, 2018

@cespare not only memory leak. inuse_space is one of the first places to look into when optimizing the memory usage in stable state or comparing multiple different instances with different configuration. alloc_space is of course useful for allocation optimization.

For benchmark or test or short running programs, this doesn't make much - why do we care about the inuse_space from the last GC after the end of the program, right? @rauls5382 and @aalexand, is there any way to tell pprof to choose alloc_space over inuse_space for such profile data? For example, what do you think about recording preferred value sample index in the profile, or just dropping inuse_space samples from benchmark or test generated profile out?

@robpike
Copy link
Contributor Author

robpike commented Mar 20, 2018

I'd settle for a print statement conditioned by no output that suggests trying another index and a way to find out what they are.

@aalexand
Copy link
Contributor

@hyangah default_sample_type field in the profile can be used to specify the metric to display by default. See https://github.com/google/pprof/blob/e8d30eee164b66e3e349506f2bd220395cd2c9d1/proto/profile.proto#L82.

@aalexand
Copy link
Contributor

To echo the other discussions here, I think inuse_space is more useful for long-running servers than alloc_space, so if the default metric is going to change for anything other than the local "go tool" runs, please let users know in advance. I'd opt against that since alloc_space is currently cumulative since program start which makes it difficult to aggregate across different replicas of a server or over time unless some custom normalization is applied.

@ALTree ALTree added NeedsDecision Feedback is required from experts, contributors, and/or the community before a change can be made. and removed NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. labels Mar 20, 2018
aalexand pushed a commit to google/pprof that referenced this issue Mar 20, 2018
…336)

In the interactive mode, inform users of different sample types
if the profile includes zero samples for selected sample type
by default (or through user-provided sample_index flag value).

The example output may look like

$ pprof mem.prof
Type: inuse_space
Time: Mar 20, 2018 at 11:36am (EDT)

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)

Update golang/go#24443
@gopherbot
Copy link

Change https://golang.org/cl/101677 mentions this issue: runtime/pprof: comment on sample types in heap profile

@hyangah
Copy link
Contributor

hyangah commented Mar 20, 2018

Thanks @aalexand
I looked into a way to set the default_sample_type differently for memory profiles produced during test but it is trickier than I hoped. What I can think of are either 1) change runtime/pprof.WriteHeapProfile to accept an option, or 2) use a magical environment variable so if it's set mark alloc_space as the default_sample_type. None of them seems like a minor change to me.

My PR to add a print statement in case of zero sample was merged to upstream. I will try to update the vendored version of pprof as well.

The change 101677 is to additionally embed comments in the generated profile output - they explain what those different measurement types are.

@gopherbot
Copy link

Change https://golang.org/cl/101736 mentions this issue: cmd/vendor/.../pprof: refresh from upstream@a74ae6f

gopherbot pushed a commit that referenced this issue Mar 23, 2018
Merges updates listed in
google/pprof@0e0e5b7...a74ae6f

Update #24443

cmd/vendor/vendor.json was updated manually.

Change-Id: I15d5fe82ac18263d4d54f5773cee0e197e93dd59
Reviewed-on: https://go-review.googlesource.com/101736
Reviewed-by: Alberto Donizetti <alb.donizetti@gmail.com>
@rsc
Copy link
Contributor

rsc commented Mar 27, 2018

One thing we could do is introduce a new named profile that means "heap allocations for all time" and make it the same as the regular heap profile but with a different default. Then -memprofile can write that new profile out instead of the old one.

Go runtime/pprof.WriteMemProfile is equivalent to runtime/pprof.Lookup("heap").WriteTo, so we'd just have a new name "allocs" or something like that, which is almost exactly the same output, with a different default. Then you can ask for it from running servers too.

@rsc
Copy link
Contributor

rsc commented Mar 27, 2018

/cc @hyangah see what you think of previous comment

@hyangah
Copy link
Contributor

hyangah commented Mar 27, 2018

SGTM

@gopherbot
Copy link

Change https://golang.org/cl/102696 mentions this issue: runtime/pprof: introduce "allocs" profile

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge NeedsDecision Feedback is required from experts, contributors, and/or the community before a change can be made.
Projects
None yet
Development

No branches or pull requests

10 participants