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.

Sign up for GitHub

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: finalizers misbehave with GC and heap profiling #3668

Closed
remyoudompheng opened this issue May 23, 2012 · 3 comments
Closed

runtime: finalizers misbehave with GC and heap profiling #3668

remyoudompheng opened this issue May 23, 2012 · 3 comments
Labels
FrozenDueToAge

Comments

@remyoudompheng
Copy link
Contributor 

What steps will reproduce the problem?
1. Compile and run the attached program with GOGCTRACE=1

What is the expected output? What do you see instead?

Expected: nothing particular. Little memory footprint in profile.
Seen: a large memory leak.

% GOGCTRACE=1 GOMAXPROCS=2 ./main
gc1(1): 0+0+0 ms, 0 -> 0 MB 195 -> 158 (196-38) objects, 0(0) handoff, 0/0/0 yields
0
gc2(2): 0+0+0 ms, 0 -> 0 MB 4420 -> 327 (4857-4530) objects, 4(36) handoff,
20/20/4 yields
gc3(2): 1+0+0 ms, 0 -> 0 MB 14884 -> 552 (20702-20150) objects, 3(110) handoff,
40/30/4 yields
gc4(2): 2+0+0 ms, 1 -> 1 MB 29125 -> 992 (51867-50875) objects, 2(158) handoff,
24/14/3 yields
gc5(2): 3+0+0 ms, 2 -> 2 MB 46494 -> 1695 (101425-99730) objects, 3(96) handoff,
40/26/3 yields
gc6(2): 6+0+0 ms, 5 -> 4 MB 85872 -> 2991 (193158-190167) objects, 4(36) handoff,
20/12/3 yields
gc7(2): 12+1+0 ms, 9 -> 8 MB 152494 -> 5295 (355981-350686) objects, 4(36)
handoff, 20/17/3 yields
gc8(2): 22+2+0 ms, 16 -> 14 MB 268934 -> 9354 (643266-633912) objects, 5(174)
handoff, 30/15/8 yields
1000000
gc9(2): 38+4+0 ms, 29 -> 25 MB 475028 -> 16528 (1150608-1134080) objects, 1(2)
handoff, 20/16/2 yields
gc10(2): 69+7+0 ms, 51 -> 44 MB 838136 -> 29180 (2045636-2016456) objects, 4(36)
handoff, 20/15/8 yields
2000000
3000000
gc11(2): 122+13+0 ms, 89 -> 79 MB 1475839 -> 51459 (3621635-3570176) objects,
4(36) handoff, 20/16/6 yields
4000000
5000000
gc12(2): 215+23+0 ms, 158 -> 139 MB 2598793 -> 90688 (6396715-6306027) objects,
4(36) handoff, 20/18/15 yields
6000000
...
10000000
gc13(2): 388+42+0 ms, 278 -> 244 MB 4575104 -> 159744 (11282339-11122595) objects,
4(36) handoff, 20/15/98 yields
11000000
...
17000000
gc14(2): 683+76+0 ms, 489 -> 429 MB 8042735 -> 281136 (19870512-19589376) objects,
4(36) handoff, 20/12/180 yields
18000000
...
31000000
gc15(2): 1202+129+0 ms, 859 -> 755 MB 14140314 -> 494553 (34970414-34475861)
objects, 4(36) handoff, 20/16/387 yields
32000000
scvg0: inuse: 840, idle: 95, sys: 936, released: 0, consumed: 936 (MB)
33000000
...
55000000
gc16(2): 2072+238+0 ms, 1511 -> 1328 MB 24858859 -> 869739 (61513168-60643429)
objects, 4(36) handoff, 20/14/31 yields

Attachments:

  1. main.go (585 bytes)
@remyoudompheng
Copy link
Contributor Author

Comment 1:

The pattern SetFinalizer(f, close) then SetFinalizer(f, nil) is typical of os.File and
network connections.
I have long running servers that receive millions of connections per day and I wonder if
someone should be done.

@remyoudompheng
Copy link
Contributor Author

Comment 2:

When the program is run with 20 million iterations and the default MemProfileRate the
memory usage does not blow up but the profile is wrong.
One of the last GC traces is:
gc398(2): 0+0+0 ms, 0 -> 0 MB 48903 -> 267 (21000747-21000480) objects, 1(2) handoff,
20/20/2 yields
% go tool pprof main prof
Adjusting heap profiles for 1-in-524288 sampling rate
Welcome to pprof!  For help, type 'help'.
(pprof) top
Total: 154.0 MB
   154.0 100.0% 100.0%    154.0 100.0% main.alloc
     0.0   0.0% 100.0%    154.0 100.0% main.main
     0.0   0.0% 100.0%    154.0 100.0% runtime.main
     0.0   0.0% 100.0%    154.0 100.0% schedunlock
% go tool pprof --inuse_objects main prof
Adjusting heap profiles for 1-in-524288 sampling rate
Welcome to pprof!  For help, type 'help'.
(pprof) top 
Total: 20185088 objects
20185088 100.0% 100.0% 20185088 100.0% main.alloc
       0   0.0% 100.0% 20185088 100.0% main.main
       0   0.0% 100.0% 20185088 100.0% runtime.main
       0   0.0% 100.0% 20185088 100.0% schedunlock

@remyoudompheng
Copy link
Contributor Author

Comment 3:

This issue was closed by revision 3480878.

Status changed to Fixed.

gopherbot pushed a commit that referenced this issue May 11, 2015
@remyoudompheng
[release-branch.go1] runtime: do not unset the special bit after fina…
f12183f 
…lization.

««« backport 4a10c887bb3e
runtime: do not unset the special bit after finalization.

A block with finalizer might also be profiled. The special bit
is needed to unregister the block from the profile. It will be
unset only when the block is freed.

Fixes #3668.

R=golang-dev, rsc
CC=golang-dev, remy
https://golang.org/cl/6249066

»»»
@golang golang locked and limited conversation to collaborators Jun 24, 2016
This issue was closed.
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
No milestone
Development

No branches or pull requests
2 participants
@remyoudompheng @gopherbot