runtime: GC freeing goroutines memory but then taking it again #8832

siritinga · 2014-09-29T07:08:16Z

I'm seen this in tip version:
go version devel +9472d0e26c23 Sun Sep 28 08:27:05 2014 -0700 linux/amd64

Using this simple program:
http://play.golang.org/p/ircvbhPy3u

There is a related issue here:
https://golang.org/issue/8287

It will immediately use 250 MB of RES memory. After about 10 minutes, the scavenger will
free 205 MB, showing about 45MB of RES. Ignoring that there are still 45 MB used, the
real problem is that after that point, the RES memory will increase slowly until it uses
250MB of RES again!

This is what "ps u" shows every 10 seconds:

USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
user     22626  2.5  3.1 261336 258096 pts/4   Sl+  08:34   0:00 ./tmp
user     22626  1.6  3.1 261336 258164 pts/4   Sl+  08:34   0:00 ./tmp
user     22626  1.0  3.1 261336 258164 pts/4   Sl+  08:34   0:00 ./tmp
[...] 9 minutes later... 
user     22626  0.0  3.2 261336 258792 pts/4   Sl+  08:34   0:00 ./tmp
user     22626  0.0  3.2 261336 258792 pts/4   Sl+  08:34   0:00 ./tmp
[Here the scavenger frees the memory]
user     22626  0.0  0.6 261336 48776 pts/4    Sl+  08:34   0:00 ./tmp
user     22626  0.0  0.6 261336 48776 pts/4    Sl+  08:34   0:00 ./tmp
user     22626  0.0  0.6 261336 48776 pts/4    Sl+  08:34   0:00 ./tmp
user     22626  0.0  0.6 261336 48776 pts/4    Sl+  08:34   0:00 ./tmp
user     22626  0.0  0.6 261336 48776 pts/4    Sl+  08:34   0:00 ./tmp
user     22626  0.0  0.6 261336 48776 pts/4    Sl+  08:34   0:00 ./tmp
user     22626  0.0  0.6 261336 48776 pts/4    Sl+  08:34   0:00 ./tmp
user     22626  0.0  0.6 261336 48776 pts/4    Sl+  08:34   0:00 ./tmp
user     22626  0.0  0.6 261336 48776 pts/4    Sl+  08:34   0:00 ./tmp
user     22626  0.0  0.6 261336 48776 pts/4    Sl+  08:34   0:00 ./tmp
user     22626  0.0  0.6 261336 48776 pts/4    Sl+  08:34   0:00 ./tmp
user     22626  0.0  0.6 261336 48776 pts/4    Sl+  08:34   0:00 ./tmp
[from here, the memory is increased little by little]
user     22626  0.0  0.6 261336 50384 pts/4    Sl+  08:34   0:00 ./tmp
user     22626  0.0  0.8 261336 64736 pts/4    Sl+  08:34   0:00 ./tmp
user     22626  0.0  0.9 261336 79096 pts/4    Sl+  08:34   0:00 ./tmp
user     22626  0.0  1.1 261336 93472 pts/4    Sl+  08:34   0:00 ./tmp
user     22626  0.0  1.3 261336 107840 pts/4   Sl+  08:34   0:00 ./tmp
user     22626  0.0  1.5 261336 122216 pts/4   Sl+  08:34   0:00 ./tmp
user     22626  0.0  1.6 261336 136600 pts/4   Sl+  08:34   0:00 ./tmp
user     22626  0.0  1.8 261336 151000 pts/4   Sl+  08:34   0:00 ./tmp
user     22626  0.0  2.0 261336 165336 pts/4   Sl+  08:34   0:00 ./tmp
user     22626  0.0  2.2 261336 179744 pts/4   Sl+  08:34   0:00 ./tmp
user     22626  0.0  2.4 261336 194080 pts/4   Sl+  08:34   0:00 ./tmp
user     22626  0.0  2.5 261336 208512 pts/4   Sl+  08:34   0:00 ./tmp
user     22626  0.0  2.7 261336 222848 pts/4   Sl+  08:34   0:00 ./tmp
user     22626  0.0  2.9 261336 237184 pts/4   Sl+  08:34   0:00 ./tmp
user     22626  0.0  3.0 261336 249728 pts/4   Sl+  08:34   0:00 ./tmp
user     22626  0.0  3.1 261336 255520 pts/4   Sl+  08:34   0:00 ./tmp
user     22626  0.0  3.1 261336 255520 pts/4   Sl+  08:34   0:00 ./tmp
user     22626  0.0  3.1 261336 255520 pts/4   Sl+  08:34   0:00 ./tmp
[remains here, it is not freed again and not detected by the GC]

ianlancetaylor · 2014-09-29T14:53:54Z

Comment 2:

Labels changed: added repo-main, release-go1.5.

ricktian1226 · 2015-02-09T07:04:42Z

When will this issue be fixed? It happens on our production project too.

bradfitz · 2015-02-09T07:11:49Z

It's targeted for Go 1.5. Any updates will occur on this thread.

RLH · 2015-02-09T17:45:11Z

I'm trying to get a sense of the use case here. You have 100,000 goroutines, could you indicate
which of the following are true, say for 99,000 of the goroutines.

Each go routine gets input from
a. A channel
b. A socket
c. shared immutable memory
d. shared mutable memory
e. no input, only output.
Each go routine provides output to
a. A channel
b. A socket
c. shared memory that it mutates
1. with pointers to freshly allocated data structures
2. no freshly allocated memory is referenced after the goroutine ends

I ask this since the answers will help dictate the best solution. An optimal solution for a goroutine
that just does a 10 second noop might be to just elide the goroutine, which is probably not what you want.

randall77 · 2015-02-09T19:21:21Z

I don't see the behavior the OP sees at tip. The RSS drops to 46MB and stays there.
Probably something changed between September and now.

go version devel +f8176f8 Mon Feb 9 18:20:28 2015 +0000 linux/amd64
(one line per minute)
khr 13203 0.2 1.5 260856 255968 pts/1 Sl+ 10:46 0:00 ./issue8832
khr 13203 0.2 1.5 260856 255972 pts/1 Sl+ 10:46 0:00 ./issue8832
khr 13203 0.1 1.5 260856 255972 pts/1 Sl+ 10:46 0:00 ./issue8832
khr 13203 0.1 1.5 260856 255972 pts/1 Sl+ 10:46 0:00 ./issue8832
khr 13203 0.1 1.5 260856 255972 pts/1 Sl+ 10:46 0:00 ./issue8832
khr 13203 0.1 1.5 260856 255980 pts/1 Sl+ 10:46 0:00 ./issue8832
khr 13203 0.0 1.5 260856 255980 pts/1 Sl+ 10:46 0:00 ./issue8832
khr 13203 0.0 1.5 260856 255980 pts/1 Sl+ 10:46 0:00 ./issue8832
khr 13203 0.0 0.2 260856 46144 pts/1 Sl+ 10:46 0:00 ./issue8832
khr 13203 0.0 0.2 260856 46144 pts/1 Sl+ 10:46 0:00 ./issue8832
khr 13203 0.0 0.2 260856 46144 pts/1 Sl+ 10:46 0:00 ./issue8832
khr 13203 0.0 0.2 260856 46144 pts/1 Sl+ 10:46 0:00 ./issue8832
khr 13203 0.0 0.2 260856 46144 pts/1 Sl+ 10:46 0:00 ./issue8832
khr 13203 0.0 0.2 260856 46144 pts/1 Sl+ 10:46 0:00 ./issue8832
khr 13203 0.0 0.2 260856 46144 pts/1 Sl+ 10:46 0:00 ./issue8832
khr 13203 0.0 0.2 260856 46144 pts/1 Sl+ 10:46 0:00 ./issue8832
khr 13203 0.0 0.2 260856 46144 pts/1 Sl+ 10:46 0:00 ./issue8832
khr 13203 0.0 0.2 260856 46144 pts/1 Sl+ 10:46 0:00 ./issue8832
khr 13203 0.0 0.2 260856 46144 pts/1 Sl+ 10:46 0:00 ./issue8832

siritinga · 2015-02-09T20:16:13Z

It is still there. Slower, but I see it going up to 56 MB before I stopped it, in about half an hour.

randall77 · 2015-02-10T00:49:46Z

So it is, if you wait long enough (for me, 16 minutes after the free) it starts growing. Very strange. The runtime doesn't allocate a single MSpan during that time, so I'm inclined to think this is a bug in linux/madvise. But I haven't been able to reproduce it outside the Go runtime. I'll keep looking.

minux · 2015-02-10T00:53:33Z

Could it because somehow our GC tries to scan or otherwise read freed MSpans?

randall77 · 2015-02-10T00:59:31Z

I suppose it is possible, but I don't see how that doesn't happen in the first 16 minutes and then starts happening thereafter. Lots of GCs happen in that window.

randall77 · 2015-02-10T15:08:40Z

I replaced the madvise call with munmap. It fixed the problem and the program never crashed. That tells us that the runtime never touches those pages after it is done with them, and that the bug is probably in madvise. Or munmap is buggy as well...

dvyukov · 2015-02-10T15:34:53Z

Have you changed sysUsed? How?

randall77 · 2015-02-10T19:01:12Z

No, I have not changed sysUsed. If the program tried to use any sysUnused page again, it would fault. Can't be checked in, of course, but it's fine for debugging this problem.

randall77 · 2015-02-11T00:01:55Z

I do not see this bug on my home Ubuntu box

$ uname -a
Linux linux 3.8.0-44-generic #66~precise1-Ubuntu SMP Tue Jul 15 04:01:04 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux

Might be something os-specific. siritinga, what's your machine running?

randall77 · 2015-02-11T07:15:59Z

On an amazon ec2 instance (c4.xlarge, Ubuntu Server 14.04 LTS), the memory comes back really fast, about 4 minutes after it gets madvised:

USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
ubuntu 7236 1.6 3.3 260856 257244 pts/0 Sl 04:03 0:00 ./issue8832
ubuntu 7236 0.4 3.3 260856 257244 pts/0 Sl 04:03 0:00 ./issue8832
ubuntu 7236 0.3 3.3 260856 257448 pts/0 Sl 04:03 0:00 ./issue8832
ubuntu 7236 0.2 3.3 260856 258800 pts/0 Sl 04:03 0:00 ./issue8832
ubuntu 7236 0.2 3.3 260856 258800 pts/0 Sl 04:03 0:00 ./issue8832
ubuntu 7236 0.1 3.3 260856 258800 pts/0 Sl 04:03 0:00 ./issue8832
ubuntu 7236 0.1 3.3 260856 258808 pts/0 Sl 04:03 0:00 ./issue8832
ubuntu 7236 0.1 3.3 260856 258808 pts/0 Sl 04:03 0:00 ./issue8832
ubuntu 7236 0.1 3.3 260856 258808 pts/0 Sl 04:03 0:00 ./issue8832
ubuntu 7236 0.1 0.8 260856 63296 pts/0 Sl 04:03 0:00 ./issue8832
ubuntu 7236 0.1 1.9 260856 147696 pts/0 Sl 04:03 0:00 ./issue8832
ubuntu 7236 0.1 2.8 260856 216064 pts/0 Sl 04:03 0:00 ./issue8832
ubuntu 7236 0.1 3.3 260856 255576 pts/0 Sl 04:03 0:00 ./issue8832
ubuntu 7236 0.1 3.3 260856 255576 pts/0 Sl 04:03 0:00 ./issue8832
ubuntu 7236 0.1 3.3 260856 255576 pts/0 Sl 04:03 0:00 ./issue8832

Linux ip-172-30-0-129 3.13.0-44-generic #73-Ubuntu SMP Tue Dec 16 00:22:43 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux

Still don't know what is going on.

siritinga · 2015-02-11T08:22:27Z

I don't have access right now to the computer where I did the test to check the kernel version, but it is a Ubuntu 14.04 TLS 64 bits with the latests updates applied.

Update #8832 This is probably not the root cause of the issue. Resolve TODO about setting unusedsince on a wrong span. Change-Id: I69c87e3d93cb025e3e6fa80a8cffba6ad6ad1395 Reviewed-on: https://go-review.googlesource.com/4390 Reviewed-by: Keith Randall <[email protected]>

randall77 · 2015-02-11T21:18:02Z

I have successfully reproduced this outside of Go. I hacked the runtime to log every time it does an mmap, munmap, or madvise. A little C program replays the log and exhibits the same behavior.

Part of the problem may be the number of madvise calls. There are over 4000 of them in this example. The resulting heap has lots of 1 page in-use spans interspersed with small (1-10 pages typically) not-in-use spans. I'm not sure why our in-use pages are so scattered. I'll look into that, it is not the root cause of this bug but may be contributing.

I'll see if I can send the extracted example to linux folks.

randall77 · 2015-02-11T21:25:48Z

replay.c
memlog

gcc replay.c -o replay
./replay memlog

It runs the log and then prints RSS once a second. Watch it grow, kind of like a chia pet.

davecheney · 2015-02-11T21:30:12Z

Testing on my system (ubuntu linux 14.04.1) fails to grow at all, stupid
chia pet.

Dumb question, is swap disabled on the systems that you see this behaviour
on?

On Thu, Feb 12, 2015 at 8:25 AM, Keith Randall [email protected]
wrote:

replay.c http://keithandkatie.com/downloads/replay.c
memlog http://keithandkatie.com/downloads/memlog

gcc replay.c -o replay
./replay memlog

It runs the log and then prints RSS once a second. Watch it grow, kind of
like a chia pet.

—
Reply to this email directly or view it on GitHub
#8832 (comment).

ianlancetaylor · 2015-02-11T21:37:44Z

Nice repro. Wacky, but nice.

I guess we can leave this issue open until we hear back from the kernel folks to see whether there is something we can do to avoid the odd behaviour.

randall77 · 2015-02-11T22:43:06Z

Both. Swap is disabled on the ec2 instance where this happens quickest. It also happens on my laptop where swap is enabled, although it takes a lot longer (2 min vs. 45 min).

randall77 · 2015-02-12T00:39:53Z

Kernel bug report: https://bugzilla.kernel.org/show_bug.cgi?id=93111

randall77 · 2015-02-23T22:14:38Z

Patch is out to work around the kernel bug. The other part of this issue is why our heap is so fragmented in the first place. It deserves its own issue, #9869.

gopherbot · 2015-09-30T19:02:11Z

CL https://golang.org/cl/15191 mentions this issue.

This fixes an issue where the runtime panics with "out of memory" or "cannot allocate memory" even though there's ample memory by reducing the number of memory mappings created by the memory allocator. Commit 7e1b61c worked around issue #8832 where Linux's transparent huge page support could dramatically increase the RSS of a Go process by setting the MADV_NOHUGEPAGE flag on any regions of pages released to the OS with MADV_DONTNEED. This had the side effect of also increasing the number of VMAs (memory mappings) in a Go address space because a separate VMA is needed for every region of the virtual address space with different flags. Unfortunately, by default, Linux limits the number of VMAs in an address space to 65530, and a large heap can quickly reach this limit when the runtime starts scavenging memory. This commit dramatically reduces the number of VMAs. It does this primarily by only adjusting the huge page flag at huge page granularity. With this change, on amd64, even a pessimal heap that alternates between MADV_NOHUGEPAGE and MADV_HUGEPAGE must reach 128GB to reach the VMA limit. Because of this rounding to huge page granularity, this change is also careful to leave large used and unused regions huge page-enabled. This change reduces the maximum number of VMAs during the runtime benchmarks with GODEBUG=scavenge=1 from 692 to 49. Fixes #12233. Change-Id: Ic397776d042f20d53783a1cacf122e2e2db00584 Reviewed-on: https://go-review.googlesource.com/15191 Reviewed-by: Keith Randall <[email protected]>

gopherbot · 2015-11-16T23:00:46Z

CL https://golang.org/cl/16980 mentions this issue.

…age granularity This fixes an issue where the runtime panics with "out of memory" or "cannot allocate memory" even though there's ample memory by reducing the number of memory mappings created by the memory allocator. Commit 7e1b61c worked around issue #8832 where Linux's transparent huge page support could dramatically increase the RSS of a Go process by setting the MADV_NOHUGEPAGE flag on any regions of pages released to the OS with MADV_DONTNEED. This had the side effect of also increasing the number of VMAs (memory mappings) in a Go address space because a separate VMA is needed for every region of the virtual address space with different flags. Unfortunately, by default, Linux limits the number of VMAs in an address space to 65530, and a large heap can quickly reach this limit when the runtime starts scavenging memory. This commit dramatically reduces the number of VMAs. It does this primarily by only adjusting the huge page flag at huge page granularity. With this change, on amd64, even a pessimal heap that alternates between MADV_NOHUGEPAGE and MADV_HUGEPAGE must reach 128GB to reach the VMA limit. Because of this rounding to huge page granularity, this change is also careful to leave large used and unused regions huge page-enabled. This change reduces the maximum number of VMAs during the runtime benchmarks with GODEBUG=scavenge=1 from 692 to 49. Fixes #12233. Change-Id: Ic397776d042f20d53783a1cacf122e2e2db00584 Reviewed-on: https://go-review.googlesource.com/15191 Reviewed-by: Keith Randall <[email protected]> Reviewed-on: https://go-review.googlesource.com/16980 Run-TryBot: Austin Clements <[email protected]> Reviewed-by: Ian Lance Taylor <[email protected]> Reviewed-by: Russ Cox <[email protected]>

siritinga added new labels Sep 29, 2014

bradfitz modified the milestone: Go1.5 Dec 16, 2014

bradfitz removed release-go1.5 labels Dec 16, 2014

randall77 closed this as completed Feb 9, 2015

randall77 reopened this Feb 10, 2015

randall77 self-assigned this Feb 10, 2015

mikioh changed the title ~~runtime : GC freeing goroutines memory but then taking it again~~ runtime: GC freeing goroutines memory but then taking it again Feb 10, 2015

randall77 mentioned this issue Feb 13, 2015

runtime: dead Gs cause span fragmentation #9869

Open

bradfitz added kernel-bug labels Feb 18, 2015

gopherbot closed this as completed in 7e1b61c Feb 25, 2015

aclements mentioned this issue Sep 25, 2015

runtime: huge page fragmentation on Linux leads to out of memory #12233

Closed

jsravn mentioned this issue Jul 27, 2016

Implement strategies to limit memory usage. prometheus/prometheus#455

Closed

golang locked and limited conversation to collaborators Nov 16, 2016

gopherbot added the FrozenDueToAge label Nov 16, 2016

rsc unassigned randall77 Jun 23, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

runtime: GC freeing goroutines memory but then taking it again #8832

runtime: GC freeing goroutines memory but then taking it again #8832

siritinga commented Sep 29, 2014

ianlancetaylor commented Sep 29, 2014

ricktian1226 commented Feb 9, 2015

bradfitz commented Feb 9, 2015

RLH commented Feb 9, 2015

randall77 commented Feb 9, 2015

siritinga commented Feb 9, 2015

randall77 commented Feb 10, 2015

minux commented Feb 10, 2015 via email

randall77 commented Feb 10, 2015

randall77 commented Feb 10, 2015

dvyukov commented Feb 10, 2015

randall77 commented Feb 10, 2015

randall77 commented Feb 11, 2015

randall77 commented Feb 11, 2015

siritinga commented Feb 11, 2015

randall77 commented Feb 11, 2015

randall77 commented Feb 11, 2015

davecheney commented Feb 11, 2015

ianlancetaylor commented Feb 11, 2015

randall77 commented Feb 11, 2015

randall77 commented Feb 12, 2015

randall77 commented Feb 23, 2015

gopherbot commented Sep 30, 2015

gopherbot commented Nov 16, 2015

runtime: GC freeing goroutines memory but then taking it again #8832

runtime: GC freeing goroutines memory but then taking it again #8832

Comments

siritinga commented Sep 29, 2014

ianlancetaylor commented Sep 29, 2014

ricktian1226 commented Feb 9, 2015

bradfitz commented Feb 9, 2015

RLH commented Feb 9, 2015

randall77 commented Feb 9, 2015

siritinga commented Feb 9, 2015

randall77 commented Feb 10, 2015

minux commented Feb 10, 2015 via email

randall77 commented Feb 10, 2015

randall77 commented Feb 10, 2015

dvyukov commented Feb 10, 2015

randall77 commented Feb 10, 2015

randall77 commented Feb 11, 2015

randall77 commented Feb 11, 2015

siritinga commented Feb 11, 2015

randall77 commented Feb 11, 2015

randall77 commented Feb 11, 2015

davecheney commented Feb 11, 2015

ianlancetaylor commented Feb 11, 2015

randall77 commented Feb 11, 2015

randall77 commented Feb 12, 2015

randall77 commented Feb 23, 2015

gopherbot commented Sep 30, 2015

gopherbot commented Nov 16, 2015