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

Jump to bottom

runtime/pprof: weird allocation counts after reading a file of a certain minimum size #11343

Closed
jacobsa opened this issue Jun 23, 2015 · 7 comments
Closed

runtime/pprof: weird allocation counts after reading a file of a certain minimum size #11343

jacobsa opened this issue Jun 23, 2015 · 7 comments
Labels
FrozenDueToAge
Milestone
Go1.5

Comments

@jacobsa
Copy link
Contributor

jacobsa commented Jun 23, 2015

Here is a gist containing a program that does the following:

  1. Set runtime.MemProfileRate to 1.
  2. Read a flag-controlled number of zeroes from /dev/zero using ioutil.ReadAll and io.LimitReader.
  3. Call io.MultiWriter 1024 times in a loop, encouraging it to make allocations.
  4. Write out a heap profile to /tmp/mem.pprof.

When I run the program with the flag that tells it to read 2096128 bytes before calling io.MultiWriter, I see the expected number of calls in the profile:

% go build main.go && ./main --size 2096128 && grep -B 1 MultiWriter /tmp/mem.pprof
1024: 32768 [1024: 32768] @ 0x43aaf5 0x45dd38 0x400f60 0x4010a1 0x42a3ff 0x456331
#       0x45dd38        io.MultiWriter+0x48     /usr/local/google/home/jacobsa/clients/go/src/io/multi.go:58
--
996: 31872 [1024: 32768] @ 0x45dda3 0x400f60 0x4010a1 0x42a3ff 0x456331
#       0x45dda3        io.MultiWriter+0xb3     /usr/local/google/home/jacobsa/clients/go/src/io/multi.go:60

However, with any value above this I get unreliable results (these change from run to run, but are never the full count and are often zero):

% go build main.go && ./main --size 2096129 && grep -B 1 MultiWriter /tmp/mem.pprof
0: 0 [0: 0] @ 0x45dda3 0x400f60 0x4010a1 0x42a3ff 0x456331
#       0x45dda3        io.MultiWriter+0xb3     /usr/local/google/home/jacobsa/clients/go/src/io/multi.go:60
--
0: 0 [0: 0] @ 0x43aaf5 0x45dd38 0x400f60 0x4010a1 0x42a3ff 0x456331
#       0x45dd38        io.MultiWriter+0x48     /usr/local/google/home/jacobsa/clients/go/src/io/multi.go:58

This shows up as nonsense callgraphs in pprof, containing lots of runtime frames and the wrong counts for the functions I'm interested in. Compare this one to this one. Each is from an invocation of pprof that looks like:

go tool pprof -alloc_objects ~/tmp/59f9bbfa096fd3c595dc/main /tmp/mem.pprof

I have been unable to simplify the test case further. In particular, merely allocating a slice of bytes of the given size isn't good enough; it seems I have to open and read a file. I've also seen the problem when not setting runtime.MemProfileRate to a non-default value, but it is harder to reproduce.

go version:

go version devel +f2662f2 Tue Jun 23 03:18:52 2015 +0000 linux/amd64
@bradfitz bradfitz added this to the Go1.5 milestone Jun 23, 2015
@bradfitz
Copy link
Contributor

Marking this Go1.5 so we at least understand what's happening.

@rsc
Copy link
Contributor

rsc commented Jul 23, 2015

The heap profile reports a snapshot as of the most recent garbage collection. It omits more recent allocations, because otherwise the recent garbage in the profile can drown out the older live data. What's going on in your program is that the size of the read affects whether a garbage collection happens after the multiwriters are created. If so, they appear in the profile; if not, they don't.

If you want to see a snapshot of live data as of the writing of the profile, you need to call runtime.GC before writing out the profile. If you only care about allocation counts and not what is live, then you can also use GOGC=off. When the GC is off, the profile reports all allocations (since there's no "last GC").

So this is working as intended, if possibly mysteriously. I will update the runtime/pprof doc comment to make this clear.

@jacobsa
Copy link
Contributor Author

jacobsa commented Jul 23, 2015

Thanks so much for the explanation. Sticking something similar in the docs sounds good to me.

@jacobsa
Copy link
Contributor Author

jacobsa commented Jul 23, 2015

Oh, to clarify: when you say "see a snapshot of live data", do you mean to say only objects that are still live? Or can I call runtime.GC just before writing the file to see historical allocation counts, even for objects that have long since been collected?

@gopherbot
Copy link

CL https://golang.org/cl/12556 mentions this issue.

@rsc
Copy link
Contributor

rsc commented Jul 23, 2015

@jacobsa Each profile line gives n: m [N: M] for a particular allocation stack, where n: m is currently allocated (live) objects, and N: M is all objects. pprof --inuse_xxx uses n: m and pprof --alloc_xxx uses N: M. What I mean by "a snapshot of live data" is really "a snapshot of right now", because those are updated only at each GC.

@jacobsa
Copy link
Contributor Author

jacobsa commented Jul 23, 2015

Got it, thanks for confirming.

@rsc rsc closed this as completed in 6b87621 Jul 27, 2015
@mikioh mikioh changed the title pprof: weird allocation counts after reading a file of a certain minimum size runtime/pprof: weird allocation counts after reading a file of a certain minimum size Jul 28, 2015
@golang golang locked and limited conversation to collaborators Aug 5, 2016
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge
Projects
None yet
Milestone
Go1.5
Development

No branches or pull requests
4 participants
@bradfitz @rsc @jacobsa @gopherbot