code review 136310044: runtime: output number of goroutines in GC trace

runtime: output number of goroutines in GC trace
Example output:
gc26(1): 1+0+1038+0 us, 0 -> 1 MB, 19074 (88777-69703) objects, 5 gs, 184/0/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields
It's useful to understand long scan times,
because goroutine traceback is slow.

[dvyukov, 2014-09-17 00:58:06]

Hello golang-codereviews@googlegroups.com (cc: khr@golang.org, rsc@golang.org),

I'd like you to review this change to
https://dvyukov%40google.com@code.google.com/p/go/

[dvyukov, 2014-09-17 01:00:19]

It came up on golang-nuts list:

>> out), I get gc pauses as -
>> gc30(8): 10+23+3360+160 us, 22 -> 44 MB, 240321 (3126041-2885720) objects,
>> 6585/4441/0 sweeps,
>
> 3.36ms to sweep a small heap like this sounds wrong. Dmitry, is my
> estimation off?

Difficult to say w/o knowing number of goroutines.

[rsc, 2014-09-17 13:49:17]

Please change gs to goroutines.

On Tuesday, September 16, 2014, <dvyukov@google.com> wrote:

> Reviewers: golang-codereviews,
>
> Message:
> Hello golang-codereviews@googlegroups.com (cc: khr@golang.org,
> rsc@golang.org),
>
> I'd like you to review this change to
> https://dvyukov%40google.com@code.google.com/p/go/
>
>
> Description:
> runtime: output number of goroutines in GC trace
> Example output:
> gc26(1): 1+0+1038+0 us, 0 -> 1 MB, 19074 (88777-69703) objects, 5 gs,
> 184/0/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields
> It's useful to understand long scan times,
> because goroutine traceback is slow.
>
> Please review this at https://codereview.appspot.com/136310044/
>
> Affected files (+2, -0 lines):
>   M src/runtime/mgc0.c
>
>
> Index: src/runtime/mgc0.c
> ===================================================================
> --- a/src/runtime/mgc0.c
> +++ b/src/runtime/mgc0.c
> @@ -1400,11 +1400,13 @@
>                 stats.nsleep += work.markfor->nsleep;
>
>                 runtime·printf("gc%d(%d): %D+%D+%D+%D us, %D -> %D MB, %D
> (%D-%D) objects,"
> +                               " %d gs,"
>                                 " %d/%d/%d sweeps,"
>                                 " %D(%D) handoff, %D(%D) steal, %D/%D/%D
> yields\n",
>                         mstats.numgc, work.nproc, (t1-t0)/1000,
> (t2-t1)/1000, (t3-t2)/1000, (t4-t3)/1000,
>                         heap0>>20, heap1>>20, obj,
>                         mstats.nmalloc, mstats.nfree,
> +                       runtime·gcount(),
>                         work.nspan, runtime·sweep.nbgsweep,
> runtime·sweep.npausesweep,
>                         stats.nhandoff, stats.nhandoffcnt,
>                         work.markfor->nsteal, work.markfor->nstealcnt,
>
>
>

[dvyukov, 2014-09-17 23:11:57]

On 2014/09/17 13:49:17, rsc wrote:
> Please change gs to goroutines.
> 
> On Tuesday, September 16, 2014, <mailto:dvyukov@google.com> wrote:
> 
> > Reviewers: golang-codereviews,
> >
> > Message:
> > Hello mailto:golang-codereviews@googlegroups.com (cc: mailto:khr@golang.org,
> > mailto:rsc@golang.org),
> >
> > I'd like you to review this change to
> > https://dvyukov%40google.com@code.google.com/p/go/
> >
> >
> > Description:
> > runtime: output number of goroutines in GC trace
> > Example output:
> > gc26(1): 1+0+1038+0 us, 0 -> 1 MB, 19074 (88777-69703) objects, 5 gs,
> > 184/0/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields
> > It's useful to understand long scan times,
> > because goroutine traceback is slow.
> >
> > Please review this at https://codereview.appspot.com/136310044/
> >
> > Affected files (+2, -0 lines):
> >   M src/runtime/mgc0.c
> >
> >
> > Index: src/runtime/mgc0.c
> > ===================================================================
> > --- a/src/runtime/mgc0.c
> > +++ b/src/runtime/mgc0.c
> > @@ -1400,11 +1400,13 @@
> >                 stats.nsleep += work.markfor->nsleep;
> >
> >                 runtime·printf("gc%d(%d): %D+%D+%D+%D us, %D -> %D MB, %D
> > (%D-%D) objects,"
> > +                               " %d gs,"
> >                                 " %d/%d/%d sweeps,"
> >                                 " %D(%D) handoff, %D(%D) steal, %D/%D/%D
> > yields\n",
> >                         mstats.numgc, work.nproc, (t1-t0)/1000,
> > (t2-t1)/1000, (t3-t2)/1000, (t4-t3)/1000,
> >                         heap0>>20, heap1>>20, obj,
> >                         mstats.nmalloc, mstats.nfree,
> > +                       runtime·gcount(),
> >                         work.nspan, runtime·sweep.nbgsweep,
> > runtime·sweep.npausesweep,
> >                         stats.nhandoff, stats.nhandoffcnt,
> >                         work.markfor->nsteal, work.markfor->nstealcnt,
> >
> >
> >

done
ptal

[khr, 2014-09-18 03:30:30]

LGTM.

[dvyukov, 2014-09-18 03:38:10]

*** Submitted as https://code.google.com/p/go/source/detail?r=6aa1064ad564 ***

runtime: output number of goroutines in GC trace
Example output:
gc26(1): 1+0+1038+0 us, 0 -> 1 MB, 19074 (88777-69703) objects, 5 gs, 184/0/0
sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields
It's useful to understand long scan times,
because goroutine traceback is slow.

LGTM=khr
R=golang-codereviews, khr
CC=golang-codereviews, rsc
https://codereview.appspot.com/136310044