memory leaks when creating lots of maps

[Marco Peereboom]

Executive overview:
Repeatedly creating and destroying maps leaks memory over time. Depending on
the OS settings either a whole lot of memory will be occupied or the program
eventually crashes.

The test program is a little longish but it is boiled down from a real program
we are developing. That program creates large maps of sha256, stuffs them in a
database and then tosses the map. Adding a call to runtime.GC() prolongs the
runtime however in the end the results are always the same.

Everyone I have shown this program so far has gone through the 5 phases of
denial. So before you dismiss it right away I invite you to play with the test
program. And, yes, I am fully aware of the nits that are in it and debating
those isn't my goal :) Unless I am missing something the result is that a
little bit of memory is leaked every couple of runs and eventually bad things
happen.

These are the go versions I have tested this program with:
go version devel +8bf13ae02c8e Mon Aug 19 16:22:33 2013 +1000 openbsd/amd64
go version devel +1d0a0a267088 Wed Aug 14 22:18:49 2013 +0400 linux/386
go version devel +8bf13ae02c8e Mon Aug 19 16:22:33 2013 +1000 darwin/amd64
go version go1.1.2 windows/386
go version go1.1.2 windows/amd64

-----------------------------------------------------------------------
package main

import (
"crypto/sha256"
"encoding/binary"
"fmt"
"runtime"
"runtime/debug"
"strconv"
"sync"
)

var done sync.WaitGroup

type MemTest struct {
postfix string
maxSize int64
mymap map[string][]byte
}

func NewMemTest(postfix string) (*MemTest, error) {
mt := MemTest{}
mt.postfix = postfix
mt.maxSize = 16 * 1024 * 1024
return &mt, nil
}

func (mt *MemTest) start() {
var i, keySize, valueSize int64

done.Add(1)
defer done.Done()
mt.mymap = make(map[string][]byte)
keySize = sha256.Size * 2 // ascii
valueSize = 16
elements := mt.maxSize / (keySize + valueSize) // this really is off
for i = 0; i < elements; i++ {
digest := sha256.New()
sha := make([]byte, 16)
binary.PutVarint(sha, int64(i))
digest.Write(sha)
d := digest.Sum(nil)
ds := fmt.Sprintf("%x", d)

buf := make([]byte, valueSize)

mt.mymap[ds] = buf
}
}

func (mt *MemTest) Delete() {
mt.mymap = nil
}

func getusage() (uint64, uint64) {
var m runtime.MemStats
runtime.ReadMemStats(&m)
return m.HeapAlloc, m.HeapObjects
}

func main() {
var delta int64
trygc := false
tryfree := false
runtime.GOMAXPROCS(runtime.NumCPU())
prev, _ := getusage()
fmt.Printf("Start Of Day: %v\n", prev)
memtests := make(map[string]*MemTest, 16)
for {
for x := 0; x < 8; x++ {
mt, err := NewMemTest(strconv.Itoa(x))
if err != nil {
fmt.Printf("could not create a new mem test")
continue
}
memtests[strconv.Itoa(x)] = mt
go mt.start()
}
done.Wait()
for k, mt := range memtests {
mt.Delete()
delete(memtests, k)
}
if tryfree == false && trygc == true {
runtime.GC()
}
if tryfree {
debug.FreeOSMemory()
}
now, objects := getusage()
delta = int64(now - prev)
fmt.Printf("Usage: %v delta %v objects %v\n", now, delta, objects)
prev = now
}
}
-----------------------------------------------------------------------

Example output:
Start Of Day: 175624
Usage: 273175944 delta 273000320 objects 3556907
Usage: 371666496 delta 98490552 objects 6379833
Usage: 404890128 delta 33223632 objects 7352573
Usage: 400073592 delta -4816536 objects 7246046
Usage: 406229672 delta 6156080 objects 7424067
Usage: 336162032 delta -70067640 objects 5226654
Usage: 339698072 delta 3536040 objects 5490347
Usage: 398100744 delta 58402672 objects 7006394
Usage: 331054968 delta -67045776 objects 5235921
Usage: 289647232 delta -41407736 objects 4033146
Usage: 423024248 delta 133377016 objects 7897517
Usage: 341334560 delta -81689688 objects 5531437
Usage: 837388720 delta 496054160 objects 15367983
Usage: 289569928 delta -547818792 objects 4024942
Usage: 308276472 delta 18706544 objects 4569045
Usage: 368364376 delta 60087904 objects 6118254
Usage: 855167840 delta 486803464 objects 15702178
fatal error: runtime: out of memory

goroutine 145 [running]:
runtime.throw(0x593d60)
/home/marco/hg/go/src/pkg/runtime/panic.c:506 +0x69 fp=0x20342a688
runtime.SysMap(0xc2484c0000, 0x100000)
/home/marco/hg/go/src/pkg/runtime/mem_openbsd.c:76 +0x7b fp=0x20342a6b8
runtime.MHeap_SysAlloc(0x5a9580, 0x100000)
/home/marco/hg/go/src/pkg/runtime/malloc.goc:473 +0x103 fp=0x20342a6f8
MHeap_Grow(0x5a9580, 0x10)
/home/marco/hg/go/src/pkg/runtime/mheap.c:243 +0x5c fp=0x20342a738
MHeap_AllocLocked(0x5a9580, 0x1, 0x5)
/home/marco/hg/go/src/pkg/runtime/mheap.c:126 +0x332 fp=0x20342a778
runtime.MHeap_Alloc(0x5a9580, 0x1, 0x5, 0x200000001)
/home/marco/hg/go/src/pkg/runtime/mheap.c:95 +0x7b fp=0x20342a7a0
MCentral_Grow(0x5b0400)
/home/marco/hg/go/src/pkg/runtime/mcentral.c:180 +0x8c fp=0x20342a800
runtime.MCentral_AllocList(0x5b0400, 0x208095060)
/home/marco/hg/go/src/pkg/runtime/mcentral.c:46 +0x4f fp=0x20342a828
runtime.MCache_Refill(0x208095000, 0x5)
/home/marco/hg/go/src/pkg/runtime/mcache.c:22 +0x7c fp=0x20342a848
runtime.mallocgc(0x40, 0x48ec61, 0x1)
/home/marco/hg/go/src/pkg/runtime/malloc.goc:71 +0xff fp=0x20342a8b8
cnew(0x48ec60, 0x40, 0x1)
/home/marco/hg/go/src/pkg/runtime/malloc.goc:713 +0xc1 fp=0x20342a8d8
runtime.cnewarray(0x48ec60, 0x40)
/home/marco/hg/go/src/pkg/runtime/malloc.goc:726 +0x3a fp=0x20342a8f8
makeslice1(0x489f00, 0x20, 0x40, 0x20342a9b0)
/home/marco/hg/go/src/pkg/runtime/slice.c:57 +0x4d fp=0x20342a910
growslice1(0x489f00, 0xc2484b7500, 0x20, 0x20, 0x22, ...)
/home/marco/hg/go/src/pkg/runtime/slice.c:216 +0x58 fp=0x20342a940
runtime.growslice(0x489f00, 0xc2484b7500, 0x20, 0x20, 0x2, ...)
/home/marco/hg/go/src/pkg/runtime/slice.c:183 +0x9d fp=0x20342a988
fmt.(*fmt).fmt_sbx(0xc210024c88, 0x4baea0, 0x0, 0xc2484b74c0, 0x20, ...)
/home/marco/hg/go/src/pkg/fmt/format.go:300 +0x2af fp=0x20342aa00
fmt.(*fmt).fmt_bx(0xc210024c88, 0xc2484b74c0, 0x20, 0x20, 0x4c79d0, ...)
/home/marco/hg/go/src/pkg/fmt/format.go:312 +0x6d fp=0x20342aa48
fmt.(*pp).fmtBytes(0xc210024c30, 0xc2484b74c0, 0x20, 0x20, 0x78, ...)
/home/marco/hg/go/src/pkg/fmt/print.go:588 +0x219 fp=0x20342ab70
fmt.(*pp).printArg(0xc210024c30, 0x489f00, 0xc2484b74e0, 0x78, 0x0, ...)
/home/marco/hg/go/src/pkg/fmt/print.go:806 +0x50f fp=0x20342abd0
fmt.(*pp).doPrintf(0xc210024c30, 0x4baec0, 0x2, 0x20342af30, 0x1, ...)
/home/marco/hg/go/src/pkg/fmt/print.go:1182 +0x14a2 fp=0x20342ae88
fmt.Sprintf(0x4baec0, 0x2, 0x20342af30, 0x1, 0x1, ...)
/home/marco/hg/go/src/pkg/fmt/print.go:235 +0x8e fp=0x20342aed8
main.(*MemTest).start(0xc23366cf20)
/home/marco/git/go/src/ldb/memtest3.go:43 +0x2a6 fp=0x20342af98
runtime.goexit()
/home/marco/hg/go/src/pkg/runtime/proc.c:1386 fp=0x20342afa0
created by main.main
/home/marco/git/go/src/ldb/memtest3.go:78 +0x434

goroutine 1 [semacquire]:
sync.runtime_Semacquire(0xc233661f78)
/home/marco/hg/go/src/pkg/runtime/sema.goc:198 +0x30
sync.(*WaitGroup).Wait(0x597f60)
/home/marco/hg/go/src/pkg/sync/waitgroup.go:127 +0x166
main.main()
/home/marco/git/go/src/ldb/memtest3.go:80 +0x205

goroutine 139 [runnable]:
fmt.(*pp).free(0xc2100a8000)
/home/marco/hg/go/src/pkg/fmt/print.go:173
fmt.Sprintf(0x4baec0, 0x2, 0x203420f30, 0x1, 0x1, ...)
/home/marco/hg/go/src/pkg/fmt/print.go:237 +0xd1
main.(*MemTest).start(0xc23366cfe0)
/home/marco/git/go/src/ldb/memtest3.go:43 +0x2a6
created by main.main
/home/marco/git/go/src/ldb/memtest3.go:78 +0x434

goroutine 140 [runnable]:
crypto/sha256.(*digest).Sum(0xc2484ad180, 0x0, 0x0, 0x0, 0x0, ...)
/home/marco/hg/go/src/pkg/crypto/sha256/sha256.go:141 +0x205
main.(*MemTest).start(0xc23366cfc0)
/home/marco/git/go/src/ldb/memtest3.go:42 +0x1db
created by main.main
/home/marco/git/go/src/ldb/memtest3.go:78 +0x434

goroutine 141 [runnable]:
crypto/sha256.(*digest).Write(0x20342ee38, 0x20342ed20, 0x28, 0x40, 0x0, ...)
/home/marco/hg/go/src/pkg/crypto/sha256/sha256.go:105
crypto/sha256.(*digest).checkSum(0x20342ee38, 0x0, 0x0, 0x0, 0x0)
/home/marco/hg/go/src/pkg/crypto/sha256/sha256.go:150 +0x102
crypto/sha256.(*digest).Sum(0xc2484b0780, 0x0, 0x0, 0x0, 0x0, ...)
/home/marco/hg/go/src/pkg/crypto/sha256/sha256.go:137 +0x9d
main.(*MemTest).start(0xc23366cfa0)
/home/marco/git/go/src/ldb/memtest3.go:42 +0x1db
created by main.main
/home/marco/git/go/src/ldb/memtest3.go:78 +0x434

goroutine 142 [runnable]:
unicode/utf8.DecodeRuneInString(0x4baec1, 0x1, 0x4baec0, 0x2)
/home/marco/hg/go/src/pkg/unicode/utf8/utf8.go:229
fmt.(*pp).doPrintf(0xc2100e0000, 0x4baec0, 0x2, 0x20342df30, 0x1, ...)
/home/marco/hg/go/src/pkg/fmt/print.go:1159 +0xfab
fmt.Sprintf(0x4baec0, 0x2, 0x20342df30, 0x1, 0x1, ...)
/home/marco/hg/go/src/pkg/fmt/print.go:235 +0x8e
main.(*MemTest).start(0xc23366cf80)
/home/marco/git/go/src/ldb/memtest3.go:43 +0x2a6
created by main.main
/home/marco/git/go/src/ldb/memtest3.go:78 +0x434

goroutine 143 [runnable]:
crypto/sha256.(*digest).Sum(0xc2484b8280, 0x0, 0x0, 0x0, 0x0, ...)
/home/marco/hg/go/src/pkg/crypto/sha256/sha256.go:141 +0x205
main.(*MemTest).start(0xc23366cf60)
/home/marco/git/go/src/ldb/memtest3.go:42 +0x1db
created by main.main
/home/marco/git/go/src/ldb/memtest3.go:78 +0x434

goroutine 144 [running]:
goroutine running on other thread; stack unavailable
created by main.main
/home/marco/git/go/src/ldb/memtest3.go:78 +0x434

goroutine 146 [runnable]:
crypto/sha256.(*digest).Sum(0xc2484b3380, 0x0, 0x0, 0x0, 0x0, ...)
/home/marco/hg/go/src/pkg/crypto/sha256/sha256.go:141 +0x205
main.(*MemTest).start(0xc23366cf00)
/home/marco/git/go/src/ldb/memtest3.go:42 +0x1db
created by main.main
/home/marco/git/go/src/ldb/memtest3.go:78 +0x434

[mikey...@gmail.com]

I am seeing the same thing.  There is clearly a leak of some type going on.  The posted program really should only by taking around 16MB * 8 = 128MB per loop iteration (plus a little more for operation), but running this on Windows 7 using go 1.1.2, I'm seeing it creep upwards with each iteration.  After just 2 minutes it's up to over 2GB and slowly climbing.

[Kyle Lemons]

Have you run with the memory profiler to see where it attributes the memory?

[andrey mirtchovski]

i got it on a high and a low part of its cycle. attached. not sure
what the profiles are telling me yet (if anything), still reading the
code.

[Marco Peereboom]

On 08/28/13 13:58, Kyle Lemons wrote:
> Have you run with the memory profiler to see where it attributes the memory?

$ go tool pprof memtest3 /tmp/profile.14
Adjusting heap profiles for 1-in-524288 sampling rate
Welcome to pprof! For help, type 'help'.
(pprof) top
Total: 1904.1 MB
513.6 27.0% 27.0% 1902.6 99.9% main.(*MemTest).start
406.5 21.3% 48.3% 406.5 21.3% crypto/sha256.New
406.0 21.3% 69.6% 406.0 21.3% fmt.(*fmt).fmt_sbx
373.5 19.6% 89.3% 779.5 40.9% fmt.Sprintf
100.0 5.3% 94.5% 100.0 5.3% runtime.convT2E
99.5 5.2% 99.7% 99.5 5.2% crypto/sha256.(*digest).Sum
3.5 0.2% 99.9% 3.5 0.2% evacuate
0.5 0.0% 99.9% 0.5 0.0% runtime.allocm
0.5 0.0% 100.0% 0.5 0.0% runtime.malg
0.5 0.0% 100.0% 0.5 0.0% runtime/pprof.writeHeap

Attached the code that generated this profile and the actual profile file.

[andrey mirtchovski]

- you have a race in your program. you'll need to fix that first
before you continue. run with -race and you'll see it immediately.

- you generate an inordinate amount of garbage. the garbage
collector's standard procedure is to kick in when the previously
allocated memory is overshot by 100%. you can clearly see this if you
run with GODEBUG=gctrace=1 set. note that this version calls
runtime.GC() before outputting statistics:

http://play.golang.org/p/6zF7DyRQ6v

if you don't ask the GC to run at the end of the main loop garbage
will accumulate:

http://play.golang.org/p/z3rELs_RG-

- you can control how often the GC kicks in by setting GOGC=X for some
number X, the smaller the more responsive the GC will be to growth.
the number is the percentage of memory overcommitted from the previous
run:

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

- finally, when you run GC at the end of the loop you'll see the
memory footprint stabilize even without the GOGC tweak:

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

all this doesn't preclude the possibility of a leak in go maps, only
binds its magnitude somewhat for this case. i don't know about the
inner workings of hash and can't tell you if the growth/subsequent
settling down from the last link are expected behaviour. i also didn't
run the test long enough to see if the settling down would be
permanent :D

[Marco Peereboom]

On Wed, Aug 28, 2013 at 03:49:25PM -0600, andrey mirtchovski wrote:
> - you have a race in your program. you'll need to fix that first
> before you continue. run with -race and you'll see it immediately.

Fine. I attached the non racy one and it helps (of course!). The
original version of this code was single threaded; I just added the go
routines to run faster and misplaced a statement. Sorry about that.

> - you generate an inordinate amount of garbage. the garbage
> collector's standard procedure is to kick in when the previously
> allocated memory is overshot by 100%. you can clearly see this if you
> run with GODEBUG=gctrace=1 set. note that this version calls
> runtime.GC() before outputting statistics:

The test exacerbates what I am trying to illustrate. I didn't claim
that it was an awesome piece of code ;)

Point is that if you'd run a variant of this that does something like:
allocLargeMap()
doSomethingWithMap()
tossMap()
runtime.GC()

And at this point not all memory is freed. Fine sit on some of it,
however this memory is *never* reused.

> http://play.golang.org/p/6zF7DyRQ6v
>
> if you don't ask the GC to run at the end of the main loop garbage
> will accumulate:
>
> http://play.golang.org/p/z3rELs_RG-

I'll argue that a go program should never have to call runtime.GC().

> - you can control how often the GC kicks in by setting GOGC=X for some
> number X, the smaller the more responsive the GC will be to growth.
> the number is the percentage of memory overcommitted from the previous
> run:
>
> http://play.golang.org/p/liy6LMvTdU
>
> - finally, when you run GC at the end of the loop you'll see the
> memory footprint stabilize even without the GOGC tweak:

Well, it doesn't over longer periods of time :)

Also if you'd rig the program to run like 10k loops and then call
runtime.GC() you'll see that a bunch of memory is not recovered. If
you'd restart the tool memory would go up again. I have a version of
the code that does that btw.

> http://play.golang.org/p/tRB80q8Fxu
>
> all this doesn't preclude the possibility of a leak in go maps, only
> binds its magnitude somewhat for this case. i don't know about the
> inner workings of hash and can't tell you if the growth/subsequent
> settling down from the last link are expected behaviour. i also didn't
> run the test long enough to see if the settling down would be
> permanent :D

Like I said in my original email, 5 stages of grief ;)

The original program does what I described in the first paragraph. And
after a few days it uses 2.7G now if I restart the app it uses 24M
(which is what to expect). We have ruled out the database code and the
networking code. The only thing left over is the map we use to populate
the database and this test tool is an extreme version of it.

Here is an example run:
$ ./memtest3
Start Of Day: 175208
Usage: 275328072 delta 275152864 objects 3621224
this being the first print indicates how much mem each run is going to
use. 2.7G give or take.

Usage: 377653752 delta 102325680 objects 6544963
Next run we hit 3.7G

Usage: 386970024 delta 9316272 objects 6822665
Now we hit 3.7G

Usage: 659434096 delta 272464072 objects 11781987
And now we are at about >200% of the original run.

Usage: 374859208 delta -284574888 objects 6512875
Looky, we give back 2g!

Usage: 355925144 delta -18934064 objects 5960409
And another 200m!

Usage: 846617384 delta 490692240 objects 15598226
Oops, now we go to 8.4G (nearly the breaking point)

This goes on for a bit and bombs.

[Kyle Lemons]

Juuust out of curiosity, are you running in 32-bit?

[RickyS]

Usage: 377653752 delta 102325680 objects 6544963
Next run we hit 3.7G

377653752 is 377,653,752 is just over a third of a billion.

[RickyS]

That's a billion in the short scale, or American usage.  Brits and others have a different meaning for billion.   I mean 10 to the 9th.

[Marco Peereboom]

Happens on both. 32 bit ulimit is just smaller. Making ulimit bigger
just makes the test run longer. I'll do another test program to
illustrate the point.

[andrey mirtchovski]

> I'll argue that a go program should never have to call runtime.GC().

but you really _are_ generating a lot of garbage. the system can't
cope without help from you -- it's designed for the common case, where
garbage generation is somewhat bound.

i ran your code unmodified except for the added http/pprof on a 4-core
32-gig linux machine to give the memory subsystem of the runtime a
fighting chance against the "garbage" generated. the results are
summarized in the link below. i would suspect the peaks are what gets
you, me and everybody else on a more memory constraint machine.

http://goo.gl/teqCai

in fact, your code is still running:

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
23721 aam 20 0 2590m 933m 2776 S 286.6 2.9 88:28.63 t

the memory consumption is well settled. yes, there are peaks in the
graphs. those may require looking at, but there's no leak. it even
returned memory to the system (used to be 1.9GB resident). attached
are two pprof graphs: before it returned memory to the system, and
after. i would focus on those being slightly wrong rather than the map
code.

cheers!

[Marco Peereboom]

Unfortunately, you are missing my point :(

The crash is just a natural side effect of the memory leak. It isn't
the actual issue. Attached is a program that waits for the user to hit
return before it continues. Look at the "Usage at rest" lines and also
note that this is printed AFTER a runtime.GC().

Start Of Day: 185160 objects 118
Usage: 786835312 delta 786650152 objects 14112227
Usage at rest: 1113360 objects 308

Usage: 790922984 delta 4087672 objects 13636714
Usage: 790312824 delta -610160 objects 13958679
Usage: 697487216 delta -92825608 objects 10605430
Usage: 890655496 delta 193168280 objects 12289048
Usage: 714844208 delta -175811288 objects 12010727
Usage: 717205472 delta 2361264 objects 11909176
Usage: 1678406240 delta 961200768 objects 31186117
Usage: 1970253016 delta 291846776 objects 32683431
Usage: 2616780728 delta 646527712 objects 43281100
Usage: 3134761912 delta 517981184 objects 49612820
Usage at rest: 1452008 objects 599

Usage: 746243136 delta -2388518776 objects 12913283
Usage: 1184210144 delta 437967008 objects 16809964
Usage: 2132610408 delta 948400264 objects 36646008
Usage: 2897411064 delta 764800656 objects 50567052
Usage: 3319509992 delta 422098928 objects 54574362
Usage: 3486200104 delta 166690112 objects 50836804
Usage: 5175152464 delta 1688952360 objects 91205507
Usage: 4810270136 delta -364882328 objects 71871319
Usage: 6499204864 delta 1688934728 objects 112239958
Usage: 5548645640 delta -950559224 objects 75876818
Usage at rest: 1785096 objects 891

Usage: 851031768 delta -4697613872 objects 15890015
Usage: 746945624 delta -104086144 objects 12564012
Usage: 1691865176 delta 944919552 objects 31142016
Usage: 1931194536 delta 239329360 objects 29372840
Usage: 2598911808 delta 667717272 objects 39788508
Usage: 2887946552 delta 289034744 objects 39081154
Usage: 4576953888 delta 1689007336 objects 79449990
Usage: 4428265832 delta -148688056 objects 66195008
Usage: 6117251568 delta 1688985736 objects 106563778
Usage: 5477042328 delta -640209240 objects 79000372
Usage at rest: 2129800 objects 1181

etc

[andrey mirtchovski]

> Unfortunately, you are missing my point :(

i must be.

Usage at rest: 617504 objects 203
Usage at rest: 764760 objects 331
Usage at rest: 930840 objects 474
Usage at rest: 1109776 objects 654
Usage at rest: 1325896 objects 773
Usage at rest: 1485568 objects 934
Usage at rest: 1538984 objects 958
Usage at rest: 1538984 objects 958
Usage at rest: 1539528 objects 961
Usage at rest: 1544584 objects 967
Usage at rest: 1543848 objects 963
Usage at rest: 1543528 objects 961
Usage at rest: 1543776 objects 983
Usage at rest: 1565024 objects 1002
Usage at rest: 1564872 objects 981
Usage at rest: 1564296 objects 978

[andrey mirtchovski]

i removed the Scanf and ran your code for an hour with no other
modifications. i don't know what else can convince you that there's no
leak:

http://goo.gl/Id6KxK

the initial growth which you mistake for a leak is probably the
internal implementation of the hashmap growing to accommodate the
large, fairly random key space. i don't know enough about it, but i
suspect the insides of the hashmap are not managed by the GC in the
same manner as everything else.

[Marco Peereboom]

Well the versions I am running exhibit a leak. Can you tell me what
version of go you used and what OS? I'll then try to reproduce.

[andrey mirtchovski]

my first email was done on:

go version devel +8bf13ae02c8e Mon Aug 19 16:22:33 2013 +1000 darwin/amd64

the last two emails are from:
go version devel +84a92114983d Thu Aug 29 16:48:44 2013 +0200 linux/amd64

i have been running with different key sizes for the hash. i tried
[ds[:32]] and [ds+ds] in your code, 32 and 128 bytes respectively, for
the past hour trying to see if the code settles at a different
footprint at rest. there are very small differences -- it still hovers
around 1000 objects for both after the initial blowup, but 128-bytes
rest at 990 and 32-bytes rest at 1040. is the difference due to
collisions? i can only speculate.

[Dan Kortschak]

worked fine for me on amd6 linux.

[Carlos Castillo]

Does the behaviour happen if GOMAXPROCS=1, if so it may be a case of https://code.google.com/p/go/issues/detail?id=6119

[Carlos Castillo]

I meant that if the situation occurs when GOMAXPROCS > 1, than it's possibly related to issue 6119.

[andrey mirtchovski]

nice, thanks for the reference. at GOMAXPROCS=1:

Usage at rest: 243520 objects 134
Usage at rest: 243792 objects 136
Usage at rest: 243792 objects 136
Usage at rest: 243792 objects 136
Usage at rest: 243792 objects 136
Usage at rest: 243792 objects 136
Usage at rest: 243792 objects 136
Usage at rest: 243792 objects 136
Usage at rest: 243792 objects 136
Usage at rest: 243792 objects 136
Usage at rest: 243792 objects 136
Usage at rest: 243792 objects 136
Usage at rest: 243792 objects 136
Usage at rest: 243792 objects 136
Usage at rest: 243792 objects 136
Usage at rest: 243792 objects 136
Usage at rest: 243792 objects 136
Usage at rest: 243792 objects 136
Usage at rest: 243792 objects 136
Usage at rest: 243792 objects 136
Usage at rest: 243792 objects 136
Usage at rest: 243792 objects 136
Usage at rest: 243792 objects 136
Usage at rest: 243792 objects 136
Usage at rest: 243792 objects 136
Usage at rest: 243792 objects 136

[Marco Peereboom]

So have you arrived at stage 5 (acceptance)? ;)

And I can confirm that this is exactly what I see as well.

[andrey mirtchovski]

> So have you arrived at stage 5 (acceptance)? ;)

i would consider this a leak if it exhibited unbounded growth, so no.
but if it helps you sleep at night...

[Marco Peereboom]

That is unfortunate because I can obviously modify the code to never
reuse the same map key and therefore grow it forever. It is also
unfortunate that it continues to grow on other OS'. And lastly I find
it unfortunate that if a program is eating >2.5GB it will never reuse
that people think it is not a leak. I guess this is where I do the
"back in my day we had to fit code in a couple of KB, up the hill,
twice" routine.

Now if we can get it fixed I guess everyone wins.

[Kyle Lemons]

Is there an issue tracking this yet?

[Carlos Castillo]

Since it's map related, and doesn't happen when GOMAXPROCS=1, it might to be related to issue 6119.

--
Carlos Castillo

[andrey mirtchovski]

> Since it's map related, and doesn't happen when GOMAXPROCS=1, it might to be
> related to issue 6119.

a long run of the test code from 6119, available here:

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

shows a different behaviour than the one this thread discusses, but
the underlying cause may be the same. 6119's test balloons to 30+GB
memory before collecting everything down to the original 400mb it
started with, then repeats. i've plotted its behaviour on the same
sheet as the other one, after running it for more than an hour:

http://goo.gl/tVp7pz

the only modification apart from printing the memory stats after a GC
is that i am using random int keys rather than the [1,N) used by the
original.

[andrey mirtchovski]

ps: i'd like to see the gc pause time for this baby: 35,999,974,872
-> 398,607,832 (36GB vs 398MB) :)

[andrey mirtchovski]

6119 was fixed by:

https://code.google.com/p/go/source/detail?r=f605488ef701

you should re-run your tests and create a new issue if you are still
experiencing troubles.

[Piotr Narewski]

Sorry guys, but just to be sure: is there a map related memleak introduced in 1.1.2, on Windows?

Because I have also observed my app eating up the mem, like never before, after I had upgraded from 1.1.1 to 1.1.2.

And that would explain it...

[Dave Cheney]

The set of changes in 1.1.2 were very small (from memory 11 or 12), if there was a regression it was obviously not intentional. 

As there have been two (possibly related, possibly unrelated) issues relating to memory usage and hash maps can you please raise an issue with a working code sample that reproduces the issue. 

Cheers

Dave

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

[andrey mirtchovski]

> As there have been two (possibly related, possibly unrelated) issues

After the fix for 6119 went in, I re-ran memtest4.go from above with
the following modifications: removed Scanf and changed the hash input
to be an ever-increasing integer, which will, hopefully, only offer
unique keys. i ran for 1 billion map inserts and only looked at the
memory footprint "at rest" (after GC). the results are summarized on
sheet 2 of this spreadhsheet and they mimic closely the results before
6119 was fixed (available on the first sheet):

goo.gl/Id6KxK

Since OP and I disagree on what constitutes a leak, I will leave it to
them to decide if the issue is fixed. the ballooning of memory that
caused the OOM killer to kick in on LInux appears to be gone on both
OSX and Linux.

[Piotr Narewski]

OK - thanks for explaining, Dave.

I wish I could raise an issue with a working code sample, but honestly I am not even sure if there is a mem leak.

My app is sort of a complex p2p client and it takes literally days to observe how it consumes all the 12GB of my system's mem.

It normally uses like 4GB in peeks, but I don't remember ever running out of mem before - it started happening somehow recently.

I was suspecting some changes in the p2p net itself, but then I found this topic and realized that I upgraded to 1.1.2 about the time when it started to happen.

Now I have downgraded to 1.1.1 and will see if it helped anyhow - but that will take days, for a conclusive measure.

Cheers,

Piotr

[Dave Cheney]

The 1.1.2 released contained only minimal changes, 

http://code.google.com/p/go/source/list?name=release-branch.go1.1

Is the code of your application available online?

[Piotr Narewski]

Yes, it is available online - you can find it here: https://github.com/piotrnar/gocoin

The executable I am talking about builds from the "client/" folder.

But as I said, I need some more time to make sure that it does not happen with 1.1.1 as well.

Cheers

[Dave Cheney]

Your code plays pretty fast and loose with error handling in file and socket io. 

I can also see some concurrent map access that is not properly mutexed. 

Please try building a version of your client with -race and see if it complains about data races. 

Like other languages, data races on map access can easily corrupt internal map data structures, then all bets are off. 

Dave

[Piotr Narewski]

OK - I will.

Thanks for advise!

[Marco Peereboom]

That fixed it for me.

Thanks for pointing it out and thanks everyone who looked and worked on
this.