A strange problem with go GC on slice

[Wu Jian]

Hi everyone,

    Recently I ran into a problem about go GC. Generally speaking, my job is generating a new slice from a existing map on every second, and assign it to a global variable.

Here's my code.

 

package main

import (
 "fmt"
 "math/rand"
 "runtime"
 "time"
)

 

var peermap map[uint64]int64 = make(map[uint64]int64, 10000000)
var g []int64

 

func main() {

 //runtime.GOMAXPROCS(4)

 

 // fill the map
 r := rand.New(rand.NewSource(199))
 for i := 0; i < 10000000; i++ {
  peermap[uint64(r.Int63())] = 6
 }

 go test()

 select {}

}

 

func test() {
 for {
  runtime.GC()
  time.Sleep(1 * time.Second)
  p := make([]int64, 10000000)
  i := 0
  for _, v := range peermap {
   p[i] = v
   i++
  }

  g = p
  fmt.Println("g.size() = ", len(g))
 }
}

 

After I typed "go run test.go", I used "top" command to watch the memory status of the test program.

 

In the case above, the virtual memory this process occupied increased to 746M and never changed.

 

However, if I add the code "runtime.GOMAXPROCS(4)" at the beginning of the main function and run this program again, I found that the virtual memory that the program occupied would increase forever.

 

Moreover, if I just made the slice (p := make([]int64, 10000000)), did not copy the data from the map, and assigned the p to g (g = p), there wouldn't be any memory leak, no matter whether I write "runtime.GOMAXPROCS(4)" or not.

 

It's highly appreciated if some one could tell me why this happened.

Thanks :)

[Jesse McNelis]

On Fri, Aug 9, 2013 at 6:23 PM, Wu Jian <ravi...@gmail.com> wrote:

However, if I add the code "runtime.GOMAXPROCS(4)" at the beginning of the main function and run this program again, I found that the virtual memory that the program occupied would increase forever.

You have two data races.

1. you're not protecting 'peermap' from being accessed by multiple threads at the same time.

2. you're not protecting the 'g' from being accessed by multiple threads at the same time.

You should use a sync.Mutex to protect them.

You should fix those first since they can result in memory corruption with unpredictable results.

 

 

Moreover, if I just made the slice (p := make([]int64, 10000000)), did not copy the data from the map, and assigned the p to g (g = p), there wouldn't be any memory leak, no matter whether I write "runtime.GOMAXPROCS(4)" or not.

 

It's highly appreciated if some one could tell me why this happened.

Thanks :)

--
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.
For more options, visit https://groups.google.com/groups/opt_out.
 
 

--
=====================
http://jessta.id.au

[Viacheslav Biriukov]

There is only one goroutine and from my understanfing there is no race, isn't?

2013/8/9 Jesse McNelis <jes...@jessta.id.au>

--

Viacheslav Biriukov
BR

http://biriukov.me

[Wu Jian]

Yep, no race at all.

In fact there were lots of go routines in my program, but they were meaningless in this case. Thus I removed them so that we could focus on the real problem.

--
武健

北京搜狗科技发展有限公司

MSN：nir.j...@hotmail.com

QQ: 124416650

[Carlos Castillo]

First of all, due to the Garbage Collector, memory that is collected is put into a free list, and reused for further allocations. This means that from the OS's perspective, a go program never returns memory to the OS (ie: it never "frees" it.) Unless the OS takes memory back from the go process, the numbers in your system monitor will never go down. Also if you allocate memory, but don't write to it, the os doesn't actually need to give your program any memory (it will give you memory pages on use), so your "leak-free" scenario is just an illusion made possible how Virtual memory works. 

Second, for the GC to be efficient, it can't be collecting all the time (especially if it stops the world). Therefore there is a watermark that is used, if an allocation would exceed the watermark, then the collector is run. After a collection, the watermark is reset to the amount of active memory * (100 + GCPercent) / 100. By default GCPercent is 100, so after every collection, the watermark is set to 2 times the amount of active memory. This doesn't apply to your program, because you manually call runtime.GC() in the test() loop, but for programs that don't call runtime.GC that is what happens.

On my run, the program uses 460MB (Real Memory). Where did all that memory use come from? If you analyze the code, it looks like you are using 8 bytes of memory for each element of g, and 16 bytes (key + value) for each element of peermap. Since there are 10 million entries you probably assumed that you were only using: (8 * 1e7 = 76.3 MB) + (16 * 1e7 = 152.6MB) = 228.9MB. This estimate is incorrect for 2 reasons:

1. Peermap is a hashtable, and will at best use 187.8MB and at worst use 375.6 MB due to the extra space used to minimize hash collisions, profiling shows that it in fact uses somewhere around the midpoint of 281MB (total mem reported by the profiler was 288MB)
2. At any given time, there could be two 76.3MB slices in memory, both of which have pointers to them (meaning that to the GC they are alive). For example, if you consider the memory use at any point after the allocation of a new p slice, but before it's assigned to g, then the slice at g also exists, and both are alive. This means that you should count the memory for the slice at least twice.

Result: 281MB + 76.3 * 2 = 433.6MB - Very close to what my System Monitor says. The difference is probably due to the memory used by the runtime for buffers, caches, and keeping track of the program's allocations.

For the record I used the following altered program http://play.golang.org/p/Jnx40NcN9-, which pauses after the creation of the hash, and creates memory profiles you can see with the pprof tool. I also got rid of the 10000000 magic number.

The GOMAXPROCS > 1 does seem like a memory leak though, especially since only one actual user-created go-routine is running at a time (no matter the number of PROCS). I am using tip on darwin, what were you using?

[Carlos Castillo]

As a follow up, I ran the code using GODEBUG=gctrace=1 (for 1.1 you use GOGCTRACE=1 instead). For GOMAXPROCS=1 the lines printed on each GC during test() were constantly variants of:

gc5(1): 285+0+0 ms, 456 -> 380 MB 114045 -> 114034 (114111-77) objects, 0(0) handoff, 0(0) steal, 0/0/0 yields

gc6(1): 287+0+0 ms, 456 -> 380 MB 114045 -> 114034 (114123-89) objects, 0(0) handoff, 0(0) steal, 0/0/0 yields

gc7(1): 284+0+0 ms, 456 -> 380 MB 114045 -> 114034 (114135-101) objects, 0(0) handoff, 0(0) steal, 0/0/0 yields

gc8(1): 277+0+0 ms, 456 -> 380 MB 114045 -> 114034 (114147-113) objects, 0(0) handoff, 0(0) steal, 0/0/0 yields

gc9(1): 278+0+0 ms, 456 -> 380 MB 114045 -> 114034 (114159-125) objects, 0(0) handoff, 0(0) steal, 0/0/0 yields

Meaning that every time runtime.GC ran in the loop, the memory use went from 456MB down to 380MB (ie: the size of one stale 1e7 element slice).

With GOMAXPROCS=2 the following happens:

gc5(2): 289+0+0 ms, 456 -> 456 MB 113247 -> 113237 (113310-73) objects, 1(31) handoff, 3(92) steal, 22/13/434 yields

gc6(2): 288+0+0 ms, 532 -> 532 MB 113248 -> 113238 (113322-84) objects, 2(57) handoff, 3(67) steal, 42/18/361 yields

gc7(2): 283+0+0 ms, 609 -> 608 MB 113249 -> 113239 (113334-95) objects, 1(31) handoff, 2(6) steal, 22/13/230 yields

gc8(2): 290+0+0 ms, 685 -> 685 MB 113250 -> 113240 (113346-106) objects, 2(57) handoff, 2(1116) steal, 42/17/392 yields

gc9(2): 332+0+0 ms, 761 -> 761 MB 113251 -> 113241 (113358-117) objects, 2(36) handoff, 1(4) steal, 35/15/715 yields

gc10(2): 358+0+0 ms, 837 -> 837 MB 113252 -> 113242 (113370-128) objects, 1(31) handoff, 1(2) steal, 27/13/74 yields

Meaning that every time, the GC doesn't seem to be doing much (it's certainly not collecting any stale slices).

[Ian Lance Taylor]

On Sat, Aug 10, 2013 at 1:52 PM, Carlos Castillo <cook...@gmail.com> wrote:
> First of all, due to the Garbage Collector, memory that is collected is put
> into a free list, and reused for further allocations. This means that from
> the OS's perspective, a go program never returns memory to the OS (ie: it
> never "frees" it.) Unless the OS takes memory back from the go process, the
> numbers in your system monitor will never go down. Also if you allocate
> memory, but don't write to it, the os doesn't actually need to give your
> program any memory (it will give you memory pages on use), so your
> "leak-free" scenario is just an illusion made possible how Virtual memory
> works.

Note that the Go runtime does slowly return memory to the OS if
possible. See runtime·MHeap_Scavenger in src/runtime/mheap.c.

Ian

[Wu Jian]

In fact, after I kept running my test program for a while, the program throw a fatal error: runtime: out of memory.

I still don't know why this happened when I set GOMAXPROCS to 4.

--
You received this message because you are subscribed to a topic in the Google Groups "golang-nuts" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/golang-nuts/aa14gSRKPM0/unsubscribe.
To unsubscribe from this group and all its topics, send an email to golang-nuts...@googlegroups.com.

For more options, visit https://groups.google.com/groups/opt_out.

--

[Wu Jian]

Thanks for your reply, Carlos. To your last question, I'm using RHEL 5.8(Tikanga) x64:)

As I mentioned, my test program paniced when the momery it allocated reached to 10G. The error msg is "fatal error: runtime: out of memory"

Therefore, my problem is still there. What shoud I do if  I want to set GOMAXPROCS=4 and run my program correctly.

Thanks.

--

You received this message because you are subscribed to a topic in the Google Groups "golang-nuts" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/golang-nuts/aa14gSRKPM0/unsubscribe.
To unsubscribe from this group and all its topics, send an email to golang-nuts...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.

[Carlos Castillo]

Yes, but as discussed elsewhere on this list, the operation performed to "return the memory" doesn't do anything noticeable to system statistics: RES doesn't go down, free system memory doesn't go up. I was mostly explaining to the OP how in any go program, the memory stats on the OS side (eg: in top) won't go down ever, unless the OS needs to take the memory.

runtime.SysUnused (called by the scavenger) makes the memory easier to take back by the OS. For all intents and purposes it is equivalent to "free" memory (not paged, selected first by kernel to be re-used before active memory), but the system stats don't reflect that, at least not on any system I use. The best I've seen is that on darwin, the overall memory pie chart slides the "released" memory from the active section to the inactive section (not the Free section). I have heard anecdotal evidence that some linux systems in overcommit mode will actually display accurate memory stats, but I've never seen it myself.

It also isn't implemented on Windows (yet...)

--
Carlos Castillo

[Dmitry Vyukov]

Windows patch is sent https://codereview.appspot.com/12720043/

--

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.

[Carlos Castillo]

Yes I noticed that, I had been following issue 5584 for a while. And in fact it may make the Windows version of Go build programs that have accurate OS memory stats, in addition to releasing unused memory back to the OS.

That being said, the problem of the numbers not going down (but not going up either) under regular use, is only perceptual one on systems that have a working SysUnused.

[Wu Jian]

Thanks to all.

But I still got a program which would panic here. What should I do with it? 

I still don't understand why my program panic if I add runtime.GOMAXPROCS(4) at the beginning of main func.

--
You received this message because you are subscribed to a topic in the Google Groups "golang-nuts" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/golang-nuts/aa14gSRKPM0/unsubscribe.
To unsubscribe from this group and all its topics, send an email to golang-nuts...@googlegroups.com.

For more options, visit https://groups.google.com/groups/opt_out.

[Carlos Castillo]

I have written a simpler example (no goroutines), with some tuneable knobs at the top: http://play.golang.org/p/IhCBf2f_hT

If that program is run with GOMAXPROCS=1 everything is fine, GODEBUG=gctrace=1 (1.1: GOGCTRACE=1) shows that the memory hovers at a fixed amount after every GC. If GOMAXPROCS is changed to 2, or greater, then after every collect there is more and more memory in use.

Changing the parameters at the top of the program (decreasing N_ELEMS to 1e6, or changing m_type to the array definition) causes the program to work with GOMAXPROCS>=2.

This seems like a bug in the collector. With some prolific go-devs now listening in, should an issue be posted?

[Jakob Borg]

2013/8/12 Carlos Castillo <cook...@gmail.com>:

> I have written a simpler example (no goroutines), with some tuneable knobs
> at the top: http://play.golang.org/p/IhCBf2f_hT
>
> If that program is run with GOMAXPROCS=1 everything is fine,
> GODEBUG=gctrace=1 (1.1: GOGCTRACE=1) shows that the memory hovers at a fixed
> amount after every GC. If GOMAXPROCS is changed to 2, or greater, then after
> every collect there is more and more memory in use.
>
> Changing the parameters at the top of the program (decreasing N_ELEMS to
> 1e6, or changing m_type to the array definition) causes the program to work
> with GOMAXPROCS>=2.
>
> This seems like a bug in the collector. With some prolific go-devs now
> listening in, should an issue be posted?

I seem to remember the garbage collector being dependent on being able
to pause all goroutines, which given the cooperative nature of the
scheduler is not possible with your program? Try adding a
runtime.Gosched() to the outer loop in your main or similar and see if
that makes a difference.

//jb

[Carlos Castillo]

That would make no sense, since it works for GOMAXPROCS=1, but not for GOMAXPROCS>=2. Also the GC trace is showing the gc being called in either scenario, just that no work is done in the GOMAXPROCS>=2 case (it thinks all objects were live). Also the pre-emptive scheduler (at tip) should allow the GC to run eventually, even before pre-emption, the GC could interrupt on allocations.

[Jakob Borg]

Right, indeed. It seems the map access is necessary to cause the
issue; I slightly reduced the problem program to

http://play.golang.org/p/Tkdqs0lWoc

Removing the "_ = m[0]" removes the issue.

2013/8/12 Carlos Castillo <cook...@gmail.com>:

> --
> 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

[Carlos Castillo]

Right, so Dimitri, Ian, this should probably be posted as an Issue, right?

@Wu Jian: If you can't wait for the compiler/GC to be fixed I can see the following stop-gap measures:

1. If possible, switch to a slice type, or try to keep the map small, since the problem only happens with a big hashmap.
2. The actual memory leak, despite being caused by the hash, happens when you allocate a new slice each time in the loop. If you were to re-write the loop to reuse slices from a pool, then you wouldn't be allocating memory when the GC was unable to collect it.
3. If you use a database table (eg: sqlite3) in place of your hash, then there won't be a problem with the GC (no bighash), and you will likely use less memory as the entire hash won't be in memory all at once.
4. Any data structure provided by a CGO library would do as well, since CGO memory isn't visible to the GC.
5. It hasn't been confirmed if this issue happened with the go1 collector (I have only tested 1.1 and tip). If go1 works, and your code doesn't use any go1.1 features, you could try the older compiler.
6. Similarly, if your platform supports GCCGO (darwin doesn't, so I can't), you could see if the GC there has this problem.

[Dmitry Vyukov]

On Mon, Aug 12, 2013 at 11:46 PM, Carlos Castillo <cook...@gmail.com> wrote:

Right, so Dimitri, Ian, this should probably be posted as an Issue, right?

Sure

This is a good test case

[Carlos Castillo]

Done Issue 6119 Posted: https://code.google.com/p/go/issues/detail?id=6119

Note: I used my example code in the issue because I couldn't get Jakob's code to exhibit the memleak.

Note 2: I noticed that building an executable, vs using go run produced visibly different gctraces, but the code still exhibited the same problem: memleak when GOMAXPROCS>=2.

[Wu Jian]

Thanks for your suggestions, Carlos. I finally took the second advice. I made two slices as a pool and did some A/B switch job on it, which temporarily solved my problem here.

--
You received this message because you are subscribed to a topic in the Google Groups "golang-nuts" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/golang-nuts/aa14gSRKPM0/unsubscribe.
To unsubscribe from this group and all its topics, send an email to golang-nuts...@googlegroups.com.

For more options, visit https://groups.google.com/groups/opt_out.

[Carlos Castillo]

Issue 6119 is now closed. The tests I made are now behaving properly.

If you build go from tip, you should see this, otherwise it'll probably be in 1.2.

Your pool solution is still a good thing to have arround, even if the GC is doing it's job, as it allows you to make better estimates about the how much memory you're using.

[Carlos Castillo]

Apparently I spoke too soon, errors have cropped up elsewhere so the change has been reverted and the issue re-opened.

--
Carlos Castillo

[Wu Jian]

I was downloading the lastest source code when I saw this post... bad news for me:(