code review 71080043: runtime: fix finalizer flakiness

runtime: fix finalizer flakiness

The flakiness appears to be just in tests, not in the actual code.
Specifically, the many tests call runtime.GC once and expect that
the finalizers will be running in the background when GC returns.
Now that the sweep phase is concurrent with execution, however,
the finalizers will not be run until sweep finishes, which might
be quite a bit later. To force sweep to finish, implement runtime.GC
by calling the actual collection twice. The second will complete the
sweep from the first.

This was reliably broken after a few runs before the CL and now
passes tens of runs:

while GOMAXPROCS=2 ./runtime.test -test.run=Finalizer -test.short \
        -test.timeout=300s -test.cpu=$(perl -e 'print ("1,2,4," x 100) . "1"')
do true; done

Fixes issue 7328.

[rsc, 2014-03-04 06:29:24]

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

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

[dave_cheney.net, 2014-03-04 06:33:07]

I'm fine with this. I have little sympathy for bug reports that complain that
calling runtime.GC is too expensive and if this helps dissuade people from the
practice of manually managing the gc, all the better. 

> On 4 Mar 2014, at 17:29, rsc@golang.org wrote:
> 
> Reviewers: dvyukov,
> 
> Message:
> Hello dvyukov (cc: golang-codereviews@googlegroups.com),
> 
> I'd like you to review this change to
> https://code.google.com/p/go/
> 
> 
> Description:
> runtime: fix finalizer flakiness
> 
> The flakiness appears to be just in tests, not in the actual code.
> Specifically, the many tests call runtime.GC once and expect that
> the finalizers will be running in the background when GC returns.
> Now that the sweep phase is concurrent with execution, however,
> the finalizers will not be run until sweep finishes, which might
> be quite a bit later. To force sweep to finish, implement runtime.GC
> by calling the actual collection twice. The second will complete the
> sweep from the first.
> 
> This was reliably broken after a few runs before the CL and now
> passes tens of runs:
> 
> while GOMAXPROCS=2 ./runtime.test -test.run=Finalizer -test.short \
>        -test.timeout=300s -test.cpu=$(perl -e 'print ("1,2,4," x 100) .
> "1"')
> do true; done
> 
> Fixes issue 7328.
> 
> Please review this at https://codereview.appspot.com/71080043/
> 
> Affected files (+9, -0 lines):
>  M src/pkg/runtime/malloc.goc
> 
> 
> Index: src/pkg/runtime/malloc.goc
> ===================================================================
> --- a/src/pkg/runtime/malloc.goc
> +++ b/src/pkg/runtime/malloc.goc
> @@ -803,6 +803,15 @@
> }
> 
> func GC() {
> +    // We assume that the user expects unused memory to have
> +    // been freed when GC returns. To ensure this, run gc(1) twice.
> +    // The first will do a collection, and the second will force the
> +    // first's sweeping to finish before doing a second collection.
> +    // The second collection is overkill, but we assume the user
> +    // has a good reason for calling runtime.GC and can stand the
> +    // expense. At the least, this fixes all the calls to runtime.GC in
> +    // tests that expect finalizers to start running when GC returns.
> +    runtime·gc(1);
>    runtime·gc(1);
> }
> 
> 
> 
> -- 
> You received this message because you are subscribed to the Google Groups
"golang-codereviews" group.
> To unsubscribe from this group and stop receiving emails from it, send an
email to golang-codereviews+unsubscribe@googlegroups.com.
> For more options, visit https://groups.google.com/groups/opt_out.

[dvyukov, 2014-03-04 06:45:45]

I agree that users should not call GC manually in performance sensitive
contexts.

But what do you think if we sweep everything and start finalizers when force=1,
that would pretty much restore the original behavior (at the cost of additional
code).
I've found 10 calls of runtime.GC in our internal codebase (not in tests), I
don't know why people are doing this.

[rsc, 2014-03-04 06:51:24]

On Tue, Mar 4, 2014 at 1:45 AM, <dvyukov@google.com> wrote:

> But what do you think if we sweep everything and start finalizers when
> force=1, that would pretty much restore the original behavior (at the
> cost of additional code).
>

I looked at all the internal uses and I don't see any that warrant this
effort. What's in this CL seems fine.

[dvyukov, 2014-03-04 06:56:39]

LGTM

[rsc, 2014-03-04 14:46:17]

by the way, if you'd like to make this better, i would suggest looking into
why it is that the bgsweep goroutine is not running quickly enough. the
finalizer test in package runtime does a 4 second sleep after runtime.GC to
wait for the finalizer to be run. it seems like bgsweep should be able to
complete and then run finalizers in under 4 seconds. my guess is that there
is a race and that on some invocations bgsweep does not get woken up. in
fact i think i see a race between the park in bgsleep and the wakeup in the
collector. but my attempted fix did not make any difference to the test
failing.

if you do

for i in $(seq 1 100); do
GOMAXPROCS=2 ./runtime.test -test.run=Finalizer \
    -test.short -test.timeout=300s \
   -test.cpu=$(perl -e 'print ("1,2,4," x 100) . "1"')
done

then it typically fails (at least on my laptop) about 10% of the time, with
or without my "bgsweep race" fix. but with this CL, it's really fixed.

[rsc, 2014-03-04 14:46:43]

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

runtime: fix finalizer flakiness

The flakiness appears to be just in tests, not in the actual code.
Specifically, the many tests call runtime.GC once and expect that
the finalizers will be running in the background when GC returns.
Now that the sweep phase is concurrent with execution, however,
the finalizers will not be run until sweep finishes, which might
be quite a bit later. To force sweep to finish, implement runtime.GC
by calling the actual collection twice. The second will complete the
sweep from the first.

This was reliably broken after a few runs before the CL and now
passes tens of runs:

while GOMAXPROCS=2 ./runtime.test -test.run=Finalizer -test.short \
        -test.timeout=300s -test.cpu=$(perl -e 'print ("1,2,4," x 100) . "1"')
do true; done

Fixes issue 7328.

LGTM=dvyukov
R=dvyukov, dave
CC=golang-codereviews
https://codereview.appspot.com/71080043

[dvyukov, 2014-03-14 06:59:24]

On Tue, Mar 4, 2014 at 6:46 PM, Russ Cox <rsc@golang.org> wrote:
> by the way, if you'd like to make this better, i would suggest looking into
> why it is that the bgsweep goroutine is not running quickly enough. the
> finalizer test in package runtime does a 4 second sleep after runtime.GC to
> wait for the finalizer to be run. it seems like bgsweep should be able to
> complete and then run finalizers in under 4 seconds. my guess is that there
> is a race and that on some invocations bgsweep does not get woken up. in
> fact i think i see a race between the park in bgsleep and the wakeup in the
> collector. but my attempted fix did not make any difference to the test
> failing.


okay, there are 3 races in that code
i will send fixes




> if you do
>
> for i in $(seq 1 100); do
> GOMAXPROCS=2 ./runtime.test -test.run=Finalizer \
>     -test.short -test.timeout=300s \
>    -test.cpu=$(perl -e 'print ("1,2,4," x 100) . "1"')
> done
>
> then it typically fails (at least on my laptop) about 10% of the time, with
> or without my "bgsweep race" fix. but with this CL, it's really fixed.