runtime: scavenger freezes up in Go 1.14 in Windows due to coarse time granularity

[kingreatwill]

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

$ go version
go version go1.14.1 windows/amd64

Does this issue reproduce with the latest release?

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

go env Output

$ go env
set GO111MODULE=
set GOARCH=amd64
set GOBIN=
set GOCACHE=C:\Users\35084\AppData\Local\go-build
set GOENV=C:\Users\35084\AppData\Roaming\go\env
set GOEXE=.exe
set GOFLAGS=
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GOINSECURE=
set GONOPROXY=*.lingcb.net
set GONOSUMDB=*.lingcb.net
set GOOS=windows
set GOPATH=D:\go
set GOPRIVATE=*.lingcb.net
set GOPROXY=https://goproxy.cn,direct
set GOROOT=c:\go
set GOSUMDB=sum.golang.org
set GOTMPDIR=
set GOTOOLDIR=c:\go\pkg\tool\windows_amd64
set GCCGO=gccgo
set AR=ar
set CC=gcc
set CXX=g++
set CGO_ENABLED=1
set GOMOD=
set CGO_CFLAGS=-g -O2
set CGO_CPPFLAGS=
set CGO_CXXFLAGS=-g -O2
set CGO_FFLAGS=-g -O2
set CGO_LDFLAGS=-g -O2
set PKG_CONFIG=pkg-config
set GOGCCFLAGS=-m64 -mthreads -fmessage-length=0 -fdebug-prefix-map=C:\Users\35084\AppData\Local\Temp\go-build075262326=/tmp/go-build -gno-record-gcc-switches
GOROOT/bin/go version: go version go1.14.1 windows/amd64
GOROOT/bin/go tool compile -V: compile version go1.14.1
gdb --version: GNU gdb (GDB) 8.2.1

What did you do?

Used memory cannot be freed.

package main

import (
	"fmt"
	"runtime"
	"runtime/debug"
	"time"
)

func main() {

	var a []int
	for i := 0; i < 2000; i++ {
		a = make([]int, i*100000)
	}
	a = nil
	fmt.Printf("%v\n", a)

	go func() {
		for {
			m := runtime.MemStats{}
			d := debug.GCStats{}
			runtime.ReadMemStats(&m)
			debug.ReadGCStats(&d)
			fmt.Printf("%v\t%v\t%v\n", d.NumGC, m.HeapIdle/1024/1024, m.HeapInuse/1024/1024)
			time.Sleep(time.Second)
		}
	}()
	for {
		runtime.GC()
		time.Sleep(time.Second)
	}
}

[andybons]

Thanks for the issue.

This is expected on linux and RSS will drop if the system is under memory pressure. But this is Windows. Is the same behavior expected @aclements @mknyszek ?

[mknyszek]

On Windows it should be eager.

Firstly I'll note that what the reproducer is printing doesn't subtract out HeapReleased from HeapIdle, so it's not going to give an accurate picture of what the runtime thinks it returned to the OS.

The fact that Windows' Task Manager is reporting that high of an RSS is concerning, considering that Windows reports physical memory used. I ran this on a Windows VM and HeapReleased didn't increase on Windows like it does on Linux.

Puzzled, I started printing some diagnostics, and noticed that scavenge pacing math was producing a bunch of NaN values... the problem is that the pacing is based on a measurement of how long it takes the scavenge, and on Windows the time granularity is really coarse (like 15ms or something). So the time measured for the scavenge pacing was exactly 0, because it happened within that time granule. The scavenge pacing sees some NaN values, and basically sleeps forever.

So, this is a real bug. I'm not sure what the fix is, and it may be worth back-porting to 1.14? There is a workaround, which is to call debug.FreeOSMemory occasionally.

[mknyszek]

As @aclements informed me it looks like the theoretical granularity should be 100ns, which would be enough, but the time is only updated on every OS tick.

Experimentally, I found in my Windows VM that the best granularity I could get (spin until nanotime()-start != 0 in the scavenger) was around 0.95ms, which is definitely not good enough.

I think we need a fallback here to the Go 1.13 pacing which didn't rely on measuring time.

CC @aclements

[mknyszek]

@aclements also just informed me that Go sets Windows' interrupt frequency to 1ms, so there we go.