runtime: Running two go program with 1GB mem GC not releases free package variable mem

[wasmup]

What version of Go are you using (go version)?

$ go version
go version go1.15.5 linux/amd64

Does this issue reproduce with the latest release?

yes

What operating system and processor architecture are you using (go env)?

go env Output

$ go env
GO111MODULE="auto"
GOARCH="amd64"
GOBIN="/home/user1/go/bin"
GOCACHE="/home/user1/.cache/go-build"
GOENV="/home/user1/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/user1/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/user1/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR="/dev/shm"
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/dev/shm/go-build790679581=/tmp/go-build -gno-record-gcc-switches"

What did you do?

Run this code twice on a system with 8GB RAM:

package main

import (
	"fmt"
	"os"
	"runtime"
	"time"
)

func main() {
	for i := 0; i < 10; i++ {
		a = make([]byte, 1024*meg)
		var m runtime.MemStats
		runtime.ReadMemStats(&m)
		fmt.Printf("env: %v, sys: %4d MB, alloc: %4d MB, idel: %4d MB, released: %4d MB, inuse: %4d MB\n",
			os.Getenv("GODEBUG"), m.HeapSys/meg, m.HeapAlloc/meg, m.HeapIdle/meg, m.HeapReleased/meg, m.HeapInuse/meg)
		time.Sleep(1 * time.Second)
	}
}

var a []byte

const meg = 1024 * 1024

e.g.:

go build
./main
# on a second terminal again:
./main

What did you expect to see?

It should work without problem.

What did you see instead?

one program killed:

./hello 
env: , sys: 1087 MB, alloc: 1024 MB, idel:   63 MB, released:   63 MB, inuse: 1024 MB
env: , sys: 2111 MB, alloc: 2048 MB, idel:   63 MB, released:   63 MB, inuse: 2048 MB
env: , sys: 3135 MB, alloc: 3072 MB, idel:   63 MB, released:   63 MB, inuse: 3072 MB
env: , sys: 4159 MB, alloc: 4096 MB, idel:   63 MB, released:   63 MB, inuse: 4096 MB
env: , sys: 4159 MB, alloc: 3072 MB, idel: 1087 MB, released:   63 MB, inuse: 3072 MB
env: , sys: 4159 MB, alloc: 4096 MB, idel:   63 MB, released:   63 MB, inuse: 4096 MB
env: , sys: 4159 MB, alloc: 3072 MB, idel: 1087 MB, released:   63 MB, inuse: 3072 MB
Killed

second is ok:

./hello 
env: , sys: 1087 MB, alloc: 1024 MB, idel:   63 MB, released:   63 MB, inuse: 1024 MB
env: , sys: 2111 MB, alloc: 2048 MB, idel:   63 MB, released:   63 MB, inuse: 2048 MB
env: , sys: 3135 MB, alloc: 3072 MB, idel:   63 MB, released:   63 MB, inuse: 3072 MB
env: , sys: 4159 MB, alloc: 4096 MB, idel:   63 MB, released:   63 MB, inuse: 4096 MB
env: , sys: 4159 MB, alloc: 3072 MB, idel: 1087 MB, released:   63 MB, inuse: 3072 MB
env: , sys: 4159 MB, alloc: 4096 MB, idel:   63 MB, released:   63 MB, inuse: 4096 MB
env: , sys: 4159 MB, alloc: 3072 MB, idel: 1087 MB, released:   63 MB, inuse: 3072 MB
env: , sys: 4159 MB, alloc: 4096 MB, idel:   63 MB, released:   63 MB, inuse: 4096 MB
env: , sys: 4159 MB, alloc: 3072 MB, idel: 1087 MB, released:   63 MB, inuse: 3072 MB
env: , sys: 4159 MB, alloc: 4096 MB, idel:   63 MB, released:   63 MB, inuse: 4096 MB

Command:

vmstat 1 -S MB

Output:

procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 1  0   1066   6138     71    721    0    0   695   482  305  612  6  3 90  1  0
 1  0   1065   6104     71    721    0    0   160     0 1531 4596  7  2 91  0  0
 0  0   1065   6037     71    721    0    0   240     0 1557 4083  7  2 91  0  0
 0  0   1065   5970     71    721    0    0     4   192  937 2217  3  1 96  0  0
 0  0   1065   5905     71    721    0    0    24     0 1034 2301  4  1 95  0  0
 1  0   1065   4892     71    721    0    0     8     0  859 1899  3  3 94  0  0
 1  0   1065   3820     71    721    0    0    20     0 1049 2427  4  3 93  0  0
 0  0   1065   1768     71    721    0    0   680    56 2089 4458  5  7 88  0  0
 1  0   1065    709     71    721    0    0     4     8  874 1644  4  4 93  0  0
 1  6   1097    100      0    133    0   32 21856 35908 10957 8837  3 20 76  2  0
 2  9   1266    101      0    153    0  169 60980 173888 45459 48146  1 16 65 18  0
 0  6   1461    100      0    154    3  204 41340 209088 63567 58552  1 17 66 16  0
 1 19   1693     99      0    161    1  233 29264 239488 66461 67954  0 17 46 37  0
 1 16   1881    122      0    189    5  195 48992 200360 52910 61015  1 17  4 78  0
 4  1   2047    100      1    174   10  188 48572 192868 54604 61304  1 20 33 46  0
 2  1   1402   2837      0    180   25   19 141128 19628 16023 29175  4 21 69  6  0
 1  0   1382   2793      1    203   19    0 44548     0 6728 17851  6  3 87  4  0

Happens for this code too:

package main

import (
	"fmt"
	"time"
)

func main() {
	for i := 0; i < 10; i++ {
		a = make([]byte, 1024*meg)
		a[0] = 1
		fmt.Println(a[0], len(a))
		time.Sleep(1 * time.Second)
	}
}

var a []byte

const meg = 1024 * 1024

Run :

go build
./hello
./hello
vmstat 1 -S MB

one:

1 1073741824
1 1073741824
1 1073741824
1 1073741824
1 1073741824
1 1073741824
1 1073741824
1 1073741824
Killed

[toothrot]

I am no GC expert, so I am cc'ing runtime owners here: @aclements @randall77 @mknyszek @prattmic

I believe the releasing is based on what objects are determined to be reachable. In this case, you're using a package variable, so it's handled differently than if a were declared inside of main. Declaring it in main behaves as you would expect, rather than growing the heap to ~3-4GB.

If your program weren't actively allocating close to its max heap, the unused memory would be released when another memory-hogging program started. See also #29844 (comment)

Adding similar code to your program:

func main() {
// ...
	for {
		rssAfter := getRss()
		fmt.Printf("RSS before: %d, after: %d, delta: %d\n", rssBefore, rssAfter, rssBefore-rssAfter)
		time.Sleep(3 * time.Second)
	}
}

func getRss() int {
	output, err := exec.Command("ps", "-p", strconv.Itoa(os.Getpid()), "-o", "rss=").Output()
	if err != nil {
		panic(err)
	}

	rss, err := strconv.Atoi(strings.TrimSpace(string(output)))
	if err != nil {
		panic(err)
	}

	return rss
}

The memory remains unreleased, until the other memory hogging programs are started, during which it gets released:

RSS before: 4924, after: 3355644, delta: -3350720
RSS before: 4924, after: 3355644, delta: -3350720
RSS before: 4924, after: 1363620, delta: -1358696

See #42430 as an aggregate of GC pacing issues.