runtime: "schedule: holding locks"

[bcmills]

##### GOMAXPROCS=2 runtime -cpu=1,2,4 -quick
fatal error: fatal error: schedule: holding locks
fatal error: unexpected signal during runtime execution
panic during panic
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x0]

runtime stack:
runtime.throw(0x6aede6, 0x2a)
	/workdir/go/src/runtime/panic.go:1126 +0x74 fp=0x7ff7dc87ebe0 sp=0x7ff7dc87ebb0 pc=0x43f2f4
runtime: unexpected return pc for runtime.sigpanic called from 0x0
stack: frame={sp:0x7ff7dc87ebe0, fp:0x7ff7dc87ec40} stack=[0x7ff7dc07f280,0x7ff7dc87ee80)
0x00007ff7dc87eae0:  0x000000c000440300  0x0100000000000013 
0x00007ff7dc87eaf0:  0x000000000000000e  0x000000000000001f 
0x00007ff7dc87eb00:  0x0000000000000000  0x0000000000000000 
0x00007ff7dc87eb10:  0x0000000000000001  0x00000000006aa7d3 
0x00007ff7dc87eb20:  0x00007ff7dc87eb68  0x000000000043f5ff <runtime.fatalthrow.func1+0x000000000000005f> 
0x00007ff7dc87eb30:  0x000000c000440300  0x000000000043f2f4 <runtime.throw+0x0000000000000074> 
0x00007ff7dc87eb40:  0x00007ff7dc87ebb0  0x0000000000000001 
0x00007ff7dc87eb50:  0x00007ff7dc87ebb0  0x000000000043f2f4 <runtime.throw+0x0000000000000074> 
0x00007ff7dc87eb60:  0x000000c000440300  0x00007ff7dc87eba0 
0x00007ff7dc87eb70:  0x000000000043f57e <runtime.fatalthrow+0x000000000000005e>  0x00007ff7dc87eb80 
0x00007ff7dc87eb80:  0x000000000043f5a0 <runtime.fatalthrow.func1+0x0000000000000000>  0x000000c000440300 
0x00007ff7dc87eb90:  0x000000000043f2f4 <runtime.throw+0x0000000000000074>  0x00007ff7dc87ebb0 
0x00007ff7dc87eba0:  0x00007ff7dc87ebd0  0x000000000043f2f4 <runtime.throw+0x0000000000000074> 
0x00007ff7dc87ebb0:  0x00007ff7dc87ebb8  0x000000000043f320 <runtime.throw.func1+0x0000000000000000> 
0x00007ff7dc87ebc0:  0x00000000006aede6  0x000000000000002a 
0x00007ff7dc87ebd0:  0x00007ff7dc87ec30  0x0000000000457bcc <runtime.sigpanic+0x000000000000050c> 
0x00007ff7dc87ebe0: <0x00000000006aede6  0x000000000000002a 
0x00007ff7dc87ebf0:  0x0000000000440ea5 <runtime.gwrite+0x00000000000000a5>  0x0000000000599d55 <runtime_test.TestDebugCallGC+0x0000000000000095> 
0x00007ff7dc87ec00:  0x00000080000601ef  0x0000000000000000 
0x00007ff7dc87ec10:  0x000000000000000d  0x0000000000000000 
0x00007ff7dc87ec20:  0x0000000000000000  0x0000000000000000 
0x00007ff7dc87ec30:  0x0000000000000000 !0x0000000000000000 
0x00007ff7dc87ec40: >0x0000000000000000  0x0000000000470105 <runtime.InjectDebugCall+0x0000000000000205> 
0x00007ff7dc87ec50:  0x000000000043b7c5 <runtime.signalM+0x0000000000000045>  0x0000000000014f29 
0x00007ff7dc87ec60:  0x0000000000014f43  0x0000000000000017 
0x00007ff7dc87ec70:  0x00007ff7dc87ec90  0x000000000044e965 <runtime.preemptone+0x00000000000000c5> 
0x00007ff7dc87ec80:  0x000000c000108400  0x0000000000000017 
0x00007ff7dc87ec90:  0x00007ff7dc87ecd0  0x000000000044e865 <runtime.preemptall+0x0000000000000065> 
0x00007ff7dc87eca0:  0x000000c00002b800  0x0000000000000001 
0x00007ff7dc87ecb0:  0x0100000000000000  0x0000000000000003 
0x00007ff7dc87ecc0:  0x0000000000000000  0x00000000000f4240 
0x00007ff7dc87ecd0:  0x00007ff7dc87ecf0  0x000000000044399f <runtime.freezetheworld+0x000000000000003f> 
0x00007ff7dc87ece0:  0x00000000000003e8  0x0000000000000000 
0x00007ff7dc87ecf0:  0x00007ff7dc87ed18  0x000000000043f935 <runtime.startpanic_m+0x0000000000000155> 
0x00007ff7dc87ed00:  0x00000000008654c0  0x00000000006b4ad8 
0x00007ff7dc87ed10:  0x0000000000000001  0x00007ff7dc87ed60 
0x00007ff7dc87ed20:  0x000000000043f5dd <runtime.fatalthrow.func1+0x000000000000003d>  0x0000000000000001 
0x00007ff7dc87ed30:  0x00000000006b4ad8  0x0000000000000001 
runtime.sigpanic()
	/workdir/go/src/runtime/signal_unix.go:719 +0x50c fp=0x7ff7dc87ec40 sp=0x7ff7dc87ebe0 pc=0x457bcc

2021-02-23T09:15:36-6525abd/linux-amd64-fedora

CC @danscales @cherrymui @mknyszek @jeremyfaller

[danscales]

@prattmic in case you have any thoughts, since you have been looking at the scheduling code and at held locks recently

[prattmic]

I still need to look more closely at this, but there is a lot of suspicious behavior going on:

1. This is an InjectDebugCall test.
2. The test seems to be panicking on a g.m.locks++ line in acquirem() (bad g.m pointer?).
3. The stack dump indicates preemptone calls at some point (though probably after the first throw?).

[mknyszek]

I reworked some of the details re: how InjectDebugCall interacts with the scheduler, so if this isn't showing up anymore that might be one reason why.

[dmitshur]

It seems there haven't been more occurrences reported. @prattmic Do you expect to look more at this in time for Go 1.17, or should we move this to Backlog if this can happen later on?

[bcmills]

greplogs --dashboard -md -l -e 'schedule: holding locks' --since=2021-02-24

2021-11-04T21:53:05-ce13745-76c48e9/netbsd-386-9_0
2021-11-03T18:37:22-3a5865c-cfd016d/netbsd-amd64-9_0
2021-11-01T19:56:50-ee08195-5f1bcd1/netbsd-386-9_0
2021-10-29T18:23:03-413672f/netbsd-386-9_0
2021-09-07T19:39:04-d92101f/plan9-arm
2021-04-01T15:50:43-45ca9ef/linux-arm-scaleway
2021-04-01T01:26:29-5f646f0/linux-arm-scaleway
2021-04-01T00:51:26-ec721d9/linux-arm-scaleway
2021-04-01T00:51:24-1f29e69/linux-arm-scaleway
2021-04-01T00:51:23-3304b22/linux-arm-scaleway
2021-03-31T20:21:57-5d6581d/linux-arm-scaleway

[bcmills]

(None of the above failures seem to have anything to do with InjectDebugCall or linux-amd64, though.)

[bcmills]

Disregarding the platforms affected by #49209, the only recent failures are on plan9-arm (CC @millerresearch).

greplogs --dashboard -md -l -e 'fatal error: schedule: holding locks' --since=2021-11-18

2022-01-12T01:49:33-d55c255-3d3f5d9/plan9-arm
2022-01-06T15:30:17-9d39a96-dbdf055/netbsd-amd64-9_0-n2d
2021-12-23T18:58:36-af3b8cf/openbsd-386-70
2021-12-08T15:21:23-cadd57e-61317ef/netbsd-amd64-9_0-n2d
2021-12-07T20:14:56-d3358c1-b37a539/netbsd-386-9_0-n2d
2021-12-07T20:13:17-d3358c1-61317ef/openbsd-386-70-n2d
2021-12-06T22:34:03-eba003a-0f2d0d0/netbsd-386-9_0-n2d
2021-12-02T15:48:58-eb34ac4-28ec0fd/netbsd-386-9_0-n2d
2021-11-29T20:12:13-6e52f51-b7651e5/netbsd-amd64-9_0

[bcmills]

(Hmm, probably work opening a separate issue for that, since it has a separate root cause.)

Closing as obsolete per #44544 (comment).

[bcmills]

(Filed plan9-arm as #50560.)