Memory not being reclaimed by OS

[Pungyeon]

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

We have reproduced this behaviour with 1.13, 1.14 & 1.15

$ go version
go version go1.15.2 linux/amd64

Does this issue reproduce with the latest release?

Yes.

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

We have tried several different UNIX distributions, mainly ubuntu and alpine. However, they all behave alike.

go env Output

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/root/.cache/go-build"
GOENV="/root/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
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=/tmp/go-build014469751=/tmp/go-build -gno-record-gcc-switches"

What did you do?

We have written an application for transforming VoIP traffic from the network, using the gopacket library. The application parses VoIP streams and decodes the associated RTP traffic. All data associated with ongoing calls is stored in memory and all completed calls are stored on disk. However, when sending traffic through our application, we have noticed that memory is never reclaimed by the OS. We initially thought that this was a memory leak but after extensive investigation concluded that it is not.

We stumbled upon the following article, which described similar behaviour: https://blog.detectify.com/2019/09/05/how-we-tracked-down-a-memory-leak-in-one-of-our-go-microservices/

We tried implementing a similar fix, and it actually seemed to work. Using the environment variable GODEBUG=madvdontneed=1 together with running debug.FreeOSMemory enabled the OS to reclaim the memory and avoiding an eventual OOM error.

I unfortunately cannot share the code at this current time, since it is still proprietary software 😢 But I may be able to share a video demonstration of this exact issue, if this would help in any way.

What did you expect to see?

Once a call session is over, all data is cleared from memory. We expected to see the OS reclaiming this memory.

What did you see instead?

The OS never reclaims this memory and we see a steady increase in memory usage of our application (without the fix described above).

[davecheney]

The OS never reclaims this memory and we see a steady increase in memory usage of our application (without the fix described above).

Can you run your application with GODEBUG=gctrace=1 up to the point it is killed by the operating system and paste the complete output in this issue. Thank you.

[Pungyeon]

Thank you so much @davecheney for the extremely quick response. I will return with this information as soon as possible 🙏

[Pungyeon]

Here is a link with two different traces, I hope the names are sufficiently descriptive :) https://lmjcorti-my.sharepoint.com/:f:/g/personal/infrastructure_corti_ai/EtXO0HhmtIdBhrusGcjdkhQB4INvplcJyR50eR9NGP9iyg?e=KNPC68

I have run this in the official golang:1.15 docker container, with 2GB of memory allocated. Since the leak is rather minor I didn't wait until a OOM, but I hope that the logs are still useful. If not, let me know and I will rerun the tests again and produce new output.

Thank you again.

[davecheney]

Thank you for this data, can I ask you to use go build, not go run as the trace for go run is conflated with the trace for you application.

[davecheney]

Having said that, it looks like your application's heap is around 25 based on this line

gc 11 @600.379s 0%: 0.062+13+0.025 ms clock, 0.12+0/6.4/14+0.051 ms cpu, 13->13->12 MB, 25 MB goal, 2

Does this match with your measurements?

[aclements]

@Pungyeon , it's not clear from your original post how you're observing that memory is not being reclaimed by the OS. Are you observing this from memory statistics reported by the OS, and if so, which ones (RSS or something else)? Or are you observing OOMs?

What happens if you set GODEBUG=madvdontneed=1 without using debug.FreeOSMemory?

What does runtime.ReadMemStats report when your application is having memory trouble? In particular, what are HeapSys, HeapInUse, and HeapReleased?

Go defaults to using MADV_FREE, which marks memory that can be reclaimed by the OS, but that memory doesn't get reclaimed until the OS is actually under pressure. Hence, it can look like your application has a large RSS, but that can shrink rapidly if the OS needs that memory. I ask about OOMs because the OS should definitely reclaim the memory before OOMing your process, so if your process is OOMing, that suggests a different issue.

[gopherbot]

Change https://golang.org/cl/267100 mentions this issue: runtime: default to MADV_DONTNEED on Linux

[Pungyeon]

Hi everyone 👋 Really really sorry for the radio silence 😳 I am honestly quite embarassed about this.

Thank you for this data, can I ask you to use go build, not go run as the trace for go run is conflated with the trace for you application.

@davecheney I will see try to do this tomorrow and get back to you as soon as possible.

it's not clear from your original post how you're observing that memory is not being reclaimed by the OS. Are you observing this from memory statistics reported by the OS, and if so, which ones (RSS or something else)? Or are you observing OOMs?

@aclements we were experiencing OOMs on some of our customer deployments, possibly due to this issue. However, we were able to mitigate this, by using the combination of GODEBUG=madvdontneed=1 and debug.FreeOSMemory (running this in intervals). This isn't really ideal, hence why I opened this issue.

This is an internal video, which resulted in our final solution. Perhaps it's a misunderstanding of the memory management in Go... If so, please let me know what else to do 🙏 https://drive.google.com/file/d/1si2BltEeESERp3W7bXSL7tSKRzoB5k_8/view?usp=sharing

[aclements]

@aclements we were experiencing OOMs on some of our customer deployments, possibly due to this issue. However, we were able to mitigate this, by using the combination of GODEBUG=madvdontneed=1 and debug.FreeOSMemory (running this in intervals). This isn't really ideal, hence why I opened this issue.

GODEBUG=madvdontneed=1 shouldn't have any effect on OOMs. The fact that debug.FreeOSMemory helped suggests to me your application was actually running pretty close to memory limits and this just helped nudge it into a safe amount. Since the Go garbage collector is designed to retain about twice as much memory as your live heap size, debug.FreeOSMemory is expected to free about half of your memory, but the moment you start allocating again after freeing memory, it will grow back into that 2x envelope. This isn't necessarily a bad thing to do if you know your process is going to be idle for a long time, or if you know it just released a lot of memory, but it's not meant to fix OOMs.

This is an internal video, which resulted in our final solution. Perhaps it's a misunderstanding of the memory management in Go... If so, please let me know what else to do pray https://drive.google.com/file/d/1si2BltEeESERp3W7bXSL7tSKRzoB5k_8/view?usp=sharing

Without knowing what Docker is reporting as "memory usage" in that monitoring tool, it's hard to say exactly what's going on here (I hate it when things are just labeled "memory usage"; there are so many different things that can mean). But the 2x drop from FreeOSMemory isn't a surprise, as I explained above. The fact that it rises with madvdontneed=0 but levels out with madvdontneed=1 suggests that this is indeed just a monitoring problem, and that "memory usage" includes memory that can be reclaimed at any time by the OS if there's pressure.

[Pungyeon]

Without knowing what Docker is reporting as "memory usage" in that monitoring tool, it's hard to say exactly what's going on here (I hate it when things are just labeled "memory usage"; there are so many different things that can mean)

@aclements I absolutely agree with, the levels of ambiguity in a lot of the tools we have used for attempting to debug this has not been helpful 😅 Either way, if this is expected behaviour. Then let us close this issue. I will do some further testing and report back once I have something to report on.

Thank you so much for your assistance 🙏

[aclements]

Glad we were able to help! FYI, we're currently planning to default to madvdontneed=1 in Go 1.16 because of these sorts of confusing monitoring issues (#42330).