runtime: potential memory leak in Go1.11.2

[andig]

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

$ go version
go version go1.11.2 darwin/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
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/andig/Library/Caches/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/andig/go"
GOPROXY=""
GORACE=""
GOROOT="/usr/local/Cellar/go/1.11.2/libexec"
GOTMPDIR=""
GOTOOLDIR="/usr/local/Cellar/go/1.11.2/libexec/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/Users/andig/htdocs/ingress/go.mod"
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 -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/73/89ycv7qn51j4kbm04jsz9b840000gn/T/go-build037396939=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

I realize this is very unlikely but I wouldn't expect this simple loop to show increasing memory usage:

for {
	time.Sleep(time.Second)
	runtime.GC() // this is optional
	var memstats runtime.MemStats
	runtime.ReadMemStats(&memstats)
	fmt.Printf("%db\n", memstats.Alloc)
}

What did you expect to see?

Consant memory usage

What did you see instead?

Rising memory:

❯ go run cmd/test/main.go
68360b
...
68376b
...
68832b
...
69288b
...
69744b
...
71536b
...
73328b

Omitting the GC() call makes the memory rise quicker in smaller steps.

[networkimprov]

How many iterations have you tried?

[mark-rushakoff]

With this repro on go version devel +9a11b73635 Wed Dec 12 15:00:01 2018 +0000 darwin/amd64:

package main

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

func main() {
	for {
		time.Sleep(time.Second)
		// runtime.GC() // this is optional
		var memstats runtime.MemStats
		runtime.ReadMemStats(&memstats)
		// println(memstats.Alloc)
		fmt.Printf("%db\n", memstats.Alloc)
	}
}

And running go build then running the binary with GODEBUG=allocfreetrace=1, I see repeated output indicating that the allocations are happening in fmt.Printf (converting memstats.Alloc to an interface, and a defer while writing to stdout):

73688b
tracealloc(0xc00007e2d0, 0x10, runtime.uint64InterfacePtr)
goroutine 1 [running]:
runtime.mallocgc(0x10, 0x10a46a0, 0x104d400, 0xc00008e8e8)
	/Users/mr/gotip/src/github.com/golang/go/src/runtime/malloc.go:1011 +0x4ae fp=0xc00008e868 sp=0xc00008e7c8 pc=0x100a6de
runtime.convT64(0x11fe8, 0xc000086000)
	/Users/mr/gotip/src/github.com/golang/go/src/runtime/iface.go:345 +0x5b fp=0xc00008e898 sp=0xc00008e868 pc=0x10085bb
main.main()
	/tmp/m.go:16 +0x80 fp=0xc00008ff98 sp=0xc00008e898 pc=0x1093870
runtime.main()
	/Users/mr/gotip/src/github.com/golang/go/src/runtime/proc.go:200 +0x204 fp=0xc00008ffe0 sp=0xc00008ff98 pc=0x1029414
runtime.goexit()
	/Users/mr/gotip/src/github.com/golang/go/src/runtime/asm_amd64.s:1337 +0x1 fp=0xc00008ffe8 sp=0xc00008ffe0 pc=0x1050b91

tracealloc(0xc0000805c0, 0x40, runtime._defer)
goroutine 1 [running]:
runtime.systemstack_switch()
	/Users/mr/gotip/src/github.com/golang/go/src/runtime/asm_amd64.s:311 fp=0xc00008e6a8 sp=0xc00008e6a0 pc=0x104ec60
runtime.newdefer(0x80000000008, 0x7ffff80000000000)
	/Users/mr/gotip/src/github.com/golang/go/src/runtime/panic.go:240 +0x17a fp=0xc00008e718 sp=0xc00008e6a8 pc=0x1026d4a
runtime.deferproc(0xc000000008, 0x10cda70)
	/Users/mr/gotip/src/github.com/golang/go/src/runtime/panic.go:107 +0x3e fp=0xc00008e748 sp=0xc00008e718 pc=0x102681e
internal/poll.(*FD).Write(0xc000088000, 0xc00007e018, 0x7, 0x8, 0x0, 0x0, 0x0)
	/Users/mr/gotip/src/github.com/golang/go/src/internal/poll/fd_unix.go:258 +0x87 fp=0xc00008e7b0 sp=0xc00008e748 pc=0x1084c87
os.(*File).write(...)
	/Users/mr/gotip/src/github.com/golang/go/src/os/file_unix.go:266
os.(*File).Write(0xc000086000, 0xc00007e018, 0x7, 0x8, 0x1, 0x1, 0x10085bb)
	/Users/mr/gotip/src/github.com/golang/go/src/os/file.go:145 +0x74 fp=0xc00008e830 sp=0xc00008e7b0 pc=0x1085f24
fmt.Fprintf(0x10ddf20, 0xc000086000, 0x10c6b4c, 0x4, 0xc00008ff78, 0x1, 0x1, 0x7, 0x0, 0x0)
	/Users/mr/gotip/src/github.com/golang/go/src/fmt/print.go:200 +0xa5 fp=0xc00008e898 sp=0xc00008e830 pc=0x108bcb5
fmt.Printf(...)
	/Users/mr/gotip/src/github.com/golang/go/src/fmt/print.go:208
main.main()
	/tmp/m.go:16 +0xf7 fp=0xc00008ff98 sp=0xc00008e898 pc=0x10938e7
runtime.main()
	/Users/mr/gotip/src/github.com/golang/go/src/runtime/proc.go:200 +0x204 fp=0xc00008ffe0 sp=0xc00008ff98 pc=0x1029414
runtime.goexit()
	/Users/mr/gotip/src/github.com/golang/go/src/runtime/asm_amd64.s:1337 +0x1 fp=0xc00008ffe8 sp=0xc00008ffe0 pc=0x1050b91

But if I comment out the fmt.Printf and uncomment the println, the allocations immediately steady out and the same value of memstats.Alloc are printed, at least for the first minute or two.

I really doubt fmt.Printf is actually leaking memory. Is it just the runtime allowing space for defer and interface conversion to grow to a certain size before garbage collecting that area?

[Opposition]

Is it because var memstats runtime.MemStats is heap allocated when you use fmt.Printf?

Using fmt.Printf

$ go build -gcflags '-m' main.go
# command-line-arguments
./main.go:16:31: memstats.Alloc escapes to heap
./main.go:14:24: main &memstats does not escape
./main.go:16:13: main ... argument does not escape

Using println

$ go build -gcflags '-m' main.go
# command-line-arguments
./main.go:13:24: main &memstats does not escape

I think it is common for the escape analysis to allocate on the heap, if the function takes in an interface type.

[andig]

Thank you all for the detailed feedback! From what I've understood this is the expected behaviour (memory increase until GC kicks in). Closing for now, please let me know if I did misunderstand the feedback.