time: TestOverflowRuntimeTimer fails on freebsd/amd64

[davecheney]

What steps will reproduce the problem?

> --- FAIL: TestOverflowRuntimeTimer (0.10 seconds)
>         sleep_test.go:402: runtime timer stuck: overflow in addtimer
> FAIL
> FAIL    time    5.529s

This test fails frequently on our freebsd/amd64 builder. This may be a visualization
related issue, or a real problem lurking below the surface.

http://build.golang.org/log/578b35028f3e8262df6520fcb9eec7f1865148d3

[ality]

Comment 1:

Very likely an artifact of virtualization. We should probably just
bump up the timeout by default. Windows had to be special cased for
the same reason.
I should have listened to Rob when he suggested making the timeout
very long "like a second"­ (https://golang.org/cl/9035047).

[minux]

Comment 2:

yeah, i also remember that i saw the same failure on other virtualized builders,
but couldn't find the link.

[rsc]

Comment 3:

Labels changed: added release-none, removed go1.3maybe.

[rsc]

Comment 4:

Labels changed: added repo-main.

[davecheney]

Comment 5:

I ran this test on real hardware in a loop and it failed.
--- FAIL: TestOverflowRuntimeTimer (0.10 seconds)
        sleep_test.go:402: runtime timer stuck: overflow in addtimer
FAIL
FAIL    time    7.448s
I think the theory that the failures we have seen in CI is not correct. This is a real
problem.

Labels changed: added release-go1.3, removed priority-soon, release-none.

[ality]

Comment 6:

Dave,
Can you please apply https://golang.org/cl/58880043/ and run
the tests for the time package?
The log might be quite long so you might want to send it to golang-dev.
Thanks.

[davecheney]

Comment 7:

Thanks, i'll try this tonight.

[davecheney]

Comment 8:

Hmm, I ran the test in a loop overnight and could not generate a failure.
http://paste.ubuntu.com/6852101/
I don't know if this was due to the logging altering the timing issues in the test, or
because I was not running the full test suite now (the additional output causes other
tests to fail)

[davecheney]

Comment 9:

Issue #6437 has been merged into this issue.

[davecheney]

Comment 10:

I think I have an idea what is going wrong. Applying this diff
diff -r d2e78612ed03 src/pkg/time/internal_test.go
--- a/src/pkg/time/internal_test.go     Fri Jan 31 17:43:46 2014 +1100
+++ b/src/pkg/time/internal_test.go     Sat Feb 01 13:44:06 2014 +1100
@@ -70,6 +70,10 @@
        // any more timers (they might hang due to the same bug we're
        // now testing).
        stop := Now().Add(timeout)
+       var count int
+       defer func() {
+               print("count "); println(count)
+       }()
        for {
                select {
                case <-t.C:
@@ -78,6 +82,7 @@
                        if Now().After(stop) {
                                return errors.New("runtime timer stuck: overflow in addtimer")
                        }
+                       count++
                        runtime.Gosched()
                }
        }
Then observing the value of count
deadwood(~/go/src/pkg/time) % while ./time.test ; do true ; done
count 19
PASS
count 18
PASS
count 18
PASS
We see that runtime.Gosched() does not yield to the timer goroutine immediately. However
18 iterations of the loop is sufficient to get the timer goroutine on the scheduler and
send the value down t.C.
However if the machine is loaded, as it will be by default when go test -short std runs,
the results become unpredictable.
^Cdeadwood(~/go/src/pkg/time) % while ./time.test ; do true ; done
count 614
PASS
count 1
PASS
count 860
PASS
count 343
PASS
count 2
I don't believe runtime.Gosched is yielding to the waiting goroutine.

[davecheney]

Comment 11:

Owner changed to @davecheney.

Status changed to Started.

[davecheney]

Comment 12:

Here is a possible fix, https://golang.org/cl/56540046

[davecheney]

Comment 13:

This issue was closed by revision d98b3a7.

Status changed to Fixed.

[gpaul]

Comment 14:

This test is failing quite often on our build server. The last failure was on
4b3cdcb02f2d38cb59a5e738c79100e91572809e.