runtime: panic during panic during deadlock detection

[edre]

1. Run the program in http://play.golang.org/p/1BGCSGhqfH with GOMAXPROCS > 0 (not on
the playground)

What is the expected output?
A normal panic showing what all the goroutines are doing

What do you see instead?
"panic during panic" and truncated output.

Observed at recent head:
go version devel +c96951f239c0 Wed Jun 26 13:59:25 2013 -0700 linux/amd64
but it works correctly at 1.1.1
I bisected this regression to 916cb45c0d5f (runtime: add lr, ctxt, ret to Gobuf)

Background:
I set up a simple work queue with one channel feeding some goroutines, which write their
results to another channel. Using a high GOMAXPROX I expected to see the program using
all the cpu, but found that cpu usage starts high but quickly drops down to using one
cpu. It seemed like there was some deadlock, so I told it to panic halfway through, but
panicking failed...

[edre]

Comment 1:

It seems that only the "panic during panic" was introduced by 916cb45c0d5f. At go1.1.1,
I still see cpu usage dropping to one cpu without any workers exiting. This seems pretty
bad, so I assume I'm doing something wrong in my code.

[davecheney]

Comment 2:

I have confirmed that under Go 1.1.1 the panic during panic is not present.
lucky(~/src) % go run issue.go
panic: i > 10
goroutine 4 [running]:
main.func·001()
        /home/dfc/src/issue.go:33 +0x53
sync.(*Once).Do(0x5162b0, 0x4c7458)
        /home/dfc/go/src/pkg/sync/once.go:40 +0x7e
main.func·002()
        /home/dfc/src/issue.go:34 +0xae
created by main.main
        /home/dfc/src/issue.go:38 +0xe7
goroutine 1 [chan receive]:
main.main()
        /home/dfc/src/issue.go:52 +0x160
goroutine 3 [running]:
main.func·002()
        /home/dfc/src/issue.go:29 +0x64
created by main.main
        /home/dfc/src/issue.go:38 +0xe7
goroutine 5 [runnable]:
main.func·003()
        /home/dfc/src/issue.go:44 +0x4d
created by main.main
        /home/dfc/src/issue.go:47 +0x12d
exit status 2
I believe the second panic is caused by the deadlock as there is no longer anyone to
write to result.
I don't see what this contrived example has to do with the unrelated problem of resource
starvation.

[alberts]

Comment 3:

FWIW, our pet runtime issue is at issue #5734. The commit we think might have caused it is
https://code.google.com/p/go/source/detail?r=bb553699c7e6
which went in on the same day as 916cb45c0d5f mentioned here.

[dvyukov]

Comment 4:

I suspect "panic during panic" is because traceback tries to unwind through
chansend/recv, which don't have argsize.

Owner changed to @rsc.

[edre]

Comment 5:

Using a cpu-heavy work function almost identical to the original I can show the resource
starvation problem more clearly. This runs the workers for a while but calls a panic
near the end to get a stack trace.
from http://play.golang.org/p/xC9tJhLD0b
goroutine 5 [running]:
main.func·001()
        issue.go:49 +0xa9
created by main.main
        issue.go:55 +0xe7
goroutine 1 [chan receive]:
main.main()
        issue.go:69 +0x160
goroutine 3 [running]:
created by main.main
        issue.go:55 +0xe7
goroutine 4 [running]:
created by main.main
        issue.go:55 +0xe7
goroutine 6 [chan send]:
main.func·002()
        issue.go:61 +0x4d
created by main.main
        issue.go:64 +0x12d
panic: what
goroutine 4 [running]:
main.func·001()
        issue.go:49 +0xa9
created by main.main
        issue.go:55 +0xe7
goroutine 1 is the main function waiting for results
goroutine 6 is the goroutine adding work to the queue
goroutine 4 is the worker that hit the panic code during processing
goroutines 3 and 5 should be doing work and hogging the cpu, but both are in "running"
state apparently not having entered the goroutine's function after being created. This
is consistent with what I have observed, that only one cpu is used when there is still a
lot more work to be done.
Am I misinterpreting these stacktraces, or are some goroutines stuck when they should be
able to get work from the channel?

[edre]

Comment 6:

Making the workers call runtime.Gosched() every million iterations solves the
underutilization problem. So the scheduler is not sufficiently aggressive for this use
case.

[dvyukov]

Comment 7:

The underutilized CPU look like https://golang.org/issue/5586

[rsc]

Comment 8:

Labels changed: added priority-later, go1.2, removed priority-triage.

Status changed to Accepted.

[dvyukov]

Comment 9:

I will take a look. I suspect this is already fixed.

Owner changed to @dvyukov.

[dvyukov]

Comment 10:

Works fine on tip with different values of GOMAXPROCS.
Please reopen if you still see it.

Status changed to Fixed.