Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Closed
siritinga opened this issue Sep 29, 2014 · 24 comments
Closed

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

siritinga opened this issue Sep 29, 2014 · 24 comments
Labels
FrozenDueToAge
Milestone
Go1.5

Comments

@siritinga
Copy link 

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
Copy link
Contributor

Comment 2:

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

@bradfitz bradfitz modified the milestone: Go1.5 Dec 16, 2014
@ricktian1226
Copy link

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

@bradfitz
Copy link
Contributor

bradfitz commented Feb 9, 2015

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

@RLH
Copy link
Contributor

RLH commented Feb 9, 2015

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.

  1. 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.
  2. 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
Copy link
Contributor

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
Copy link
Author

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

@randall77
Copy link
Contributor

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.

@randall77 randall77 reopened this Feb 10, 2015
@randall77 randall77 self-assigned this Feb 10, 2015
@minux
Copy link
Member

minux commented Feb 10, 2015 via email

@randall77
Copy link
Contributor

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.

@mikioh 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
Copy link
Contributor

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
Copy link
Member

dvyukov commented Feb 10, 2015

Have you changed sysUsed? How?

@randall77
Copy link
Contributor

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
Copy link
Contributor

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
Copy link
Contributor

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
Copy link
Author

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.

dvyukov added a commit that referenced this issue Feb 11, 2015
@dvyukov
runtime: fix span unusedsince setup
e604c6e 
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 <khr@golang.org>
@randall77
Copy link
Contributor

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
Copy link
Contributor

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
Copy link
Contributor

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 notifications@github.com
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
Copy link
Contributor

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
Copy link
Contributor

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
Copy link
Contributor

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

@randall77 randall77 mentioned this issue Feb 13, 2015
Open
@randall77
Copy link
Contributor

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.

@aclements aclements mentioned this issue Sep 25, 2015
Closed
@gopherbot
Copy link

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

aclements added a commit that referenced this issue Oct 2, 2015
@aclements
runtime: adjust huge page flags only on huge page granularity
44078a3 
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 <khr@golang.org>
@gopherbot
Copy link

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

aclements added a commit that referenced this issue Nov 17, 2015
@aclements
[release-branch.go1.5] runtime: adjust huge page flags only on huge p…
244294f 
…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 <khr@golang.org>
Reviewed-on: https://go-review.googlesource.com/16980
Run-TryBot: Austin Clements <austin@google.com>
Reviewed-by: Ian Lance Taylor <iant@golang.org>
Reviewed-by: Russ Cox <rsc@golang.org>
@jsravn jsravn mentioned this issue Jul 27, 2016
Closed
@golang golang locked and limited conversation to collaborators Nov 16, 2016
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge
Projects
None yet
Milestone
Go1.5
Development

No branches or pull requests
10 participants
@bradfitz @davecheney @minux @RLH @dvyukov @ricktian1226 @ianlancetaylor @siritinga @randall77 @gopherbot