Go Garbage Collector Performance Stats

[Matt Davis]

I am gathering various memory usage statistics from a particular Go
benchmark. At the end of the gccgo-4.6.3 compiled program, which is
deterministic, I will occasionally find different NumGC TotalAlloc and
Mallocs values from the 'MemStats' object. I am only running single
threaded code, therefore not explicitly spawning any go threads. Any
idea why the NumGC and various other data are not always the same
given the same input?

-Matt

[Devon H. O'Dell]

2012/5/3 Matt Davis <mattd...@gmail.com>:

I would imagine it possible that the areas where your single threaded
code yields for the GC to be able to collect can differ between
instantiations of your binary.

--dho

> -Matt

[Ian Lance Taylor]

In gccgo 4.6 different goroutines run on different threads, and the
order in which they execute is unpredictable. You say that you don't
spawn any Go threads, by which I assume you mean that you don't use the
go statement, but many of the standard packages do use the go statement.
Perhaps that is what is happening here.

Ian

[Matt Davis]

Thanks for the reply!
That is quite possible. However, the difference between runs can be
as significant as having NumGC report: 144932 or 80973. That's a
pretty big difference. It is almost consistently 144932, but rarely I
will see a value like 80973. So, for my next area of investigation, I
decided to use gdb and set a break point on pthread_create; nothing
tripped. I also paused the program in gdb and did a 'info threads'
and still, just a single thread.

-Matt

[Rémy Oudompheng]

2012/5/3 Matt Davis <mattd...@gmail.com>:

What does the benchmark look like?

Rémy.

[⚛]

Your program does 144932 garbage collections per run?

[Matt Davis]

On Thu, May 03, 2012 at 08:39:51AM +0200, R�ｿｽmy Oudompheng wrote:
> 2012/5/3 Matt Davis <mattd...@gmail.com>:
> > On Thu, May 3, 2012 at 4:22 PM, Ian Lance Taylor <ia...@google.com> wrote:
> >> Matt Davis <mattd...@gmail.com> writes:
> >>
> >>> I am gathering various memory usage statistics from a particular Go

> >>> benchmark. �ｿｽAt the end of the gccgo-4.6.3 compiled program, which is

> >>> deterministic, I will occasionally find different NumGC TotalAlloc and

> >>> Mallocs values from the 'MemStats' object. �ｿｽI am only running single
> >>> threaded code, therefore not explicitly spawning any go threads. �ｿｽAny

> >>> idea why the NumGC and various other data are not always the same
> >>> given the same input?
> >>
> >> In gccgo 4.6 different goroutines run on different threads, and the

> >> order in which they execute is unpredictable. �ｿｽYou say that you don't

> >> spawn any Go threads, by which I assume you mean that you don't use the
> >> go statement, but many of the standard packages do use the go statement.
> >> Perhaps that is what is happening here.
> >
> > Thanks for the reply!

> > That is quite possible. �ｿｽHowever, the difference between runs can be
> > as significant as having NumGC report: �ｿｽ144932 or 80973. �ｿｽThat's a
> > pretty big difference. �ｿｽIt is almost consistently 144932, but rarely I
> > will see a value like 80973. �ｿｽSo, for my next area of investigation, I

> > decided to use gdb and set a break point on pthread_create; nothing

> > tripped. �ｿｽI also paused the program in gdb and did a 'info threads'

> > and still, just a single thread.
>
> What does the benchmark look like?

I was testing performance using this application:
https://github.com/dchest/passwordhash

I purposely removed any 'go' statements, but there are none in this case aside
from, as Ian pointed out, those which might be in the libraries called (e.g. the
crypto libraries). I tossed in a:
>> println("NumGC: ", runtime.MemStats.NumGC)
at the end of the main() block, as well as a few other MemStat fields. I loop
over the provided test numerous times in a single "run." I am wondering if the
occasional difference in NumGC values has something to do with multiple CPUs
(quad-core i7) and possibly the stress of running the test is causing the CPU to
offload work to other processors, and caches.

-Matt

[⚛]

You can print out the complete MemStats via fmt.Printf("%#v", runtime.MemStats) for the two cases where the MemStats differ and send the printed information to golang-nuts.

[Ian Lance Taylor]

Do you really mean that NumGC changes that much? That seems difficult
to understand. I don't have any explanation.

Have you tried gccgo 4.7.0?

Ian

[Dmitry Chestnykh]

On Thursday, May 3, 2012 9:26:27 AM UTC+2, ⚛ wrote:

Your program does 144932 garbage collections per run?

The PDKDF2 package I used in passwordhash was written before Go 1. In those dark times, hash.Hash interface had Sum() returning a byte array. This was changed in Go 1, Sum() now accepts an optional byte slice, so that it won't allocate a byte slice if none is needed.  When I updated the package, I simply told it to do what it did before (passed nil to Sum), to it still allocates a byte slice per PBKDF2 iteration. Passwordhash uses 5000 iterations by default, so you'll get at least 5000 allocations of 32-byte array. Which is kind of nice for GC benchmarking :-)

I'll probably switch to go.crypto's implementation of PBKDF2 for this package. But now that we have bcrypt in go.crypto, and I've recently implemented scrypt (https://github.com/dchest/scrypt), I think it can be deprecated.