runtime: 1.3 garbage collector not releasing server memory back to system from finished goroutines

[gopherbot]

by matusis:

What does 'go version' print?
go version go1.3 linux/amd64

This program http://play.golang.org/p/vnKYk3sO5d creates 100000 goroutines, with each
goroutine allocating some memory and then finishing.
The program prints RES memory of the process as seen by "top" and also prints
runtime.ReadMemStats every 25 minutes.

1. Build the program from http://play.golang.org/p/vnKYk3sO5d on a server and run it
2. Wait at least for 50 minutes for two printouts


What happened?

After 50 minutes, the program produces output like this:
Creating 100000 goroutines
  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND            
19155 alecm     20   0  151m  84m  760 S    0  0.5   0:01.46 bugrep1.3          
Free #0; HeapAlloc: 10531984, HeapInuse: 10813440, HeapReleased: 0, HeapObjs: 36575
Done creating goroutines, freeing memory (every 25 mins)
  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND            
19155 alecm     20   0  151m  79m  836 S    2  0.5   0:01.69 bugrep1.3          
Free #1; HeapAlloc: 5492784, HeapInuse: 5791744, HeapReleased: 5742592, HeapObjs: 18014
  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND            
19155 alecm     20   0  151m  79m  860 S    0  0.5   0:01.88 bugrep1.3          
Free #2; HeapAlloc: 5494912, HeapInuse: 5791744, HeapReleased: 5742592, HeapObjs: 18061

The program released only 5MB or RES memory after 50 min. HeapReleased value matches RES
drop displayed by "top".

What should have happened instead?

Since goroutines exit and the slices created in them are not stored, most memory
(>80MB) should be returned to the OS. Only 5MB is returned however.

PS. We first saw this behavior in a simple TCP server accepting, reading from and
closing 10000 connections: please see
https://groups.google.com/forum/#!topic/golang-nuts/0WSOKnHGBZE

[davecheney]

Comment 1:

Can  you please run your application with the following environment variable set and
report back the results.
GODEBUG=gctrace=1 ./yourapp

Status changed to WaitingForReply.

[siritinga]

Comment 2:

Dmitry commented on golang-nuts that it is due goroutine stack, not released to the
system ever.
Here is a minimal example: http://play.golang.org/p/ircvbhPy3u  100k goroutines created
doing nothing and the dying. top shows 450 MB of RES used indefinitely.
~/tmp$ go version
go version devel +41a383d40558 Tue Jun 24 20:37:28 2014 -0700 linux/amd64
~/tmp$ GODEBUG=gctrace=1 ./tmp
gc1(1): 8+1+160+1 us, 0 -> 0 MB, 18 (19-1) objects, 0/0/0 sweeps, 0(0) handoff, 0(0)
steal, 0/0/0 yields
scvg0: inuse: 30, idle: 0, sys: 31, released: 0, consumed: 31 (MB)
gc2(1): 5+2+33063+0 us, 0 -> 29 MB, 103618 (103649-31) objects, 13/0/0 sweeps, 0(0)
handoff, 0(0) steal, 0/0/0 yields
scvg1: GC forced
scvg1: inuse: 30, idle: 0, sys: 31, released: 0, consumed: 31 (MB)
scvg2: inuse: 30, idle: 0, sys: 31, released: 0, consumed: 31 (MB)
gc3(1): 6+15+31651+0 us, 29 -> 29 MB, 103614 (103649-35) objects, 3649/3634/0 sweeps,
0(0) handoff, 0(0) steal, 0/0/0 yields
scvg3: GC forced
scvg3: inuse: 30, idle: 0, sys: 31, released: 0, consumed: 31 (MB)
scvg4: inuse: 30, idle: 0, sys: 31, released: 0, consumed: 31 (MB)
gc4(1): 8+3+25012+0 us, 29 -> 29 MB, 103612 (103649-37) objects, 3649/3632/0 sweeps,
0(0) handoff, 0(0) steal, 0/0/0 yields
scvg5: GC forced
scvg5: 0 MB released
scvg5: inuse: 30, idle: 0, sys: 31, released: 0, consumed: 30 (MB)
scvg6: 0 MB released
scvg6: inuse: 30, idle: 0, sys: 31, released: 0, consumed: 30 (MB)
gc5(1): 5+2+31097+0 us, 29 -> 29 MB, 103612 (103649-37) objects, 3649/3632/0 sweeps,
0(0) handoff, 0(0) steal, 0/0/0 yields
scvg7: GC forced
scvg7: inuse: 30, idle: 0, sys: 31, released: 0, consumed: 30 (MB)

[davecheney]

Comment 3:

Thank you for commenting, in addition to what Dmitry asked, it is clear that the
scavenger (scgN) is unable to find any completely free pages and thus you RSS does not
shrink.

[dvyukov]

Comment 4:

Labels changed: added release-go1.4, repo-main.

Owner changed to @dvyukov.

Status changed to Accepted.

[rsc]

Comment 6:

This looks like it is working now to me at tip. Marking as fixed. Please file a new bug
if you are still seeing this at tip.

Status changed to Fixed.

[dvyukov]

Comment 7:

How have you tested? It's still not fixed. The problem is with preserving 8K stack
segments for dead goroutines. We still do it.

Status changed to Accepted.

[gopherbot]

Comment 8:

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

[randall77]

Comment 9:

This issue was closed by revision 92eb1e1.

Status changed to Fixed.

[gopherbot]

Comment 10 by kirillrdy:

Hi,
revision 6c2dfbd8577f, makes a difference, but after running
http://play.golang.org/p/ircvbhPy3u ,I still get 252M RES ( FreeBSD and MacOS )
Should this be reopened ?

[ianlancetaylor]

Comment 11:

Please open a new issue instead.  Thanks.

[siritinga]

Comment 12:

I'm also seeing funny memory things. I've open this issue:
https://golang.org/issue/8832