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: memory profiler is inaccurate when GOMAXPROCS>1 #6566

Closed
rhysh opened this issue Oct 11, 2013 · 9 comments
Closed

runtime: memory profiler is inaccurate when GOMAXPROCS>1 #6566

rhysh opened this issue Oct 11, 2013 · 9 comments
Milestone

Comments

@rhysh
Copy link
Contributor

rhysh commented Oct 11, 2013

I'm finding that memory profiling is inaccurate in recent versions of tip. Allocations
are underreported, and frees are underreported even further (making it look like vast
amounts of memory are still in use).

I've written a test that demonstrates this behavior - it's at
http://play.golang.org/p/QUMOyGNTIg . Ten worker goroutines allocate a total of 1
million 8kB slices. The alloc/free counts from runtime.ReadMemStats are correct, but the
figures from runtime.MemProfile (used by e.g. net/http/pprof) are inaccurate.

The test passes with go1.1.2, it passes with GOMAXPROCS=1, and it passes if there's only
one goroutine allocating memory.

It fails on recent versions of tip with GOMAXPROCS=2 with several goroutines allocating
memory.



$ ./go1.1.2/bin/go version
go version go1.1.2 linux/amd64
$ ./go1.1.2/bin/go test -cpu=1 ~/profile_test.go 
ok      command-line-arguments  3.180s
$ ./go1.1.2/bin/go test -cpu=2 ~/profile_test.go 
ok      command-line-arguments  4.916s

$ ./go1.2.094fb360be8d/bin/go version
go version devel +094fb360be8d Tue Oct 08 16:53:56 2013 +1100 linux/amd64
$ ./go1.2.094fb360be8d/bin/go test -cpu=1 ~/profile_test.go 
ok      command-line-arguments  4.233s
$ ./go1.2.094fb360be8d/bin/go test -cpu=2 ~/profile_test.go 
--- FAIL: TestProfileLeak-2 (3.92 seconds)
    profile_test.go:38: found bucket: size 8192, count 1000000
    profile_test.go:84: n1 707328, s1 5794430976
    profile_test.go:93: n2 37248, s2 305135616
    profile_test.go:97: poor accuracy when measuring accuracy: 70.7% of allocations reported
    profile_test.go:101: profiler claims garbage: 37248 slices totalling 305135616 bytes
FAIL
FAIL    command-line-arguments  3.927s

$ ./go1.2.5f680cab75f6/bin/go version
go version devel +5f680cab75f6 Fri Oct 11 11:30:03 2013 +1100 linux/amd64
$ ./go1.2.5f680cab75f6/bin/go test -cpu=1 ~/profile_test.go
ok      command-line-arguments  4.203s
$ ./go1.2.5f680cab75f6/bin/go test -cpu=2 ~/profile_test.go
--- FAIL: TestProfileLeak-2 (5.22 seconds)
    profile_test.go:38: found bucket: size 8192, count 1000000
    profile_test.go:84: n1 674240, s1 5523374080
    profile_test.go:93: n2 30848, s2 252706816
    profile_test.go:97: poor accuracy when measuring accuracy: 67.4% of allocations reported
    profile_test.go:101: profiler claims garbage: 30848 slices totalling 252706816 bytes
FAIL
FAIL    command-line-arguments  5.219s
@rhysh
Copy link
Contributor Author

rhysh commented Oct 14, 2013

Comment 1:

I bisected this and it looks to be related to goroutine preemption [1]. Looking at
src/pkg/runtime/mprof.goc [2], it looks like this could happen when a goroutine is
preempted during runtime·MProf_Malloc (or runtime·MProf_Free) after incrementing
m->nomemprof . If another goroutine runs on the same M* in the meantime, it will see
that m->nomemprof is set and not record the malloc/free.
Does my analysis sound correct?
Can preemption be disabled for specific runtime functions? Or maybe there's a different
way to avoid the deadlock that m->nomemprof prevents?
[1]
The first bad revision is:
changeset:   17451:a5b5cbb9bd3d
user:        Dmitriy Vyukov <dvyukov@google.com>
date:        Tue Jul 30 22:17:38 2013 +0400
summary:     runtime: enable goroutine preemption
[2] http://tip.golang.org/src/pkg/runtime/mprof.goc#L248
[3]
https://code.google.com/p/go/source/diff?spec=svn9e1fd312d1bd4c0d4202fc9795f55a4d867c52c4&old=0cdceeba29f24c7dedb650f67b9d66a6705b52f9&r=9e1fd312d1bd4c0d4202fc9795f55a4d867c52c4&format=unidiff&path=%2Fsrc%2Fpkg%2Fruntime%2Fsymtab.c

@minux
Copy link
Member

minux commented Oct 15, 2013

Comment 2:

probably worth solving for Go 1.2.

Labels changed: added go1.2maybe.

Status changed to Accepted.

@dvyukov
Copy link
Member

dvyukov commented Oct 15, 2013

Comment 3:

Owner changed to @dvyukov.

@dvyukov
Copy link
Member

dvyukov commented Oct 15, 2013

Comment 4:

Status changed to Started.

@rsc
Copy link
Contributor

rsc commented Oct 15, 2013

Comment 5:

Unless the fix is trivial, let's put this off until Go 1.3.

@dvyukov
Copy link
Member

dvyukov commented Oct 16, 2013

Comment 6:

I've mailed the fix yesterday:
https://golang.org/cl/14695044/
It only deletes code, so in some sense it's trivial :)

@rsc
Copy link
Contributor

rsc commented Oct 17, 2013

Comment 7:

Issue #6592 has been merged into this issue.

@dvyukov
Copy link
Member

dvyukov commented Oct 18, 2013

Comment 8:

This issue was closed by revision f632970.

Status changed to Fixed.

@adg
Copy link
Contributor

adg commented Oct 31, 2013

Comment 9:

This issue was closed by revision 26de80888166.

@rsc rsc added this to the Go1.2 milestone Apr 14, 2015
@rsc rsc removed the go1.2maybe label Apr 14, 2015
adg added a commit that referenced this issue May 11, 2015
««« CL 14695044 / 35d5bae6aac8
runtime: remove nomemprof
Nomemprof seems to be unneeded now, there is no recursion.
If the recursion will be re-introduced, it will break loudly by deadlocking.
Fixes #6566.

R=golang-dev, minux.ma, rsc
CC=golang-dev
https://golang.org/cl/14695044
»»»

R=golang-dev, dsymonds
CC=golang-dev
https://golang.org/cl/20540043
@golang golang locked and limited conversation to collaborators Jun 25, 2016
This issue was closed.
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

6 participants