code review 7182043: runtime: account stop-the-world time in the "other" GOG...

runtime: account stop-the-world time in the "other" GOGCTRACE section
Currently it's summed to mark phase.
The change makes it easier to diagnose long stop-the-world phases.

[dvyukov, 2013-01-21 16:17:01]

Hello golang-dev@googlegroups.com,

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

[bradfitz, 2013-01-21 16:47:05]

LGTM
 On Jan 21, 2013 8:17 AM, <dvyukov@google.com> wrote:

> Reviewers: golang-dev_googlegroups.com,
>
> Message:
> Hello golang-dev@googlegroups.com,
>
> I'd like you to review this change to
>
https://dvyukov%40google.com@**code.google.com/p/go/<http://40google.com@code...
>
>
> Description:
> runtime: account stop-the-world time in the "other" GOGCTRACE section
> Currently it's summed to sweep phase.
> The change makes it easier to diagnose long stop-the-world phases.
>
> Please review this at
https://codereview.appspot.**com/7182043/<https://codereview.appspot.com/7182...
>
> Affected files:
>   M src/pkg/runtime/mgc0.c
>
>
> Index: src/pkg/runtime/mgc0.c
> ==============================**==============================**=======
> --- a/src/pkg/runtime/mgc0.c
> +++ b/src/pkg/runtime/mgc0.c
> @@ -1474,7 +1474,7 @@
>  static void
>  gc(struct gc_args *args)
>  {
> -       int64 t0, t1, t2, t3;
> +       int64 t0, t1, t2, t3, t4;
>         uint64 heap0, heap1, obj0, obj1;
>         GCStats stats;
>         M *mp;
> @@ -1528,6 +1528,8 @@
>                 runtime·helpgc(work.nproc);
>         }
>
> +       t1 = runtime·nanotime();
> +
>         runtime·parfordo(work.markfor)**;
>         scanblock(nil, nil, 0, true);
>
> @@ -1536,10 +1538,10 @@
>                         debug_scanblock(work.roots[i].**p,
> work.roots[i].n);
>                 runtime·atomicstore(&work.**debugmarkdone, 1);
>         }
> -       t1 = runtime·nanotime();
> +       t2 = runtime·nanotime();
>
>         runtime·parfordo(work.**sweepfor);
> -       t2 = runtime·nanotime();
> +       t3 = runtime·nanotime();
>
>         stealcache();
>         cachestats(&stats);
> @@ -1569,18 +1571,18 @@
>         heap1 = mstats.heap_alloc;
>         obj1 = mstats.nmalloc - mstats.nfree;
>
> -       t3 = runtime·nanotime();
> -       mstats.last_gc = t3;
> -       mstats.pause_ns[mstats.numgc%**nelem(mstats.pause_ns)] = t3 - t0;
> -       mstats.pause_total_ns += t3 - t0;
> +       t4 = runtime·nanotime();
> +       mstats.last_gc = t4;
> +       mstats.pause_ns[mstats.numgc%**nelem(mstats.pause_ns)] = t4 - t0;
> +       mstats.pause_total_ns += t4 - t0;
>         mstats.numgc++;
>         if(mstats.debuggc)
> -               runtime·printf("pause %D\n", t3-t0);
> +               runtime·printf("pause %D\n", t4-t0);
>
>         if(gctrace) {
>                 runtime·printf("gc%d(%d): %D+%D+%D ms, %D -> %D MB %D ->
> %D (%D-%D) objects,"
>                                 " %D(%D) handoff, %D(%D) steal, %D/%D/%D
> yields\n",
> -                       mstats.numgc, work.nproc, (t1-t0)/1000000,
> (t2-t1)/1000000, (t3-t2)/1000000,
> +                       mstats.numgc, work.nproc, (t2-t1)/1000000,
> (t3-t2)/1000000, (t1-t0+t4-t3)/1000000,
>                         heap0>>20, heap1>>20, obj0, obj1,
>                         mstats.nmalloc, mstats.nfree,
>                         stats.nhandoff, stats.nhandoffcnt,
>
>
>

[dave_cheney.net, 2013-01-21 20:08:19]

Thanks Dmitry, this will show some useful data. Consider the following

odessa:~ dfc$ GOGCTRACE=1 go list
gc1(1): 34+0+0 ms, 0 -> 0 MB 11 -> 13 (14-1) objects, 0(0) handoff,
0(0) steal, 0/0/0 yields
gc2(1): 20+0+0 ms, 1 -> 1 MB 4879 -> 2094 (4968-2874) objects, 0(0)
handoff, 0(0) steal, 0/0/0 yields
_/Users/dfc
odessa:~ dfc$ GOGCTRACE=1 go list
gc1(1): 0+0+0 ms, 0 -> 0 MB 11 -> 13 (14-1) objects, 0(0) handoff,
0(0) steal, 0/0/0 yields
gc2(1): 0+0+0 ms, 1 -> 1 MB 4971 -> 2059 (5062-3003) objects, 0(0)
handoff, 0(0) steal, 0/0/0 yields
_/Users/dfc

Why does the same program, run twice, report different t0's, yet have
almost the same memory footprint ? Something is extending the t0's,
and I think this was syscall blocking as the first run was done with a
cold disk cache.

[dvyukov, 2013-01-22 09:45:23]

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

runtime: account stop-the-world time in the "other" GOGCTRACE section
Currently it's summed to mark phase.
The change makes it easier to diagnose long stop-the-world phases.

R=golang-dev, bradfitz, dave
CC=golang-dev
https://codereview.appspot.com/7182043

[dvyukov, 2013-01-22 09:46:21]

On Tue, Jan 22, 2013 at 12:08 AM, Dave Cheney <dave@cheney.net> wrote:
> Thanks Dmitry, this will show some useful data. Consider the following
>
> odessa:~ dfc$ GOGCTRACE=1 go list
> gc1(1): 34+0+0 ms, 0 -> 0 MB 11 -> 13 (14-1) objects, 0(0) handoff,
> 0(0) steal, 0/0/0 yields
> gc2(1): 20+0+0 ms, 1 -> 1 MB 4879 -> 2094 (4968-2874) objects, 0(0)
> handoff, 0(0) steal, 0/0/0 yields
> _/Users/dfc
> odessa:~ dfc$ GOGCTRACE=1 go list
> gc1(1): 0+0+0 ms, 0 -> 0 MB 11 -> 13 (14-1) objects, 0(0) handoff,
> 0(0) steal, 0/0/0 yields
> gc2(1): 0+0+0 ms, 1 -> 1 MB 4971 -> 2059 (5062-3003) objects, 0(0)
> handoff, 0(0) steal, 0/0/0 yields
> _/Users/dfc
>
> Why does the same program, run twice, report different t0's, yet have
> almost the same memory footprint ? Something is extending the t0's,
> and I think this was syscall blocking as the first run was done with a
> cold disk cache.

Does it look different with this change? Is it actually stop-the-world time?

[dave_cheney.net, 2013-01-22 09:50:06]

Let me do some measurements 

On 22/01/2013, at 20:46, Dmitry Vyukov <dvyukov@google.com> wrote:

> On Tue, Jan 22, 2013 at 12:08 AM, Dave Cheney <dave@cheney.net> wrote:
>> Thanks Dmitry, this will show some useful data. Consider the following
>> 
>> odessa:~ dfc$ GOGCTRACE=1 go list
>> gc1(1): 34+0+0 ms, 0 -> 0 MB 11 -> 13 (14-1) objects, 0(0) handoff,
>> 0(0) steal, 0/0/0 yields
>> gc2(1): 20+0+0 ms, 1 -> 1 MB 4879 -> 2094 (4968-2874) objects, 0(0)
>> handoff, 0(0) steal, 0/0/0 yields
>> _/Users/dfc
>> odessa:~ dfc$ GOGCTRACE=1 go list
>> gc1(1): 0+0+0 ms, 0 -> 0 MB 11 -> 13 (14-1) objects, 0(0) handoff,
>> 0(0) steal, 0/0/0 yields
>> gc2(1): 0+0+0 ms, 1 -> 1 MB 4971 -> 2059 (5062-3003) objects, 0(0)
>> handoff, 0(0) steal, 0/0/0 yields
>> _/Users/dfc
>> 
>> Why does the same program, run twice, report different t0's, yet have
>> almost the same memory footprint ? Something is extending the t0's,
>> and I think this was syscall blocking as the first run was done with a
>> cold disk cache.
> 
> Does it look different with this change? Is it actually stop-the-world time?

[rsc, 2013-01-30 16:58:43]

LGTM