code review 87290043: runtime: reduce gc latency

runtime: reduce gc latency

Replace 1µs/100µs sleeps with yields. These sleeps take up to 10ms
on some systems, and usually take 1ms on most systems. When we yield we
are usually rescheduled much faster than that.

Results on 8-way Linux with tickless kernel:

Machine is:

    $ uname -a
    Linux 6d0b706a-0ddb-6734-844b-882660956eb8 3.8.6-joyent-debian-6-opt #1 SMP Wed Apr 10 22:00:18 UTC 2013 x86_64 GNU/Linux
    $
    $ lscpu
    Architecture:          x86_64
    CPU op-mode(s):        64-bit
    CPU(s):                8
    Thread(s) per core:    1
    Core(s) per socket:    1
    CPU socket(s):         8
    NUMA node(s):          1
    Vendor ID:             GenuineIntel
    CPU family:            6
    Model:                 44
    Stepping:              2
    CPU MHz:               2400.024
    L1d cache:             32K
    L1i cache:             32K
    L2 cache:              4096K
    $
    $ zgrep CONFIG_NO_HZ /proc/config.gz
    CONFIG_NO_HZ=y
    $ zgrep HIGH_RES_TIMERS /proc/config.gz
    CONFIG_HIGH_RES_TIMERS=y

Before (on revision b2ebbbcfc615):

    $ ./runtime.test -test.v -test.cpu=1,2,4,8,16 -test.run TestStackGrowth$ runtime
    === RUN TestStackGrowth
    --- PASS: TestStackGrowth (2.23 seconds)
    === RUN TestStackGrowth-2
    --- PASS: TestStackGrowth-2 (2.66 seconds)
    === RUN TestStackGrowth-4
    --- PASS: TestStackGrowth-4 (3.33 seconds)
    === RUN TestStackGrowth-8
    --- PASS: TestStackGrowth-8 (4.02 seconds)
    === RUN TestStackGrowth-16
    --- PASS: TestStackGrowth-16 (3.82 seconds)
    PASS

With this CL:

    $ ./runtime.test -test.v -test.cpu=1,2,4,8,16 -test.run TestStackGrowth$ runtime
    === RUN TestStackGrowth
    --- PASS: TestStackGrowth (2.27 seconds)
    === RUN TestStackGrowth-2
    --- PASS: TestStackGrowth-2 (1.94 seconds)
    === RUN TestStackGrowth-4
    --- PASS: TestStackGrowth-4 (2.94 seconds)
    === RUN TestStackGrowth-8
    --- PASS: TestStackGrowth-8 (3.73 seconds)
    === RUN TestStackGrowth-16
    --- PASS: TestStackGrowth-16 (3.47 seconds)
    PASS

Results on 2-way Solaris with 100Hz clock tick:

Machine:

    ; psrinfo -vp
    The physical processor has 2 virtual processors (0-1)
      x86 (GenuineIntel 6F2 family 6 model 15 step 2 clock 1829 MHz)
    	Intel(r) Core(tm)2 CPU         T5600  @ 1.83GHz

Before:

    ; runtime.test -test.v -test.cpu=1,2,4,8 -test.run TestStackGrowth$ runtime
    === RUN TestStackGrowth
    --- PASS: TestStackGrowth (2.13 seconds)
    === RUN TestStackGrowth-2
    --- PASS: TestStackGrowth-2 (32.48 seconds)
    === RUN TestStackGrowth-4
    --- PASS: TestStackGrowth-4 (32.36 seconds)
    === RUN TestStackGrowth-8
    --- PASS: TestStackGrowth-8 (30.10 seconds)
    PASS

After:

    ; runtime.test -test.v -test.cpu=1,2,4,8 -test.run TestStackGrowth$ runtime
    === RUN TestStackGrowth
    --- PASS: TestStackGrowth (2.08 seconds)
    === RUN TestStackGrowth-2
    --- PASS: TestStackGrowth-2 (2.02 seconds)
    === RUN TestStackGrowth-4
    --- PASS: TestStackGrowth-4 (1.97 seconds)
    === RUN TestStackGrowth-8
    --- PASS: TestStackGrowth-8 (2.00 seconds)
    PASS

Results on 24-way Solaris with 1kHz clock tick:

Machine:

    $ psrinfo -pv
    The physical processor has 6 cores and 12 virtual processors (1 3 5 7 9 11 13 15 17 19 21 23)
      The core has 2 virtual processors (1 13)
      The core has 2 virtual processors (3 15)
      The core has 2 virtual processors (5 17)
      The core has 2 virtual processors (7 19)
      The core has 2 virtual processors (9 21)
      The core has 2 virtual processors (11 23)
        x86 (GenuineIntel 206C2 family 6 model 44 step 2 clock 2400 MHz)
          Intel(r) Xeon(r) CPU           E5645  @ 2.40GHz
    The physical processor has 6 cores and 12 virtual processors (0 2 4 6 8 10 12 14 16 18 20 22)
      The core has 2 virtual processors (0 12)
      The core has 2 virtual processors (2 14)
      The core has 2 virtual processors (4 16)
      The core has 2 virtual processors (6 18)
      The core has 2 virtual processors (8 20)
      The core has 2 virtual processors (10 22)
        x86 (GenuineIntel 206C2 family 6 model 44 step 2 clock 2400 MHz)
          Intel(r) Xeon(r) CPU           E5645  @ 2.40GHz

Before:

    $ ./runtime.test -test.v -test.cpu=1,2,4,8,12,16,24,32,48 -test.run TestStackGrowth$ runtime
    === RUN TestStackGrowth
    --- PASS: TestStackGrowth (2.61 seconds)
    === RUN TestStackGrowth-2
    --- PASS: TestStackGrowth-2 (6.03 seconds)
    === RUN TestStackGrowth-4
    --- PASS: TestStackGrowth-4 (7.94 seconds)
    === RUN TestStackGrowth-8
    --- PASS: TestStackGrowth-8 (8.31 seconds)
    === RUN TestStackGrowth-12
    --- PASS: TestStackGrowth-12 (8.39 seconds)
    === RUN TestStackGrowth-16
    --- PASS: TestStackGrowth-16 (8.37 seconds)
    === RUN TestStackGrowth-24
    --- PASS: TestStackGrowth-24 (8.45 seconds)
    === RUN TestStackGrowth-32
    --- PASS: TestStackGrowth-32 (8.48 seconds)
    === RUN TestStackGrowth-48
    --- PASS: TestStackGrowth-48 (8.54 seconds)
    PASS

After:

    === RUN TestStackGrowth
    --- PASS: TestStackGrowth (2.67 seconds)
    === RUN TestStackGrowth-2
    --- PASS: TestStackGrowth-2 (2.38 seconds)
    === RUN TestStackGrowth-4
    --- PASS: TestStackGrowth-4 (2.71 seconds)
    === RUN TestStackGrowth-8
    --- PASS: TestStackGrowth-8 (3.13 seconds)
    === RUN TestStackGrowth-12
    --- PASS: TestStackGrowth-12 (3.06 seconds)
    === RUN TestStackGrowth-16
    --- PASS: TestStackGrowth-16 (3.08 seconds)
    === RUN TestStackGrowth-24
    --- PASS: TestStackGrowth-24 (2.95 seconds)
    === RUN TestStackGrowth-32
    --- PASS: TestStackGrowth-32 (2.98 seconds)
    === RUN TestStackGrowth-48
    --- PASS: TestStackGrowth-48 (3.09 seconds)

Fixes issue 7763

[aram, 2014-04-12 10:25:56]

Hello dvyukov (cc: golang-codereviews@googlegroups.com),

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

[rsc, 2014-04-14 00:06:41]

NOT LGTM

Not for Go 1.3. Too late, sorry.

It's really not a big deal on systems with a minimum sleep of 100us or so. The
problem happens on systems with a minimum sleep of 10ms or so, and the only one
we know about right now is Solaris.

I am very worried about what removing the sleeps entirely will do, especially on
systems where osyield does not work correctly in some cases. 

There may be some tuning to do here, but it will have to wait until the Go 1.4
cycle.

[aram, 2014-04-14 09:19:55]

I'm quite surprised by your response. I posted Linux/amd64 results.
This shows a clear improvement on Linux as well, for -cpu=2 the
improvement on Linux is 30%.  Problems definitely seems to happen
on more platforms, not only Solaris considering the previous state
of the builder dashboard. FWIW, the sleep granularity on Windows
is 10ms or 15ms by default (unless changed with timeBeginPeriod).
If you've seen a Windows system with 1ms sleep granularity without
calling timeBeginPeriod, it is because other application called it.

We have a performance dashboard, if this causes performance regressions
(how can it?) we can see them.

The recent timeout bump seems the wrong move; it hides the problem
and now everything seems "fine" and we will forget about it. In
other words, I am concerned that we had a test that demonstrated a
problem and now we don't.

If you really don't want to change the gc, what about changing
runtime·usleep on Solaris to yield instead of sleeping, for small
µs values. That will definitely not affect non-Solaris platforms.

[rsc, 2014-04-14 14:12:41]

On Mon, Apr 14, 2014 at 5:19 AM, <aram@mgk.ro> wrote:

> I'm quite surprised by your response. I posted Linux/amd64 results.
> This shows a clear improvement on Linux as well, for -cpu=2 the
> improvement on Linux is 30%.  Problems definitely seems to happen
> on more platforms, not only Solaris considering the previous state
> of the builder dashboard. FWIW, the sleep granularity on Windows
> is 10ms or 15ms by default (unless changed with timeBeginPeriod).
> If you've seen a Windows system with 1ms sleep granularity without
> calling timeBeginPeriod, it is because other application called it.
>

This is a benchmark that has little to do with ordinary execution. This
test is not much different than a loop that does nothing but call
runtime.GC, with a miniscule heap. Real programs do not call runtime.GC at
all. They let the garbage collector decide when to run. If you can
demonstrate a 30% improvement in a real program, then that might be worth
fixing at this late date. But even then it might not.

We are in a release freeze. The criteria for making a change is that
benefit*Pr[seeing benefit] >> cost-of-new-bug*Pr[introducing new bug]. If
you're not fixing a real bug, then the benefit is zero, and so the change
is not worth the potential cost. You are proposing to change a fundamental
detail of the looping in the garbage collector, to fix a case that
literally never happens in practice (calling GC in a loop) and that if it
did happen would not be worth optimizing.

We have a performance dashboard, if this causes performance regressions
> (how can it?) we can see them.
>

The kind of performance regressions that might be caused could be very
subtle; if we are going to make a change like this I want more time for the
reports to come in. It's too close to the Go 1.3 cutoff. That's what the
release freeze is all about.


> The recent timeout bump seems the wrong move; it hides the problem
> and now everything seems "fine" and we will forget about it. In
> other words, I am concerned that we had a test that demonstrated a
> problem and now we don't.
>

This test is not about garbage collection latency. It is about testing
stack growth. If stack growth is working properly, the test should pass.
You've filed an issue for the garbage collection latency. We won't forget
it.

If you really don't want to change the gc, what about changing
> runtime·usleep on Solaris to yield instead of sleeping, for small
> µs values. That will definitely not affect non-Solaris platforms.
>

If you can show this causing problems in real programs, then yes I'd go
along with that as a stopgap, for Solaris only. But we don't have evidence
of that yet.

Russ

[rsc, 2014-04-17 02:54:53]

R=close

Let's pick this up for 1.4 (hg mail will reopen).
In general I think it is a mistake to remove the sleeps entirely.
What if you have two CPUs running two threads and the other thread is taking a
long time on the other CPU? Once you've yielded a few times without effect, it
seems silly to spin yielding instead of sleeping.