runtime: fatal error: notewakeup - double wakeup

[alberts]

What steps will reproduce the problem?

#!/bin/bash
set -xe
export GOARCH=386
export GOHOSTARCH=386
cd $GOROOT/src
./make.bash
go version
go test -c math/rand
while true; do
GOMAXPROCS=48 ./rand.test
done

What do you see instead?

fatal error: notewakeup - double wakeup

goroutine 1 [chan receive]:
testing.RunTests(0x813f208, 0x81b4360, 0x6, 0x6, 0x1, ...)
    /build/go.386/go/src/pkg/testing/testing.go:427 +0x69f
testing.Main(0x813f208, 0x81b4360, 0x6, 0x6, 0x81b42e0, ...)
    /build/go.386/go/src/pkg/testing/testing.go:358 +0x69
main.main()
    math/rand/_test/_testmain.go:67 +0x81

goroutine 6 [running]:
testing.tRunner(0x1837e180, 0x81b4378)
    /build/go.386/go/src/pkg/testing/testing.go:329
created by testing.RunTests
    /build/go.386/go/src/pkg/testing/testing.go:426 +0x684

Which compiler are you using (5g, 6g, 8g, gccgo)?

8g

Which operating system are you using?

linux

Which version are you using?  (run 'go version')

go version devel +95b55f174b5d Tue Mar 26 17:32:22 2013 -0700 linux/386

Please provide any additional information below.

I've only seen this once. Trying to reproduce now.

[ianlancetaylor]

Comment 1:

Labels changed: added priority-asap, go1.1, removed priority-triage.

[alberts]

Comment 2:

this one is hard to reproduce. I'm leaving all of the following to run overnight to see
if it wants to fall out again:
GOMAXPROCS=$[ 1 + $[ RANDOM % 256 ]] ./rand.test -test.short
GOMAXPROCS=$[ 1 + $[ RANDOM % 256 ]] ./rand.test
GOMAXPROCS=48 ./rand.test -test.short
GOMAXPROCS=48 ./rand.test
GOMAXPROCS=48 ./rand.test -test.short -test.v
GOMAXPROCS=48 ./rand.test -test.v
./rand.test -test.short -test.cpu 1,1,1,2,2,2,4,4,4,8,16,256,256
./rand.test -test.cpu 1,1,1,2,2,2,4,4,4,8,16,256,256
./rand.test -test.short -test.v -test.cpu 1,1,1,2,2,2,4,4,4,8,16,256,256
./rand.test -test.v -test.cpu 1,1,1,2,2,2,4,4,4,8,16,256,256
GOGC=off GOMAXPROCS=128 ./rand.test -test.short -test.cpu 1,1,1,2,2,2,4,4,4,8,16,256,256
GOGC=off GOMAXPROCS=128 ./rand.test -test.cpu 1,1,1,2,2,2,4,4,4,8,16,256,256
GOGCTRACE=1 GOMAXPROCS=128 ./rand.test -test.short -test.cpu
1,1,1,2,2,2,4,4,4,8,16,256,256
GOGCTRACE=1 GOMAXPROCS=128 ./rand.test -test.cpu 1,1,1,2,2,2,4,4,4,8,16,256,256

[dvyukov]

Comment 3:

Don't forget GOTRACEBACK=2
I am not sure why it's not enabled by runtime in your fatal error report...

[alberts]

Comment 4:

For the record, I haven't managed to reproduce this yet, even with 2 machines with
different kernels running for more than a day...
the long net/http tests don't like GOTRACEBACK=2, so we need to fix that before I can
run all the tests with that turned on:
https://golang.org/issue/5005?c=28

[dvyukov]

Comment 5:

Brad reported it once, but I was not managed to reproduce it as well:
 just got this crash from this CL at 74e2affcfe39.
It went away after my next run of "go test -short std", though.  I only saw it once:
fatal error: notewakeup - double wakeup
goroutine 0 [idle]:
goroutine 1 [chan receive]:
testing.RunTests(0x400c00, 0x5d25d0, 0x2, 0x2, 0x1, ...)
    /home/bradfitz/go/src/pkg/testing/testing.go:378 +0x891
testing.Main(0x400c00, 0x5d25d0, 0x2, 0x2, 0x5d8c48, ...)
    /home/bradfitz/go/src/pkg/testing/testing.go:313 +0x8a
main.main()
    os/signal/_test/_testmain.go:45 +0x9a
goroutine 2 [syscall]:
created by runtime.main
    /home/bradfitz/go/src/pkg/runtime/proc.c:225
goroutine 3 [syscall]:
os/signal.loop()
    /home/bradfitz/go/src/pkg/os/signal/signal_unix.go:20 +0x1c
created by os/signal.init·1
    /home/bradfitz/go/src/pkg/os/signal/signal_unix.go:26 +0x2f
goroutine 6 [sleep]:
time.Sleep(0x5f5e100, 0xc20005d140)
    /home/bradfitz/go/src/pkg/runtime/ztime_linux_amd64.c:20 +0x2f
os/signal.TestStress()
    /home/bradfitz/go/src/pkg/os/signal/signal_test.go:97 +0x141
testing.tRunner(0xc200085090, 0x5d25e8, 0x0, 0x0)
    /home/bradfitz/go/src/pkg/testing/testing.go:301 +0x6c
created by testing.RunTests
    /home/bradfitz/go/src/pkg/testing/testing.go:377 +0x86e
goroutine 5 [syscall]:
created by addtimer
    /home/bradfitz/go/src/pkg/runtime/ztime_linux_amd64.c:73
goroutine 7 [select]:
os/signal.func·001(0xc20005d138, 0xc20005d140, 0x0, 0x0)
    /home/bradfitz/go/src/pkg/os/signal/signal_test.go:76 +0x14d
created by os/signal.TestStress
    /home/bradfitz/go/src/pkg/os/signal/signal_test.go:83 +0x110
goroutine 8 [running]:
created by os/signal.TestStress
    /home/bradfitz/go/src/pkg/os/signal/signal_test.go:96 +0x131
FAIL    os/signal   0.094s

[ianlancetaylor]

Comment 6:

Is this still an open issue?  Could this have been due to the precise GC issues we saw
in, e.g., issue #4979?

[dvyukov]

Comment 7:

Yes, it absolutely could have been caused by the GC issues.
I think we need to close this one for now. We can always find it and reopen in case we
see it again.

[ianlancetaylor]

Comment 8:

Please reopen if it recurs with current tip.  Thanks.

Status changed to Fixed.

[alberts]

Comment 9:

Just hit this again. Reopen?
64f7f4530ca8+ tip
linux/amd64
lots of cores
machine probably under highish load
=== RUN TestDeflateInflate-4
fatal error: notewakeup - double wakeup
goroutine 1 [chan receive]:
runtime.park(0x409e40, 0xc210077290, 0x611bad)
    /build/go.tip/go/src/pkg/runtime/proc.c:1224 +0x66
runtime.chanrecv(0x4d0420, 0xc210077240, 0x7f053d9c9cc8, 0x0, 0x0)
    /build/go.tip/go/src/pkg/runtime/chan.c:360 +0x50d
runtime.chanrecv1(0x4d0420, 0xc210077240, 0x7f053d9c9e68, 0x1, 0x1, ...)
    /build/go.tip/go/src/pkg/runtime/chan.c:452 +0x38
testing.RunTests(0x577d98, 0x6110c0, 0xb, 0xb, 0x1)
    /build/go.tip/go/src/pkg/testing/testing.go:442 +0x890
testing.Main(0x577d98, 0x6110c0, 0xb, 0xb, 0x612ba0, ...)
    /build/go.tip/go/src/pkg/testing/testing.go:373 +0x8c
main.main()
    compress/flate/_test/_testmain.go:139 +0x9c
runtime.main()
    /build/go.tip/go/src/pkg/runtime/proc.c:182 +0x94
runtime.goexit()
    /build/go.tip/go/src/pkg/runtime/proc.c:1276
goroutine 2 [syscall]:
runtime.MHeap_Scavenger()
    /build/go.tip/go/src/pkg/runtime/mheap.c:464 +0x93
runtime.goexit()
    /build/go.tip/go/src/pkg/runtime/proc.c:1276
created by runtime.main
    /build/go.tip/go/src/pkg/runtime/proc.c:165
goroutine 28 [running]:
    goroutine running on other thread; stack unavailable
FAIL    compress/flate  2.129s

[minux]

Comment 10:

Labels changed: added go1.2, removed go1.1.

Status changed to Accepted.

[alberts]

Comment 11:

One more, this time in reflect tests.
go version devel +000ecca1178d Mon Jul 08 21:14:32 2013 -0500 linux/amd64
This was running: go test -v -short -cpu 1,2,4,8,16,256 reflect
panic started while running TestSliceOf-4. Some of the test functions kept running after
that point.
fatal error: notewakeup - double wakeup
goroutine 1 [chan receive]:
runtime.park(0x40b420, 0xc2101ec590, 0x6a410d)
    /build/go.tip/go/src/pkg/runtime/proc.c:1224 +0x66
runtime.chanrecv(0x51db60, 0xc21014bcc0, 0x7f542a18ccc8, 0x0, 0x0)
    /build/go.tip/go/src/pkg/runtime/chan.c:360 +0x50d
runtime.chanrecv1(0x51db60, 0xc21014bcc0, 0x7f542a18ce68, 0x1, 0x1, ...)
    /build/go.tip/go/src/pkg/runtime/chan.c:452 +0x38
testing.RunTests(0x5e1bd8, 0x6a8340, 0x4e, 0x4e, 0x1)
    /build/go.tip/go/src/pkg/testing/testing.go:442 +0x890
testing.Main(0x5e1bd8, 0x6a8340, 0x4e, 0x4e, 0x6a2840, ...)
    /build/go.tip/go/src/pkg/testing/testing.go:373 +0x8c
main.main()
    reflect/_test/_testmain.go:209 +0x9c
runtime.main()
    /build/go.tip/go/src/pkg/runtime/proc.c:182 +0x94
runtime.goexit()
    /build/go.tip/go/src/pkg/runtime/proc.c:1276
goroutine 2 [syscall]:
runtime.MHeap_Scavenger()
    /build/go.tip/go/src/pkg/runtime/mheap.c:464 +0x93
runtime.goexit()
    /build/go.tip/go/src/pkg/runtime/proc.c:1276
created by runtime.main
    /build/go.tip/go/src/pkg/runtime/proc.c:165
goroutine 35 [syscall]:
timerproc()
    /build/go.tip/go/src/pkg/runtime/ztime_linux_amd64.c:198 +0xa6
runtime.goexit()
    /build/go.tip/go/src/pkg/runtime/proc.c:1276
created by addtimer
    /build/go.tip/go/src/pkg/runtime/ztime_linux_amd64.c:82
goroutine 34 [sleep]:
runtime.park(0x40b420, 0x6a9ba0, 0x69f780)
    /build/go.tip/go/src/pkg/runtime/proc.c:1224 +0x66
runtime.tsleep(0x3b9aca00, 0x69f780)
    /build/go.tip/go/src/pkg/runtime/ztime_linux_amd64.c:68 +0x94
time.Sleep(0x3b9aca00)
    /build/go.tip/go/src/pkg/runtime/ztime_linux_amd64.c:19 +0x31
reflect_test.selectWatcher()
    /build/go.tip/go/src/pkg/reflect/all_test.go:1346 +0x2e
runtime.goexit()
    /build/go.tip/go/src/pkg/runtime/proc.c:1276
created by reflect_test.func·003
    /build/go.tip/go/src/pkg/reflect/all_test.go:1076 +0x21
goroutine 225 [running]:
    goroutine running on other thread; stack unavailable
goroutine 227 [running]:
    goroutine running on other thread; stack unavailable

[alberts]

Comment 12:

One more. Just collecting them here in case it helps.
go version devel +000ecca1178d Mon Jul 08 21:14:32 2013 -0500 linux/386
fatal error: notewakeup - double wakeup
goroutine 1 [running]:
    goroutine running on other thread; stack unavailable
goroutine 2 [syscall]:
runtime.MHeap_Scavenger()
    /build/go.386/go/src/pkg/runtime/mheap.c:464 +0xae
runtime.goexit()
    /build/go.386/go/src/pkg/runtime/proc.c:1276
created by runtime.main
    /build/go.386/go/src/pkg/runtime/proc.c:165
FAIL    math/big    0.053s
Meanwhile, I've been running the reflect tests on linux/amd64 for 24 hours without
triggering this...

[dvyukov]

Comment 13:

I've tried to reproduce this very hard, and looked at the sources very closely. No glue.

Owner changed to @dvyukov.

[dvyukov]

Comment 14:

*** Submitted as
https://code.google.com/p/go/source/detail?r=5333e97ad270 ***
runtime: better debug output for inconsistent Note
Update issue #5139.
Double wakeup on Note was reported several times,
but no reliable reproducer.
There also was a strange report about weird value of epoll fd.
Maybe it's corruption of global data...
R=golang-dev, bradfitz
CC=golang-dev
https://golang.org/cl/12182043

[dvyukov]

Comment 15:

Frankly I am out of ideas. It happens so infrequently...
Stack trace would be useful, but unfortunately we won't see it...

Status changed to Started.