Memory leak or GC feature ?

[Christophe Meessen]

I wanted to check my program for go routine and memory leaks. In doing so I detected what resemble a memory leak while my program was doing nothing.

Here is a minimal program that reproduces the problem. The program collects and prints the total number of bytes allocated and the number of blocks.

package main

import (

"runtime"

func main() {

var m runtime.MemStats

ticker := time.NewTicker(20 * time.Second)

for {

runtime.ReadMemStats(&m)

println("status: memUsed:", m.Alloc, "allocs:", m.Mallocs-m.Frees, "numGC", m.NumGC)

<-ticker.C

runtime.GC()

}

}

What I see is a slow but steady increase of memUse and allocs. The memUse grows by 4 to 96 bytes every 40 to 60 seconds.

Is this a feature of the GC or is this a memory leak in one of the called functions ?

Note that I use println because the "leak" is much more important when I use fmt.Println of log.Println. I also use ticker because I was told it would be better than time.Sleep, but I don’t see any significant difference in the "leak" when I use one or the other.

[Volker Dobler]

This is normal behaviour and not a leak.

Nothing is leaking in your code (and it is generally

hard to leak RAM). The allocations will be reclaimed.

V.

[Christophe Meessen]

The documentation of the GC() function states:

"GC runs a garbage collection and blocks the caller until the garbage collection is complete. It may also block the entire program."

Based on the documentation, I assumed that a garbage collection would be really complete by calling GC. By complete I mean that no garbage is left over.

Apparently It’s not the case. Is it possible learn a bit more on this ? Why would the GC not garbage collect everything when GC() is called ?

It would have been convenient for detecting memory leaks to be able to compare memory Alloc before and after the checked task and a really complete GC.

[Robert Engels]

Because GC costs are amortized in order to limit the effect on the performance (pauses) of the program - you should almost never manually invoke a GC.

That being said, there are "memory profilers" that can detect live/dead objects in order to detect memory leaks - use them during development (and most can be used in production with some caveats).

--
You received this message because you are subscribed to the Google Groups "golang-nuts" group.
To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/golang-nuts/b8103128-8ae8-42fb-8b3f-4d5265632246%40googlegroups.com.

[Christophe Meessen]

While letting the program run for a few hours I see that after some time the memory usage vary in saw teeth. Some of the garbage is reclaimed after 800 calls to GC().

However, it never gets back to the low level it had initially. Initial lowest Alloc is 146520. It then grows steadily up to 163040. Then suddenly drops to 156896, and grows slowly again to 163520. Then drops suddenly to 157376. Etc.

So memory is indeed a little bit partially reclaimed from time to time. So the GC kind of works, but the GC() function doesn’t behave as I was expectiong.

[Jan Mercl]

On Fri, Mar 6, 2020 at 4:55 PM Christophe Meessen <christoph...@gmail.com> wrote:

> It would have been convenient for detecting memory leaks to be able to compare memory Alloc before and after the checked task and a really complete GC.

That's not feasible. There are _always_ other runtime-started goroutines running during execution of a program and they may allocate memory in no predictable pattern.

Here's a sample run with Go 1.14 on Linux/amd64 (with added time stamps).

jnml@e5-1650:~/tmp/gc> date ; ./gc
Fri Mar  6 17:10:55 CET 2020
2020-03-06 17:11:15.47671116 +0100 CET m=+20.000226110 status: memUsed: 140296 allocs: 155 numGC 0
2020-03-06 17:11:35.476718873 +0100 CET m=+40.000234661 status: memUsed: 155376 allocs: 191 numGC 1
2020-03-06 17:11:55.476670923 +0100 CET m=+60.000185942 status: memUsed: 157248 allocs: 197 numGC 2
2020-03-06 17:12:15.476638267 +0100 CET m=+80.000153357 status: memUsed: 157264 allocs: 199 numGC 3
2020-03-06 17:12:35.476746762 +0100 CET m=+100.000262341 status: memUsed: 157264 allocs: 199 numGC 4
2020-03-06 17:12:55.476724863 +0100 CET m=+120.000240581 status: memUsed: 157280 allocs: 201 numGC 5
2020-03-06 17:13:15.476737116 +0100 CET m=+140.000252973 status: memUsed: 157280 allocs: 201 numGC 6
2020-03-06 17:13:35.476650054 +0100 CET m=+160.000165143 status: memUsed: 157376 allocs: 202 numGC 7
2020-03-06 17:13:55.476609855 +0100 CET m=+180.000124805 status: memUsed: 157376 allocs: 202 numGC 8
2020-03-06 17:14:15.476707245 +0100 CET m=+200.000222544 status: memUsed: 157472 allocs: 203 numGC 9
2020-03-06 17:14:35.47665699 +0100 CET m=+220.000172009 status: memUsed: 157568 allocs: 204 numGC 10
2020-03-06 17:14:55.476618049 +0100 CET m=+240.000133068 status: memUsed: 157776 allocs: 207 numGC 11
2020-03-06 17:15:15.476615426 +0100 CET m=+260.000130515 status: memUsed: 157768 allocs: 206 numGC 12
2020-03-06 17:15:35.476601977 +0100 CET m=+280.000116926 status: memUsed: 157768 allocs: 206 numGC 13
2020-03-06 17:15:55.476594814 +0100 CET m=+300.000109833 status: memUsed: 159528 allocs: 210 numGC 14
2020-03-06 17:16:15.476613143 +0100 CET m=+320.000128162 status: memUsed: 159528 allocs: 210 numGC 15
2020-03-06 17:16:35.476656056 +0100 CET m=+340.000171146 status: memUsed: 159528 allocs: 210 numGC 16
2020-03-06 17:16:55.476664258 +0100 CET m=+360.000179278 status: memUsed: 159528 allocs: 210 numGC 17
2020-03-06 17:17:15.476620428 +0100 CET m=+380.000135448 status: memUsed: 159528 allocs: 210 numGC 18
^C
jnml@e5-1650:~/tmp/gc>

As can be seen above, eventually the allocated memory goes down and stabilizes, as predicted by Volker.

[Jesper Louis Andersen]

On Fri, Mar 6, 2020 at 5:21 PM Christophe Meessen <christoph...@gmail.com> wrote:

 

However, it never gets back to the low level it had initially. Initial lowest Alloc is 146520. It then grows steadily up to 163040. Then suddenly drops to 156896, and grows slowly again to 163520. Then drops suddenly to 157376. Etc.

So memory is indeed a little bit partially reclaimed from time to time. So the GC kind of works, but the GC() function doesn’t behave as I was expectiong.

 

Small fluctuations like these are somewhat expected. In a multi-core environment, you often want to cache processor-locally. Many malloc implementations would show the same behavior nowadays.

However, what is more likely here is that you are looking at different snapshots when the sweep phase is being run. Once we have marked all live data in the GC, we initiate the sweep phase to reclaim the unmarked data. But this happens incrementally while our program is running. Thus we can probably expect the numbers to fluctuate a small bit. Note that while your program only allows one OS thread, the GC will happily use all your available cores for speeding up the the GC phase. So you are also looking at non-determinism in a concurrent environment.

You need to rely on different methods if you want to detect for memory leaks in programs. The package "runtime/pprof" contains ways to get a memory profile of the program, including allocations at call sites and so on. I would probably use these tools to hunt for eventual memory leaks in programs.