runtime: broken work conservation due to CL 310850

[bcmills]

##### GOMAXPROCS=2 runtime -cpu=1,2,4 -quick
SIGQUIT: quit
PC=0x4747c1 m=0 sigcode=0

goroutine 0 [idle]:
runtime.futex()
	/workdir/go/src/runtime/sys_linux_amd64.s:519 +0x21 fp=0x7ffffcc5a8e8 sp=0x7ffffcc5a8e0 pc=0x4747c1
runtime.futexsleep(0xc000024000, 0x7f6ae0, 0xc000036800)
	/workdir/go/src/runtime/os_linux.go:44 +0x36 fp=0x7ffffcc5a938 sp=0x7ffffcc5a8e8 pc=0x435776
runtime.notesleep(0x7f6c30)
	/workdir/go/src/runtime/lock_futex.go:160 +0x87 fp=0x7ffffcc5a970 sp=0x7ffffcc5a938 pc=0x40da47
runtime.mPark()
	/workdir/go/src/runtime/proc.go:1441 +0x2a fp=0x7ffffcc5a990 sp=0x7ffffcc5a970 pc=0x43ef2a
runtime.stoplockedm()
	/workdir/go/src/runtime/proc.go:2600 +0x65 fp=0x7ffffcc5a9e0 sp=0x7ffffcc5a990 pc=0x440b85
runtime.schedule()
	/workdir/go/src/runtime/proc.go:3287 +0x3d fp=0x7ffffcc5aa30 sp=0x7ffffcc5a9e0 pc=0x44267d
runtime.park_m(0xc0000001a0)
	/workdir/go/src/runtime/proc.go:3504 +0x14d fp=0x7ffffcc5aa60 sp=0x7ffffcc5aa30 pc=0x442dcd
runtime.mcall()
	/workdir/go/src/runtime/asm_amd64.s:307 +0x43 fp=0x7ffffcc5aa70 sp=0x7ffffcc5aa60 pc=0x470783

…

goroutine 23533 [running]:
	goroutine running on other thread; stack unavailable
created by runtime_test.testGoroutineParallelism2
	/workdir/go/src/runtime/proc_test.go:174 +0x325

goroutine 23532 [runnable]:
runtime_test.testGoroutineParallelism2.func1()
	/workdir/go/src/runtime/proc_test.go:174 fp=0xc00016cfe0 sp=0xc00016cfd8 pc=0x5aa140
runtime.goexit()
	/workdir/go/src/runtime/asm_amd64.s:1581 +0x1 fp=0xc00016cfe8 sp=0xc00016cfe0 pc=0x4729c1
created by runtime_test.testGoroutineParallelism2
	/workdir/go/src/runtime/proc_test.go:174 +0x325

goroutine 23531 [running]:
	goroutine running on other thread; stack unavailable
created by runtime_test.testGoroutineParallelism2
	/workdir/go/src/runtime/proc_test.go:174 +0x325

goroutine 23511 [runnable]:
runtime.gopark(0xc0000623b8, 0x0, 0x0, 0x0, 0x0)
	/workdir/go/src/runtime/proc.go:366 +0xd6 fp=0xc000474ee8 sp=0xc000474ec8 pc=0x43c5d6
runtime.chansend(0x272, 0x657a90, 0x1, 0x0)
	/workdir/go/src/runtime/chan.go:257 +0x435 fp=0xc000474f78 sp=0xc000474ee8 pc=0x407435
runtime.chansend1(0x0, 0x0)
	/workdir/go/src/runtime/chan.go:143 +0x1d fp=0xc000474fa8 sp=0xc000474f78 pc=0x406fdd
runtime_test.testGoroutineParallelism2.func2.1(0xce)
	/workdir/go/src/runtime/proc_test.go:212 +0x5a fp=0xc000474fc8 sp=0xc000474fa8 pc=0x5aa0ba
runtime_test.testGoroutineParallelism2.func2·dwrap·87()
	/workdir/go/src/runtime/proc_test.go:213 +0x2d fp=0xc000474fe0 sp=0xc000474fc8 pc=0x5aa02d
runtime.goexit()
	/workdir/go/src/runtime/asm_amd64.s:1581 +0x1 fp=0xc000474fe8 sp=0xc000474fe0 pc=0x4729c1
created by runtime_test.testGoroutineParallelism2.func2
	/workdir/go/src/runtime/proc_test.go:205 +0x46

goroutine 23505 [chan receive]:
runtime.gopark(0x40f25b, 0xc0003680c0, 0x20, 0x0, 0x7fd204238c40)
	/workdir/go/src/runtime/proc.go:366 +0xd6 fp=0xc0000afd20 sp=0xc0000afd00 pc=0x43c5d6
runtime.chanrecv(0x0, 0x0, 0x1)
	/workdir/go/src/runtime/chan.go:576 +0x54c fp=0xc0000afdb8 sp=0xc0000afd20 pc=0x4082cc
runtime.chanrecv1(0xffffffff, 0xc000051120)
	/workdir/go/src/runtime/chan.go:439 +0x18 fp=0xc0000afde0 sp=0xc0000afdb8 pc=0x407d18
runtime_test.testGoroutineParallelism2(0xbf0b36aee8, 0x1, 0x0)
	/workdir/go/src/runtime/proc_test.go:183 +0x20c fp=0xc0000aff48 sp=0xc0000afde0 pc=0x5a9b0c
runtime_test.TestGoroutineParallelism2(0x406fdd)
	/workdir/go/src/runtime/proc_test.go:146 +0x25 fp=0xc0000aff70 sp=0xc0000aff48 pc=0x5a98a5
testing.tRunner(0xc0002201a0, 0x6593d0)
	/workdir/go/src/testing/testing.go:1242 +0x102 fp=0xc0000affc0 sp=0xc0000aff70 pc=0x4dff02
testing.(*T).Run·dwrap·21()
	/workdir/go/src/testing/testing.go:1289 +0x2a fp=0xc0000affe0 sp=0xc0000affc0 pc=0x4e0c4a
runtime.goexit()
	/workdir/go/src/runtime/asm_amd64.s:1581 +0x1 fp=0xc0000affe8 sp=0xc0000affe0 pc=0x4729c1
created by testing.(*T).Run
	/workdir/go/src/testing/testing.go:1289 +0x365

…
*** Test killed with quit: ran too long (6m0s).
FAIL	runtime	360.133s
FAIL

2021-04-30T00:32:42-303b194/linux-amd64-noopt
2020-06-26T17:07:58-d1015f3/freebsd-386-11_2

Also seen on a recent TryBot:
https://storage.googleapis.com/go-build-log/eb7ebec0/freebsd-amd64-12_2_913d0c87.log

CC @jeremyfaller @aclements

[bcmills]

greplogs --dashboard -md -l -e '(?m)(?:SIGQUIT|test timed out).*\n(?:.*\n)*^runtime\.chansend1.*\n\t.*\nruntime_test\.testGoroutineParallelism2'

2021-11-02T03:55:19-6f1e9a9/freebsd-arm64-dmgk
2021-11-01T13:12:37-4056934/freebsd-arm64-dmgk
2021-10-25T20:39:31-0ae0d5c/freebsd-arm64-dmgk
2021-10-25T12:07:15-fcd2d9c/freebsd-arm64-dmgk
2021-10-22T00:56:18-23e57e5/freebsd-arm64-dmgk
2021-10-01T04:32:04-8ac5cbe/freebsd-arm64-dmgk
2021-09-30T15:20:44-7162c4c/freebsd-arm64-dmgk
2021-09-28T17:19:19-3a55597/freebsd-arm64-dmgk
2021-09-16T17:44:44-b1bedc0/freebsd-arm64-dmgk
2021-09-15T00:06:54-c7f2f51/freebsd-arm64-dmgk
2021-09-09T15:07:50-a295b3c/freebsd-arm64-dmgk
2021-09-02T19:36:22-a8aa6cf/linux-amd64-wsl
2021-09-02T14:44:50-014a972/freebsd-arm64-dmgk
2021-09-02T09:24:59-17e9d14/linux-386-sid
2021-08-28T16:58:26-5afa555/freebsd-arm64-dmgk
2021-08-25T18:27:41-d2f002c/freebsd-arm64-dmgk
2021-08-24T22:10:11-5d863f8/freebsd-arm64-dmgk
2021-08-16T18:44:57-631af58/freebsd-arm64-dmgk
2021-06-16T16:38:43-a294e4e/freebsd-arm64-dmgk
2021-06-11T16:09:15-e2dc6dd/dragonfly-amd64
2021-04-30T00:32:42-303b194/linux-amd64-noopt
2021-04-23T05:38:47-5963f0a/freebsd-arm64-dmgk

[bcmills]

greplogs --dashboard -md -l -e '(?m)(?:SIGQUIT|test timed out).*\n(?:.*\n)*^runtime\.chansend1.*\n\t.*\nruntime_test\.testGoroutineParallelism2' --since=2021-11-03

2021-11-17T04:31:29-fceca2c/freebsd-arm64-dmgk
2021-11-15T18:02:28-1dc9af5/freebsd-arm64-dmgk
2021-11-12T18:48:59-5d24203/freebsd-arm64-dmgk
2021-11-09T22:11:33-4aa0746/freebsd-arm64-dmgk

[bcmills]

Marking as release-blocker for Go 1.18 due to the high failure rate.

(Note that at least one failure within the current cycle is on a linux/386 builder, which tests a first-class port.)

[mknyszek]

Looking at the test, and specifically the comment

 162     // If runtime triggers a forced GC during this test then it will deadlock,
 163     // since the goroutines can't be stopped/preempted.
 164     // Disable GC for this test (see issue #10958).
 165     defer debug.SetGCPercent(debug.SetGCPercent(-1))

I suspect that what's wrong here is that a GC is already in progress, and this is fallout from the new minimum heap size making that more likely. This is probably already mitigated by https://go.dev/cl/368137, but still theoretically a failure here is possible. Indeed, the last failure was on Dec 2nd (going by the greplogs in #45867 (comment)), when I landed that CL, supporting that theory.

I'll send a CL to fix this for good.

[gopherbot]

Change https://golang.org/cl/369747 mentions this issue: runtime: call runtime.GC in several tests that disable GC