help understand gctrace=1

[loo...@gmail.com]

Hi all

We have an application that crashes because of memory leak.

I collected profile for memory but it shows nothing valuable (average usage of mem is less than 1GB).
than I run gctrace=1 and it shows interesting picture like:

gc 70 @1449.352s 0%: 2.0+110+5.3+1.4+5.5 ms clock, 8.0+110+0+1509/3.0/0.008+22 ms cpu, 682->701->386 MB, 699 MB goal, 16 P

gc 71 @1449.626s 0%: 2.1+97+0.054+0.35+5.1 ms clock, 8.7+97+0+1136/0.004/1.7+20 ms cpu, 716->732->307 MB, 734 MB goal, 16 P

scvg9: 6 MB released

scvg9: inuse: 629, idle: 770, sys: 1399, released: 11, consumed: 1387 (MB)

....

gc 97 @2948.627s 0%: 1.7+15+1.2+161+5.6 ms clock, 8.9+15+0+639/645/0.60+28 ms cpu, 540->571->391 MB, 576 MB goal, 16 P

gc 98 @2956.908s 0%: 2.2+31+3.5+87+16 ms clock, 36+31+0+2.6/330/1450+267 ms cpu, 692->693->233 MB, 720 MB goal, 16 P

scvg19: 0 MB released

scvg19: inuse: 2950, idle: 2000, sys: 4951, released: 233, consumed: 4718 (MB)

...

gc 136 @3430.456s 0%: 211+173+17+5.5+19 ms clock, 1477+173+0+1405/0.83/0.98+139 ms cpu, 572->584->387 MB, 587 MB goal, 16 P

gc 137 @3436.193s 0%: 2.3+19+3.5+91+344 ms clock, 37+19+0+1.3/331/1250+5507 ms cpu, 733->733->236 MB, 752 MB goal, 16 P

scvg22: 75 MB released

scvg22: inuse: 12912, idle: 6247, sys: 19159, released: 76, consumed: 19083 (MB)

the first part is looks ok - gc's and scvg's  values some how related.

But then scvg occupies more and more memory, almost 20Gb, but GC consumes as usual .

Please help to figure out what this behavior could mean? 

Any help is appreciated 

P.S. : using go1.5.1, 64bit linux.

[Dave Cheney]

At a guess I'd say the heap is highly fragmented, your leaking goroutines and or leaking threads.

Can you hit your app with SIGQUIT and paste the entire stack trace somewhere?

What does your app do, is the source online?

[loo...@gmail.com]

Hi Dave

Our application is a kind of web server. Unfortunately I'm not eligible to share source code. But I can say app works with mongoDB and Redis. And we made stress test  that discovered memleak problem.

I'll be able to share stack trace on Monday. however we're using net/http/pprof and I didn't observe goroutine/thread leak.

But I can note one thing. Before the first crash application could work for an hour under stress load. After the crash it is restarted, and if we keep loading it will crash in couple of minutes 

суббота, 5 декабря 2015 г., 0:57:58 UTC+3 пользователь Dave Cheney написал:

[Dave Cheney]

I'd your happy that http/pprof doesn't indicate you're leaking goroutines then don't worry about that area of investigation.

Are you able to share the full output you receive when your application crashes?

[loo...@gmail.com]

application crashes without output.

but in /var/log/message we have a record that OS killed app, the log is here http://pastebin.com/P3iczBbS

it looks like OS kills mongod and our process at the same time.

суббота, 5 декабря 2015 г., 12:36:35 UTC+3 пользователь Dave Cheney написал:

[Dave Cheney]

Ok, that's Linux's oom killer. We need to see the panic message from the go application to find out what is going on, please hit it with SIGQUIT at the appropriate point in your load test and paste the full output.

[loo...@gmail.com]

ok, will able to do it on Monday

суббота, 5 декабря 2015 г., 13:04:49 UTC+3 пользователь Dave Cheney написал:

[loo...@gmail.com]

Hi Dave

there is a SIGQUIT and gctrace=1 output https://drive.google.com/file/d/0B_8MoXam1KgsQ0RyQ2Y5WU1lNHc/view?usp=sharing

Also I have a thought that root of memory consumption is the growing stack , but no idea how to find stack size for goroutine, any advice would be appreciated 

суббота, 5 декабря 2015 г., 13:08:39 UTC+3 пользователь loo...@gmail.com написал:

[Dave Cheney]

Does your code use cgo ?

Can you try adding ,schedtrace=5000 and running the test again, maybe your program is leaking OS threads.

[loo...@gmail.com]

yes, we linked some cgo libs, but the test shouldn't actively use cgo functions.

here is new dump with schedtrace=5000 https://drive.google.com/file/d/0B_8MoXam1KgscnUySmRLMnhvRFU/view?usp=sharing

And seems I have localized the problem, take a look on this script http://play.golang.org/p/DMOacFcFK3

it consumes all memory quickly, however it doesn't crush until another consumer starts 

понедельник, 7 декабря 2015 г., 15:08:54 UTC+3 пользователь Dave Cheney написал:

[Dave Cheney]

Dmitry, Keith, any ideas what is going on here ?

[loo...@gmail.com]

I just have tested script that I shared above with different go version :

go1.4.1 - consumes 3 mb, stabel

go 1.5.1 -consumes  all memory  

go 1.5.2 -consumes  all memory  

понедельник, 7 декабря 2015 г., 16:53:26 UTC+3 пользователь Dave Cheney написал:

[Dmitry Vyukov]

There were several issues with concurrent GC missing the goal. It
seems to be happening on this program with 1.5 to some degree
(however, I can't reproduce as bad behavior as you see). It seems to
be working fine with tip. Can you test with tip? I don't think it is
fixable in 1.5 at this point.

[Dave Cheney]

Thanks Dmitry. Could you explain for my benefit the difference between inuse memory and system memory that the scavenger debuf line is reporting?

[loo...@gmail.com]

sorry don't get this,

what you mean "test with tip" ?

понедельник, 7 декабря 2015 г., 17:32:20 UTC+3 пользователь Dmitry Vyukov написал:

[Austin Clements]

We've made the garbage collector much more robust to scheduling and heap overshoot issues since Go 1.5 was released, but we haven't yet made a release that includes these fixes (the next planned release is Feb 1). "Test with tip" means to build Go from source after checking out the master branch from Git, such as in the directions here: https://golang.org/doc/install/source.

[Dmitry Vyukov]

These numbers is the same as what you can see in runtime.MemStats.
"Inuse" is HeapInuse, or sum of sizes of all allocated objects; "sys"
is HeapSys, or total memory requested from OS for heap (including
empty spans).
However, numbers reported by scavenger can be in inconsistent state;
there is that comment:
// TODO(dvyukov): these stats are incorrect as we don't subtract stack
usage from heap.
// But we can't call ReadMemStats on g0 holding locks.
I don't know whether it is still correct or not.

[Austin Clements]

These numbers do still include the stack usage. (Perhaps, rather than thinking of these as inconsistent, just think of the scavenger trace as heap+stack.)

[loo...@gmail.com]

I have to admit that I made hasty conclusion about go1.5.2

I keep testing , and it seems like although script consumes a lot of memory but no leaks. 

go1.5.2 consumes 600mb.

go1.5.1(with gcstoptheworld=1) consumes 160mb.

go1.5.1 has mem leak

понедельник, 7 декабря 2015 г., 18:12:38 UTC+3 пользователь Austin Clements написал:

[Austin Clements]

Thanks. I was able to reproduce slow but steady RSS growth with your latest test program on Go master. I've turned this in to a GitHub issue: https://github.com/golang/go/issues/13552

On Wed, Dec 9, 2015 at 9:18 AM, Ilia Kandrashou <loo...@gmail.com> wrote:

just made some additional testing with this script http://play.golang.org/p/zMHtw0-8Ph

here is the memory consumption results:

linux 64bit virtual box:

go1.4.2 - 2mB, stable

go1.5.1 - quickly consumes all mem and crashes

go1.5.2 - little bet slowly consumes all mem and crashes

master brunch ( go version devel +aa487e6 Mon Dec 7 22:06:03 2015 +0000 linux/amd64 ) - starts with 20 mB, after an hour test it was 40 mB, not sure if it will consume all mem in long term.

Windows 64bit:

go1.4.2 - 4mB, stable
go1.5.1 - quickly consumes all mem, but didn't crashes

go1.5.1 - looks stable with 10 mB.

I'm confused a little bit, hope go1.6 will solve this issue.

for now It looks like we have to release to production with go1.4

вторник, 8 декабря 2015 г., 11:02:35 UTC+3 пользователь Ilia Kandrashou написал: