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: memory profiles appear to undercount allocations #10537

Closed
josharian opened this issue Apr 22, 2015 · 4 comments
Closed

runtime/pprof: memory profiles appear to undercount allocations #10537

josharian opened this issue Apr 22, 2015 · 4 comments
Milestone

Comments

@josharian
Copy link
Contributor

Apologies in advance that this is vague.

I was looking recently into compiler allocations, and because I wanted to know the breakdown by type, I hacked up tracealloc and friends in mprof.go to print exactly one line per allocation and nothing else (including suppressing output in tracefree and tracegc). Surprisingly, this output differs significantly from that reported by the memory profiler, even at runtime.MemProfileRate=1.

For example, running go tool 6g -memprofile=mem.prof html/template/*.go and then running go tool pprof -alloc_objects yields a count of 458,794 allocations, almost none of which are from cmd/internal/gc.walkexpr.

Setting runtime.MemProfileRate=1 and repeating the experiment turns up 607,429 allocations, 5.87% of which are from cmd/internal/gc.walkexpr. (The np **Node parameter escapes, causing an allocation of a *Node, which is only 8 bytes, thus the previous significant undercounting.)

Running with GODEBUG=allocfreetrace=1 go tool 6g html/template/* 2>&1 | grep "tracealloc" | wc -l yields 1,032,392 allocations, which is 70% more than reported by the memory profiler! This number is very stable across repeated runs, with variation less than 0.01%. Only logging allocs with size > 16 in tracealloc yields a count of 740,816 allocations, so this is probably not a tiny alloc issue.

There are probably multiple things to do here:

  • Understand the mismatch and fix the memory profiler.
  • Add a memprofilerate flag to the compiler.
  • Warn in pprof when -alloc_objects is used with memprofilerate != 1, because allocation counts can be dramatically skewed by the size of the allocation.

/cc @rsc @dr2chase @dvyukov

@josharian josharian added this to the Go1.5 milestone Apr 22, 2015
@josharian
Copy link
Contributor Author

Sent CL 9261 to add a memprofilerate flag to the compiler.

@dvyukov
Copy link
Member

dvyukov commented Apr 23, 2015

If you execute runtime.GC 3 times before collecting memory profile, does it help?

@josharian
Copy link
Contributor Author

@dvyukov sigh, yes. I ought to know better. Thanks. I'll update the CL.

Regarding the (now deleted?) comment from someone else about the name memprofilerate, it matches the flag name in go test.

josharian added a commit to josharian/go that referenced this issue Apr 24, 2015
Also call runtime.GC before exit to ensure
that the profiler picks up all allocations.

Fixes golang#10537.

Change-Id: Ibfbfc88652ac0ce30a6d1ae392f919df6c1e8126
@gopherbot
Copy link

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

josharian added a commit to josharian/go that referenced this issue May 1, 2015
Also call runtime.GC before exit to ensure
that the profiler picks up all allocations.

Fixes golang#10537.

Change-Id: Ibfbfc88652ac0ce30a6d1ae392f919df6c1e8126
@golang golang locked and limited conversation to collaborators Jun 25, 2016
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

3 participants