Go: runtime: memory leaked observed in go program

[santhoshkarthi]

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

go1.14.3

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

set GO111MODULE=

set GOARCH=arm

set GOBIN=

set GOCACHE=C:\Users\irhpoq\AppData\Local\go-build

set GOENV=C:\Users\irhpoq\AppData\Roaming\go\env

set GOEXE=

set GOFLAGS=

set GOHOSTARCH=amd64

set GOHOSTOS=windows

set GOINSECURE=

set GONOPROXY=

set GONOSUMDB=

set GOOS=linux

set GOPATH=D:\Karthik\Skills\Golang\GolangTraining-master

set GOPRIVATE=

set GOPROXY=https://proxy.golang.org,direct

set GOROOT=c:\go

set GOSUMDB=sum.golang.org

set GOTMPDIR=

set GOTOOLDIR=c:\go\pkg\tool\windows_amd64

set GCCGO=gccgo

set GOARM=7

set AR=ar

set CC=gcc

set CXX=g++

set CGO_ENABLED=0

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=-fPIC -marm -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=C:\Users\irhpoq\AppData\Local\Temp\go-build018000050=/tmp/go-build -gno-record-gcc-switches

What did you do?

What did you expect to see?

RSS memory should not keep increasing

What did you see instead?

RSS memory was keep increasing. It increased from 4472 KB to 4648 KB in 15 mins

temp_sensor.txt

[santhoshkarthi]

[santhoshkarthi]

after 20 mins

[santhoshkarthi]

Both TCP server and temp_sensor RSS(RAM) memory is keep growing

[randall77]

From what I can see in that program, you're making new goroutines without ever exiting them.

go autoTempUpdate(Msg1)

That goroutine never exits. And you're making one of them for every request handled.

Is this the same bug as #40404 ?

[santhoshkarthi]

yeah that is what the intention also, we dont want to exit the go routine, each goroutine should update the temp for every 10 secs indefinitely or until we close the program. Yeah I am the one who logged that bug also, Actually this is my main program, I see the more memory leak here so I just created simple tcp client program where it would send the message to TCP server every 10 sec continuously, there also i could see memory leak. so I logged that bug. Here when there is 2 or more gorouine created more memory leak was observed

[santhoshkarthi]

Actually I am preferring go lang as other scripting language like python, ruby is taking more RAM memory as compared to golang, but here i could see memory leak, Please help me to resolve this issue

[randall77]

You keep making new goroutines that never exit. Each one uses some memory. That's your leak.
You need to exit the goroutines at some point.

[santhoshkarthi]

Even I have C program where multiple threads running which will never exit, and I dont see any memory leaking. So in GO we cant create any thread which should always running and In all real time application, we wanted to have thread which should run indefinitely right, I understand each go routine would use additional 4KB of memory when we create new go routine, After I created 6 go routine it can take around 24KB extra, but why it keeps growing. moreover In each go routine I am just sending message to TCP server nothing else i am doing, but I dont understand why memory is keep growing.

[randall77]

I understand each go routine would use additional 4KB of memory when we create new go routine, After I created 6 go routine it can take around 24KB extra, but why it keeps growing.

Because you're not creating just 6 goroutines. You're making a new one with each call to webRequestHandler.

[santhoshkarthi]

yeah I have just made 5 http request and observed that whether 5 goroutine was created or not, I saw 5 goroutine was created and I have not made any web request after that. whatever memory leak that I shared is with 5 goroutine only

[santhoshkarthi]

I am attaching my go program output which is running with 5 goroutine(5 temp sensor)

Message Received: "temperature Sensor1: 32870", size:30
Message Received: "temperature Sensor2: 32790", size:30
Message Received: "temperature Sensor3: 32830", size:30
Message Received: "temperature Sensor4: 32790", size:30
Message Received: "temperature Sensor5: 32800", size:30
Message Received: "temperature Sensor1: 32880", size:30
Message Received: "temperature Sensor2: 32800", size:30
Message Received: "temperature Sensor3: 32840", size:30
Message Received: "temperature Sensor4: 32800", size:30
Message Received: "temperature Sensor5: 32810", size:30
Message Received: "temperature Sensor1: 32890", size:30
Message Received: "temperature Sensor2: 32810", size:30
Message Received: "temperature Sensor3: 32850", size:30
Message Received: "temperature Sensor4: 32810", size:30
Message Received: "temperature Sensor5: 32820", size:30
Message Received: "temperature Sensor1: 32900", size:30
Message Received: "temperature Sensor2: 32820", size:30
Message Received: "temperature Sensor3: 32860", size:30
Message Received: "temperature Sensor4: 32820", size:30
Message Received: "temperature Sensor5: 32830", size:30
Message Received: "temperature Sensor1: 32910", size:30
Message Received: "temperature Sensor2: 32830", size:30
Message Received: "temperature Sensor3: 32870", size:30
Message Received: "temperature Sensor4: 32830", size:30
Message Received: "temperature Sensor5: 32840", size:30
Message Received: "temperature Sensor1: 32920", size:30
Message Received: "temperature Sensor2: 32840", size:30
Message Received: "temperature Sensor3: 32880", size:30
Message Received: "temperature Sensor4: 32840", size:30
Message Received: "temperature Sensor5: 32850", size:30

[santhoshkarthi]

Now it is increased to 1MB in 1 hour from 4488KB to 5368KB

[santhoshkarthi]

This all observation with 5 goroutine only

[randall77]

Ok, then we're going to need more instructions about how exactly you exercised your binaries, so we can recreate the problem.
You've included the temp_sensor binary here. I got the server code from the other issue. Which version are you using? Are those the codes in question? How did you run them? How did you send them requests?

[davecheney]

Is this as duplicate of https://github.com/golang/go/issues/40404?

[santhoshkarthi]

@randall77 Sure I will share you whatever help that you need from my side. I am attaching the tcp_server code that i used,
tcp_server.txt
I am using "go1.14.3", Is there any other version of GOLang which does not have this problem

[santhoshkarthi]

Steps to run the program:

1. Run "tcp_server.go" first,
2. Then run "temp_sensor.go" program,
3. Thirdly, we need to send http post request with Json message to the machine where "temp_sensor.go" is running,
4. You can use "Linux CURL" command to send the http POST request.

Command

curl -X POST -d "{\"Sensor\" : \"Sensor1\"}" http://192.168.1.10:8080

curl -X POST -d "{\"Sensor\" : \"Sensor2\"}" http://192.168.1.10:8080

curl -X POST -d "{\"Sensor\" : \"Sensor3\"}" http://192.168.1.10:8080

curl -X POST -d "{\"Sensor\" : \"Sensor4\"}" http://192.168.1.10:8080

curl -X POST -d "{\"Sensor\" : \"Sensor5\"}" http://192.168.1.10:8080

192.168.1.10 is the IP of the system where temp_sensor.go and tcp_server.go is running
This would create 5 threads in temp_sensor.go program, each would be parallelly sending temp value to tcp_server.go program.

[davecheney]

@santhoshkarthi once your program has leaked will you please send SIGQUIT to it; you can do this with the command

kill -QUIT $PID

where $PID is the process id of your server program. This will dump a large amount of information, please include _all_ of it.

[santhoshkarthi]

Below is the Embedded Linux board RAM memory,It was taken when we started the "temp_sensor.go" and "tcp_server.go" binary,

Below image was taken after 1 hour,

If you see RAM memory of temp sensor was increased almost 1MB in 1 hr, and still it keep growing and it is not cleared the memory

[davecheney]

@santhoshkarthi to reiterate what @randall77 has said earlier. Your program has a number of places where goroutines can leak, this will cost at least 2kb per goroutine leaked. The procedure I outlined above will confirm our hypothesis.

[santhoshkarthi]

@davecheney When we kill -QUIT $PID, it will kill the process right, will it generate any file, I just tried it for another process, before doing it to "temp_sensor" but It didnot throw any information in the console

[santhoshkarthi]

Just wanted to confirm before trying it out in temp_sensor.go program

[davecheney]

It is also important to remember that the design of the go garbage collector is not to release every byte of memory back to the operating system, this is by design and also a constraint -- linux simply does not have a way to _tell_ the operating system to take a page of memory back, we can only _ask_ it too take the memory back, and depending on the memory pressure of the system, the operating system often ignores that request.

I am telling you this because it is expected that Go processes can grow after they start, what we are investigating is they should not grow continually.

[davecheney]

@davecheney When we kill -QUIT $PID, it will kill the process right, will it generate any file, I just tried it for another process, before doing it to "temp_sensor" but It didnot throw any information in the console

This is a facility of the Go runtime, non Go programs may not respond to this signal.

[santhoshkarthi]

@davecheney Yeah even I understand that, when goroutine is created it will take some memory say 4KB for each goroutine is what I read, I have created 5 goroutine, so it can take around 20KB extra, even 100KB is fine, but what i am not able to understand is, why It keeps growing? it did not stable, even after no of goroutine created was stopped

[davecheney]

The thesis is your application is leaking goroutines, how many cannot be said without the information I asked for.

[santhoshkarthi]

@davecheney I tried executing kill command for temp_sensor.go, but it didnot throw any message in the console,
kill -QUIT 30650(temp_sensor PID)

[santhoshkarthi]

Do I need to export anything before running the go program

[davecheney]

you do not need to export anything

[santhoshkarthi]

@davecheney Is this what you are asking

[santhoshkarthi]

temp_sensor_debug_output.txt
@davecheney I put the details in txt file

[davecheney]

yes, that is correct. This process shows three autoTempUpdate goroutines running. Can you please repeat this process once you feel the process has leaked sufficiently.

[santhoshkarthi]

yeah correct. now I have created 3 threads, just to share the debug output. Sure I will repeat the process and share the output
Thanks @davecheney

[santhoshkarthi]

@davecheney @randall77
As you said I rerun my temp_sensor program, RSS memory was grew up to 5228KB from 4000KB, in 2hrs. and it keeps growing, never come down, only 5 goroutine were created.
Attaching debug outputs
temp_sensor_debug_output_with_5threads.txt

[santhoshkarthi]

[santhoshkarthi]

Did you get chance to run this code/program from your end, Just wanted to understand whether you saw the memory issue or not

[davecheney]

Ok, the next thing is to get the GODEBUG output working. Run this command exactly

env GODEBUG=gctrace=1 ./temp_sensor

[santhoshkarthi]

Sure, Do I need to execute KILL command (Kill -QUIT $PID) after sometime. How would i get the debug output

[santhoshkarthi]

THis is the memory details when I am starting the temp_sensor and tcp_server

[santhoshkarthi]

root@ccimx6ulsbc:/home/root# env GODEBUG=gctrace=1 ./temp_sensor
Entered into main
Entered into webHandler Thread...
Entered into main Thread...

I executed as you said, Please correct me if i am wrong

[santhoshkarthi]

@davecheney So far there is no debug output printed in the console, It was just printing the message that I mentioned in the code

[santhoshkarthi]

@davecheney there was no debug message printed after I ran "env GODEBUG=gctrace=1 ./temp_sensor" this. Please let me know if i missed anything

[santhoshkarthi]

@randall77 , I have shared all the codes and steps to run the program,
https://github.com/golang/go/issues/40448#issuecomment-665537758
Please let me know whether you are able to observe the memory leak issue

[davecheney]

@davecheney there was no debug message printed after I ran "env GODEBUG=gctrace=1 ./temp_sensor" this. Please let me know if i missed anything

That is the correct command, I cannot explain why it has not output any information. In my tests even a tiny GO program wil execute one of two gc cycles as part of startup.

[randall77]

Ok, I can reproduce, sort of.

The RSS is indeed slowly growing. But the Go heap is really small. In Go's default configuration we don't run our first GC until the heap is close to 4MB. On OSX, the RSS (which is the Go heap, plus lots of other stuff) starts at ~1.9MB and grows very slowly (~100B/sec). So it will take many hours to reach the point at which we do our first GC.

So you're just seeing the GC being very relaxed about collecting small heaps. It's just very slowly paging in the minimum heap as needed, 4KB every minute or so. If you let it run long enough, it should collect that memory, return it to the OS, and repeat. If you're more patient than me, you could let it run for a day or two and see.

We used to run a GC every few minutes. I don't think we do that any more. @mknyszek , do you know?

[mknyszek]

@randall77 We do still force a GC every 2 minutes, unless the GC is turned off (GOGC=0 or SetGCPercent(-1)). Based on this thread, it doesn't look like the program is being invoked with GOGC as an environment variable, so is it possible SetGCPercent is getting called? That would explain why there's no gctrace output, since it's printed at the end of a GC.

@santhoshkarthi Do you call SetGCPercent(-1) at any point in your program? If not, do any of your dependencies call it?

[randall77]

I can't seem to get the GC to trigger for this case. There's no GOGC or SetGCPercent.
The code spends most of its time sleeping. Would that matter?
Here's a simple test case that behaves similarly to OP's code:

package main

import (
    "fmt"
    "time"
)

func main() {
    for n := 0; true; n++ {
        time.Sleep(time.Second)
        fmt.Printf("%d\n", n)
        sink = make([]byte, 1024)
    }
}

var sink []byte

It's allocating 1K/sec, and well after 2 minutes there's still no GC.

> go build tmp1.go
> GODEBUG=gctrace=1 ./tmp1
0
1
2
...
262
263

No gctrace output.
If I allocate 1MB instead of 1KB, I get a gc trace output every ~3-4 seconds, as expected.

[mknyszek]

I took another look at the logic, looks like we won't trigger a GC every two minutes if there hasn't been one yet... (return lastgc != 0 && t.now-lastgc > forcegcperiod). Given that, adding a runtime.GC() call at the beginning of main is one possible workaround to making sure it's on. This is a bug that should probably be fixed?

@santhoshkarthi Keith pointed out that the really slow rate of allocation means a GC might not be triggered for hours. The runtime has a minimum heap size of 4 MiB (note that RSS will be larger than that because this is just the allocated heap, not space for metadata, stacks, etc.). Even an RSS of 5228 KiB might not reflect a 4 MiB heap.

[randall77]

@mknyszek: Thanks. That workaround (adding runtime.GC() to the start of main) works for the OP's example.

The behavior is not perfect; it uses a few hundred KB to actually run a GC, and even after the first "real" GC the RSS increases somewhat. But it does look to plateau after the first few GCs.

Yes, not doing periodic GCs unless one has run already looks like something we should fix. As there is an easy workaround, maybe this is just a 1.16 thing.

[santhoshkarthi]

@davecheney https://github.com/golang/go/issues/40448#issuecomment-665952463,
I have tried with other go programs, I didnot see any other messages printed other than the messages in the code,

Is there anything I need to add it in the code

[davecheney]

I think, based on the responses above that output will be eventually printed by you will have to wait for at least 4mb of memory to be allocated on the heap.

Based on the responses above I don’t think this is a useful line of investigation. It is likely that, when observed from outside, your programs rss will grow by at least 4mb before stabilising.

[santhoshkarthi]

@randall77 @mknyszek @davecheney Actually we are doing development in C and ruby, Since ruby is using more RAM we are trying to explore is there anyother language which would use less RAM at the same time it should have more libraries so that it would be easy for the development, So we tried exploring golang as it has lot of library support, and using less RAM memory compared to other scripting language like python and ruby, Our application development in Embedded board where RAM is limited to 256 MB RAM.

But if you see other Program like C it would use less RAM and it would not grow, where as if we take ruby and python taking more RAM memory but when come to memory leak, ruby and python also very stable, RAM is not increasing even after we ran the code code 1 or 2 days, where as Golang is using less RAM memory compared to other scripting language like ruby, Python, But the thing that is more concern is, RAM memory is keep increasing, Yeah you are saying that it would clear the RAM memory only heap reaches to 4MB, but in the embedded this 4MB is huge as we have 10 to 12 such application is running and RAM memory is limited to 256MB,
and one more thing that I still understand is, why heap memory is keep growing, when we dont create any dynamic memory during every iteration. we are just creating one thread and sending message to tcp server. and this is not happening in other language like C, ruby, Python.
Yesterday I just created only one thread, instead of 5 threads, and sending message to tcp_server every 10 secs, that itself has memory leak.
When I start, Go program, it has 4336KB RAM and 524 as Dirty memory,

After I kept the board idle for one day, RAM memory went to 5692 KB, and 1816 as a Dirty memory.

[santhoshkarthi]

Please suggest me is there other lower go version does not have this memory leak, Initially when we implement the code that we was written in ruby, in golang, we were happy that it was using 1/5th of the RAM as compared to ruby code, but when we see this memory leak, we are little bit worry to move to Golang, and that too keep increasing the RAM memory with only one thread is more concern for us, As I told earlier, our embedded board RAM memory is limited to 256 MB

[santhoshkarthi]

@davecheney @randall77 @mknyszek Please help me on what I have to do to stop this memory leak in golang

[davecheney]

@santhoshkarthi as far as we know there is no memory leak. What you are seeing is the interaction of the operating system lazily allocating pages to the process as it touches them. We believe that once the program heap reaches the 4mb range the process size will stabilise; perhaps around the 7.8 to 9mb mark as measured by top.

I believe that you can verify this by reducing any delays or time.Sleeps in your program so that operations are performed more frequently. If I am correct then the observed RSS will grow faster and after it passes ~4mb over the base process size, somewhere between 7 and 9mb RSS as reported by top, you should see an output from the GODEBUG=gctrace=1 debugging information indicating a GC cycle has occured. At that time the majority of the heap should be freed -- look for the output for something like this 4->4->0 which suggests the heap usage drops from 4mb to less than 1mb.

It is _very_ likely that after the GC cycle has occured there will be only a small impact on RSS, possibly none at all. This is because the operating system will ignore the madvise(1) messages we send it until there is sufficient memory preasure (ie, the whole system is running low on ram).

Please try and let us know what you see. As always, please post _text_, not screenshots.

[santhoshkarthi]

@davecheney So you are saying that even single thread go program would use 9MB of RAM, Our main intention of moving to GO from ruby is, RAM usage, as ruby was using more RAM(close to 8.5MB), Now when you say 9MB, then both scripting(ruby) and GO is taking more or less same amount of RAM.
Is it possible to reduce the heap usage from 4MB to somewhat 2MB or less

[davecheney]

The current minimum heap size of a Go program is 4mb. In addition to this the operating system threads that back goroutines should be added to that as well as some non heap memory used by the runtime. In your case this may be somewhere between 7 and 9mb.

Please remember that RSS is _not_ how much memory is a program using, it is the _resident segment size_. Many things influence the value reported in RSS including the availability of swap and how much of the process may be swapped, if the system has reclaimed pages which we have madvise(DONTNEED) as part of the scavenger. A high RSS value does not necessarily mean that memory is not available for other processes, and so on.

If memory consumption is your primary objective I would suggest investigating https://tinygo.org/ who may (I cannot confirm) have a different approach to memory allocation.

I'll defer to @randall77 and @mknyszek on the question of if the minimum heap size can be reduced.

[randall77]

With @mknyszek's fix (adding a runtime.GC call to the start of main), you should not have to wait until you use 4MB to have GC run. It will run every 2 minutes. That should keep the heap size well below 4MB in this example.

We should be able to fix the need for that call in 1.16.

As far as lowering the minimum heap size, I suppose that's possible but I'd want to understand whether the above fix would be enough first. Ideally with the above fix, the 4MB is just virtual memory, not real memory.

have tried with other go programs, I did not see any other messages printed other than the messages in the code,

Try my example, but allocate 1MB instead of 1KB. You should see GC reports.

and one more thing that I still understand is, why heap memory is keep growing, when we dont create any dynamic memory

I suspect the allocations you're seeing are from the fmt package. You can check for sure by collecting a heap profile.

[santhoshkarthi]

@davecheney I have gone through the link that you shared(https://tinygo.org/) but it looks like it is for microcontroller, ours is a microprocessor,(imx6-ARM7) and we are running linux-4.9, So the process wise we can run many process, even go application it does not seems to be heavy process(as I could see 0% CPU utilization most of the time). If memory is stable, definitely, It would be really great.
But in the internet if we go thorough how to get the actual RAM memory for each process, they say RSS(ps -l) or cat /proc/$PID/status

[santhoshkarthi]

@randall77 As you said, I added "runtime.GC()" in my main program, and I could see "gc" is getting triggered but it did not clear any memory,
`gc 2 @120.558s 0%: 0.11+7.4+0.12 ms clock, 0.11+0/1.5/5.6+0.12 ms cpu, 0->0->0 MB, 4 MB goal, 1 P

GC forced
gc 11 @1200.949s 0%: 0.11+14+0.31 ms clock, 0.11+0/3.6/10+0.31 ms cpu, 0->0->0 MB, 4 MB goal, 1 P

GC forced
gc 15 @1681.120s 0%: 0.11+7.0+0.11 ms clock, 0.11+0/1.2/5.6+0.11 ms cpu, 0->0->0 MB, 4 MB goal, 1 P

GC forced
gc 27 @3121.646s 0%: 0.11+18+0.12 ms clock, 0.11+0/6.2/11+0.12 ms cpu, 0->0->0 MB, 4 MB goal, 1 P`

Is it possible to decrease the heap memory threshold from 4MB to 1MB something.

and another question, Is there way to clear/flush the memory after we can fmt.Sprintf if this is what increasing the RAM memory.

Or is there anyother format string function which does not use fmt package so that my program RAM memory would not grow.

[santhoshkarthi]

It would be really great and I would appreciate, if you guys can tell me way to make my Go program stable without Program RAM memory getting increased over that time like what other language does Eg, C, Ruby, Python.
@davecheney @randall77 @mknyszek
Thanks in advance

[santhoshkarthi]

We have many applications in C and ruby running in our Embedded linux board, I dont see any RSS or RAM memory getting increased even after couple of days, It always shows the same amount of RAM(RSS) memory.

[randall77]

@randall77 As you said, I added "runtime.GC()" in my main program, and I could see "gc" is getting triggered but it did not clear any memory

How did you determine that it "did not clear any memory"? Those log lines imply that your Go heap is less than 1MB (1/2 MB? Not sure how we round) and not growing.

Is it possible to decrease the heap memory threshold from 4MB to 1MB something.

You can try setting GOGC to a value less than 100. I think setting it to 10 should give you a 400KB heap. (It's an environment variable, or you can set it at the start of main with runtime/debug.SetGCPercent.)

and another question, Is there way to clear/flush the memory after we can fmt.Sprintf if this is what increasing the RAM memory.

You can call runtime.GC to run the garbage collector more often, and runtime/debug.FreeOSMemory to accelerate the pace of returning unused pages to the OS. Note that they are both expensive operations, you probably don't want to call them after every print.

Or is there anyother format string function which does not use fmt package so that my program RAM memory would not grow.

I don't know of one. You could write your own.
Your program also uses the json and net packages, which may contain allocations. Go is not really set up to achieve 0 allocations. It's certainly possible, but the stdlib is not designed that way, so you'd need to roll your own ~everything.

[santhoshkarthi]

@randall77 Yeah it clears out RAM memory after it reaches to some 6MB, I think when we add runtime.GC in our code, it gets triggered every 10 sec I guess, Is there way in which we can specify the time interval at which "GC" will get triggered. Basically I dont want to be called for every 10 sec or too frequently.

Probably I will run the code for long run without having runtime.GC(), and see how much of RAM it uses and how much it had grown from the start of the program.

Thanks alot for your support