os/signal: frequent timeouts in TestSignal beginning 2021-11-05

[bcmills]

greplogs --dashboard -md -l -e '(?ms)FAIL: TestSignal .*timeout .*waiting for window' --since=2019-11-09

2021-11-22T12:29:44-ffb6c79/linux-amd64-nocgo
2021-11-18T02:16:39-353cb71/linux-amd64-clang
2021-11-17T19:51:32-9a33945/linux-386-buster
2021-11-17T04:32:11-03dd049/linux-386-stretch
2021-11-16T15:59:43-79d0013/linux-arm-aws
2021-11-13T01:39:23-c78a267/linux-386-stretch
2021-11-12T23:26:33-3a4b950/linux-amd64-bullseye
2021-11-12T20:02:21-9519651/linux-386
2021-11-11T20:45:40-ccd41cc/linux-386
2021-11-10T00:56:02-318c024/linux-386-jessie
2021-11-05T19:01:13-93bab8a/linux-386-buster
2021-11-05T05:30:39-b68c02e/linux-386-stretch

greplogs --dashboard -md -l -e '(?ms)FAIL: TestSignal .*timeout .*waiting for hangup' --since=2019-11-09

2021-11-19T21:41:33-ba9f0f6/netbsd-arm-bsiegert
2021-11-19T21:36:17-0f75a9e/netbsd-arm-bsiegert
2021-11-17T21:26:25-0440fb8/openbsd-amd64-70
2021-11-17T04:31:22-f384c70/linux-386-jessie
2021-11-13T03:33:55-c239790/linux-amd64-buster
2021-11-11T20:25:49-c622d1d/linux-386-buster
2021-11-08T14:49:56-ab31dbc/linux-386-sid
2021-11-06T19:41:15-61d789d/netbsd-arm-bsiegert
2021-11-06T19:41:10-565f457/netbsd-arm-bsiegert
2021-11-05T22:55:56-e83a204/netbsd-arm-bsiegert
2021-11-05T22:30:17-b07c41d/linux-386-sid
2021-11-05T07:00:05-6fefb7f/linux-mips-rtrk
2021-02-19T00:03:36-75e273f/dragonfly-amd64-5_8
2020-12-23T05:27:04-fd6ba1c/darwin-amd64-10_15
2020-05-04T22:52:07-b5f7ff4/linux-ppc64-buildlet

CC @ianlancetaylor @mknyszek

My knee-jerk reaction is that this may be somehow related to the GC pacing changes, but I have no idea how. 😅

[hanchaoqun]

The root cause is that SIGURG (preemption signal) occupies the buf of chan whose size is only 10. I can reproduce it in the following way on my computer.

go test -c os/signal
./signal.test -test.v=1 -test.run='^TestSignal$' -test.count=20000

And add some test log into signal.go

func process(sig os.Signal) {
...
	for c, h := range handlers.m {
		if h.want(n) {
			// send but do not block for it
			select {
			case c <- sig:
				println("send ", n," ok! chan=", c)
			default:
				if n == 28 {
					println("send SIGWINCH failed! chan=", c)
				}
			}
		}
	}
...
}

=== RUN   TestSignal
    signal_test.go:136: sighup...
send  1  ok! chan= 0xc000280f60
    signal_test.go:149: sigwinch...
send  23  ok! chan= 0xc0000945a0
send  23  ok! chan= 0xc0000945a0
send  23  ok! chan= 0xc0000945a0
send  23  ok! chan= 0xc0000945a0
send  23  ok! chan= 0xc0000945a0
send  23  ok! chan= 0xc0000945a0
send  23  ok! chan= 0xc0000945a0
send  23  ok! chan= 0xc0000945a0
send  23  ok! chan= 0xc0000945a0
send  23  ok! chan= 0xc0000945a0
send SIGWINCH failed! chan= 0xc0000945a0
...

I will try to fix this.

[gopherbot]

Change https://golang.org/cl/366514 mentions this issue: os/signal: fix TestSignal frequent timeouts