runtime: lock ordering problems

[bcmills]

#!watchflakes
post <- builder ~ `.*-staticlockranking` && log ~ `lock ordering problem`

(Pulled out from #55167, because these issues tend to be easier to diagnose; CC @golang/runtime)

[gopherbot]

Sorry, but there were parse errors in the watch flakes script.
The script I found was:

#!watchflakes
builder ~ `.*-staticlockranking` && log ~ `lock ordering problem`

And the problems were:

script:2.9: unexpected ~

See https://go.dev/wiki/Watchflakes for details.

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- builder ~ `.*-staticlockranking` && log ~ `lock ordering problem`

2023-01-17 19:55 linux-amd64-staticlockranking go@839c8425 runtime/trace.TestTraceFutileWakeup (log)

111172  ======
0 : hchan 15 0xc0000221d8
1 : hchan 15 0xc000022258
2 : traceStackTab 43 0x702a98
3 : wbufSpans 39 0x6fb6f0
fatal error: lock ordering problem

runtime stack:
runtime.throw({0x5c3185?, 0x1?})
	/workdir/go/src/runtime/panic.go:1047 +0x5d fp=0x7fe0337fd9c0 sp=0x7fe0337fd990 pc=0x439a9d
...
	/workdir/go/src/runtime/proc.go:387
runtime.semacquire1(0xc00019c118, 0x20?, 0x1, 0x0, 0x71?)
	/workdir/go/src/runtime/sema.go:160 +0x214 fp=0xc000063d60 sp=0xc000063cf8 pc=0x44de34
sync.runtime_Semacquire(0xc0001cc040?)
	/workdir/go/src/runtime/sema.go:62 +0x27 fp=0xc000063d98 sp=0xc000063d60 pc=0x46a5c7
sync.(*WaitGroup).Wait(0x8?)
	/workdir/go/src/sync/waitgroup.go:116 +0x4b fp=0xc000063dc0 sp=0xc000063d98 pc=0x4769ab
runtime/trace_test.TestTraceFutileWakeup(0xc0001a9ba0)
	/workdir/go/src/runtime/trace/trace_test.go:556 +0x399 fp=0xc000063f70 sp=0xc000063dc0 pc=0x56ec39
testing.tRunner(0xc0001a9ba0, 0x5cd9e0)

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- builder ~ `.*-staticlockranking` && log ~ `lock ordering problem`

2023-05-19 14:59 linux-amd64-staticlockranking go@251daf46 runtime.TestPinnerSimple (log)

67962  ======
0 : mspanSpecial 29 0x7f2c982bf700
1 : mheapSpecial 28 0xb70250
fatal error: lock ordering problem

runtime stack:
runtime.throw({0x85c23c?, 0xc00007f0f8?})
	/workdir/go/src/runtime/panic.go:1077 +0x5c fp=0x7f2c2affcde0 sp=0x7f2c2affcdb0 pc=0x43e23c
runtime.checkRanks(0xc000703040, 0x0?, 0x7dada0?)
	/workdir/go/src/runtime/lockrank_on.go:162 +0x236 fp=0x7f2c2affce40 sp=0x7f2c2affcde0 pc=0x40fbf6
runtime.lockWithRank.func1()
	/workdir/go/src/runtime/lockrank_on.go:87 +0x85 fp=0x7f2c2affce70 sp=0x7f2c2affce40 pc=0x40f845
runtime.systemstack()
	/workdir/go/src/runtime/asm_amd64.s:509 +0x4a fp=0x7f2c2affce80 sp=0x7f2c2affce70 pc=0x47a9ea

runtime.systemstack_switch()
	/workdir/go/src/runtime/asm_amd64.s:474 +0x8 fp=0xc000079db8 sp=0xc000079da8 pc=0x47a988
runtime.lockWithRank(0xc000079df8?, 0x40f7c0?)
	/workdir/go/src/runtime/lockrank_on.go:76 +0x85 fp=0xc000079df0 sp=0xc000079db8 pc=0x40f785
runtime.lock(...)
	/workdir/go/src/runtime/lock_futex.go:48
runtime.(*mheap).newPinnerBits(0x412225?)
	/workdir/go/src/runtime/pinner.go:176 +0x37 fp=0xc000079e28 sp=0xc000079df0 pc=0x43f6b7
runtime.setPinned(0xc00002a630, 0x1)
	/workdir/go/src/runtime/pinner.go:128 +0xf1 fp=0xc000079ec0 sp=0xc000079e28 pc=0x43f391
runtime.(*Pinner).Pin(0xc000079f40, {0x7b9580, 0xc00002a630})
	/workdir/go/src/runtime/pinner.go:41 +0x94 fp=0xc000079f20 sp=0xc000079ec0 pc=0x43eed4
runtime_test.TestPinnerSimple(0xc0002244e0)
	/workdir/go/src/runtime/pinner_test.go:57 +0x91 fp=0xc000079f70 sp=0xc000079f20 pc=0x7583b1
testing.tRunner(0xc0002244e0, 0x87e020)

2023-05-19 15:54 linux-amd64-staticlockranking go@f283cba3 runtime.TestPinnerSimple (log)

67768  ======
0 : mspanSpecial 29 0x7f7d1c6ea348
1 : mheapSpecial 28 0xb70250
fatal error: lock ordering problem

runtime stack:
runtime.throw({0x85c23c?, 0xc000314a68?})
	/workdir/go/src/runtime/panic.go:1077 +0x5c fp=0x7f7cdaffcde0 sp=0x7f7cdaffcdb0 pc=0x43e23c
runtime.checkRanks(0xc000582820, 0x0?, 0x7dada0?)
	/workdir/go/src/runtime/lockrank_on.go:162 +0x236 fp=0x7f7cdaffce40 sp=0x7f7cdaffcde0 pc=0x40fbf6
runtime.lockWithRank.func1()
	/workdir/go/src/runtime/lockrank_on.go:87 +0x85 fp=0x7f7cdaffce70 sp=0x7f7cdaffce40 pc=0x40f845
runtime.systemstack()
	/workdir/go/src/runtime/asm_amd64.s:509 +0x4a fp=0x7f7cdaffce80 sp=0x7f7cdaffce70 pc=0x47a9ea

runtime.systemstack_switch()
	/workdir/go/src/runtime/asm_amd64.s:474 +0x8 fp=0xc000073db8 sp=0xc000073da8 pc=0x47a988
runtime.lockWithRank(0xc000073df8?, 0x40f7c0?)
	/workdir/go/src/runtime/lockrank_on.go:76 +0x85 fp=0xc000073df0 sp=0xc000073db8 pc=0x40f785
runtime.lock(...)
	/workdir/go/src/runtime/lock_futex.go:48
runtime.(*mheap).newPinnerBits(0x412225?)
	/workdir/go/src/runtime/pinner.go:176 +0x37 fp=0xc000073e28 sp=0xc000073df0 pc=0x43f6b7
runtime.setPinned(0xc0025a6678, 0x1)
	/workdir/go/src/runtime/pinner.go:128 +0xf1 fp=0xc000073ec0 sp=0xc000073e28 pc=0x43f391
runtime.(*Pinner).Pin(0xc000073f40, {0x7b9580, 0xc0025a6678})
	/workdir/go/src/runtime/pinner.go:41 +0x94 fp=0xc000073f20 sp=0xc000073ec0 pc=0x43eed4
runtime_test.TestPinnerSimple(0xc000674340)
	/workdir/go/src/runtime/pinner_test.go:57 +0x91 fp=0xc000073f70 sp=0xc000073f20 pc=0x7583b1
testing.tRunner(0xc000674340, 0x87e020)

— watchflakes

[prattmic]

cc @mknyszek these look related to pinning

[mknyszek]

They're fixed at HEAD. :) Forgot to reference the issue because the change landed before this issue was updated.

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- builder ~ `.*-staticlockranking` && log ~ `lock ordering problem`

2023-05-11 14:15 linux-amd64-staticlockranking go@e738f130 os/signal.TestSignalTrace (log)

79552  ======
0 : traceStrings 20 0x65d6f0
1 : fin 18 0x676750
fatal error: lock ordering problem

runtime stack:
runtime.throw({0x54e56a?, 0x65d780?})
	/workdir/go/src/runtime/panic.go:1047 +0x5d fp=0x7f6459c6cb18 sp=0x7f6459c6cae8 pc=0x43a09d
runtime.checkRanks(0xc000006ea0, 0x65d760?, 0x65d760?)
	/workdir/go/src/runtime/lockrank_on.go:153 +0x205 fp=0x7f6459c6cb78 sp=0x7f6459c6cb18 pc=0x40dc65
...
	/workdir/go/src/runtime/sema.go:150 +0x20f fp=0xc00023be48 sp=0xc00023bde0 pc=0x44e1ef
runtime.semacquire(...)
	/workdir/go/src/runtime/sema.go:101
runtime.StopTrace()
	/workdir/go/src/runtime/trace.go:384 +0x27d fp=0xc00023be80 sp=0xc00023be48 pc=0x45cafd
runtime/trace.Stop()
	/workdir/go/src/runtime/trace/trace.go:148 +0x8d fp=0xc00023beb8 sp=0xc00023be80 pc=0x4bbead
os/signal.TestSignalTrace(0xc000293040)
	/workdir/go/src/os/signal/signal_test.go:908 +0x21a fp=0xc00023bf70 sp=0xc00023beb8 pc=0x4df5ba
testing.tRunner(0xc000293040, 0x556e30)

— watchflakes

[mknyszek]

I don't understand this last failure because traceStrings < MALLOC < fin explicitly in the lock rank order...