Still flaky after CL 204800.

linux-386-clang: https://build.golang.org/log/4982801962e94bcbe3dd7a01114769650eaab38b

CC @aclements @mknyszek @cherrymui @ianlancetaylor

This has been happening sporadically for some time, but it seems to have definitely picked up recently.

2019-11-01T16:05:22-8d45e61/freebsd-386-11_2
2019-11-02T21:51:23-7955ece/linux-amd64-sid
2019-11-03T01:44:46-d2c039f/linux-386-clang
2019-11-03T05:01:00-4497d7e/darwin-amd64-10_12
2019-11-04T05:27:25-fb29e22/linux-386
2019-11-04T05:27:25-fb29e22/netbsd-amd64-8_0
2019-11-04T18:53:43-210e367/darwin-amd64-race
2019-11-04T22:52:25-74af7fc/linux-amd64-race
2019-11-04T23:41:34-383b447/darwin-amd64-race
2019-11-05T00:17:34-04e80fb/linux-386-387
2019-11-05T01:01:31-376c4ce/freebsd-386-11_2
2019-11-05T02:49:48-2ff746d/linux-arm64-packet
2019-11-05T03:42:00-11db7e4/linux-arm
2019-11-05T18:37:06-c3cef0b/freebsd-amd64-race
2019-11-05T18:58:41-f07cbc7/freebsd-amd64-race
2019-11-05T20:21:34-552987f/linux-386-longtest
2019-11-06T02:49:10-de70de6/freebsd-amd64-race
2019-11-06T09:09:59-0c5d545/linux-amd64-jessie
2019-11-06T14:33:39-f891b7c/linux-386-clang
2019-11-06T16:17:30-a5936a4/linux-amd64-nocgo
2019-11-06T17:03:51-a2b1dc8/freebsd-amd64-race
2019-11-06T18:27:09-3c29796/linux-386-clang

My current guess is that this has changed due to signal preemption. The test only works if each running M is hit with a SIGQUIT while it is running a tight loop. The test is checking that the stack trace for each thread shows the loop. If the thread is preempted when it receives the SIGQUIT, it will instead show a track trace in the runtime with the thread stopped at gcstopm.

CC @aclements @cherrymui

Change https://golang.org/cl/205720 mentions this issue: runtime: set GODEBUG=asyncpreemptoff=1 in TestCrashDumpsAllThreads

If the SIGQUIT lands right after asyncPreempt2 switches to the system stack, but before CASing the G status out of _Grunning, I guess this can result in goroutine running on other thread; stack unavailable on the G and also not being trace backed on the M (as it is running on its G0)? (But the failure stack traces don't look like this.)

The test is expecting to see that theoretically unpreemptible loop appears the expected number of times in the stack trace. But if the loop is preempted, then the stack trace of that M will show something else, not the loop. So the test will fail.

Non-cooperative preemption will make real code more robust, but it doesn't make this specific test more robust.

@cherrymui It's normal to see goroutine running on other thread in the first set of stack traces. The expectation of the test is that you will then see one more stack trace per thread. The test expects those additional stack traces to fill in the references to the loop. But if the M is preempted when the program dies, then we don't see a reference to the loop in its stack.

@ianlancetaylor when the goroutine is preempted, it will show something like

        goroutine 6 [runnable]:
        runtime.asyncPreempt2()
        	/workdir/go/src/runtime/preempt.go:289 +0x62 fp=0xc000030630 sp=0xc000030610 pc=0x42ba62
        runtime.asyncPreempt()
        	/workdir/go/src/runtime/preempt_amd64.s:45 +0xdb fp=0xc0000307b8 sp=0xc000030630 pc=0x4589fb
        main.loop(0x0, 0xc00005e060)
        	/workdir/tmp/go-build869718673/main.go:36 +0x2d fp=0xc0000307d0 sp=0xc0000307b8 pc=0x48e3cd
        runtime.goexit()
        	/workdir/go/src/runtime/asm_amd64.s:1375 +0x1 fp=0xc0000307d8 sp=0xc0000307d0 pc=0x4570d1
        created by main.main
        	/workdir/tmp/go-build869718673/main.go:17 +0xac

The test counts the number of "main.loop" appearances, so this is counted correctly. On that thread, the additional stack trace (what I meant by saying "being trace backed on the M") will show that M's G0 stack, which does not include main.loop.

So, I think,

• if the goroutine is not preempted, the first set of stack traces will have goroutine running on other thread, and the additional stack trace will show one with main.loop.
• if the goroutine is preempted, the first set of stack traces will show main.loop (by tracing back through runtime.asyncPreempt), and the additional stack trace will show its G0 stack, which does not include main.loop.

So either way, it should be counted as 1 appearance (except in the case that the SIGQUIT lands in the small window I mentioned in my previous comment).

I think that what is happening when the test fails is that 1) the signal is sent; 2) the goroutine is reported as goroutine running on other thread; 3) the goroutine is preempted and the M enters schedule; 4) the M that was running the goroutine is signaled; 5) the M reports a stack trace up through schedule; 6) nothing reports main.loop because that goroutine was already reported in step 2 and the M is now doing something else.

@ianlancetaylor I thing you're right. This can result in a missing main.loop.

Still flaky (with the same failure mode) after CL 205720, albeit with what seems to be a lower failure rate:
2020-05-12T15:01:56-a0698a6/darwin-amd64-10_15
2019-12-06T23:44:28-76d2f6c/freebsd-amd64-11_2

Not sure if directly related, however this test currently fails 100% of the time on the openbsd/mips64 builder:

https://build.golang.org/log/b88cd54aa3ccb3e2bf03f5958dd593291803b00e

2020-12-07T02:31:33-e10c94a/freebsd-amd64-11_2
2020-10-26T14:50:38-532c199/dragonfly-amd64-5_8
2020-10-01T15:16:43-89f687d/freebsd-386-12_0

The runtime waits for 5 seconds for the SIGQUIT signal to bounce between all threads. All failure cases above seem to take longer than 5 seconds to finish, and it doesn't include all Ms. For those cases, I guess it is just that 5 seconds is not long enough to have the signal bounce between all threads (maybe the system is quite busy, because all.bash launches many processes?).

Still flaky, but shouldn’t hold up a release. Punting to Go1.17. Thank you everyone.

2021-04-16T21:50:38-9481789/freebsd-amd64-11_2
2021-04-06T23:39:42-972e883/linux-ppc64-buildlet
2021-03-08T19:07:25-7419a86/freebsd-arm64-dmgk

I think my analysis above gives a possible reason. But I don't know what we want to do to fix. Do we want to increase the 5 seconds waiting time?

Let's try dropping the t.Parallel so that there is hopefully less going on during this test. I'll send you a CL that does that and also tries to fold the test into testprog.

Change https://golang.org/cl/312510 mentions this issue: runtime: don't run TestCrashDumpsAllThreads in parallel