#!watchflakes
default <- pkg == "internal/trace" && log ~ `holding locks`
Issue created automatically to collect these failures.
Example (log):
=== RUN TestTraceStressStartStop/AllocFree
exec.go:213: test timed out while running command: /home/swarming/.swarming/w/ir/x/w/goroot/bin/go run -race testdata/testprog/stress-start-stop.go
trace_test.go:610: signal: killed
--- FAIL: TestTraceStressStartStop/AllocFree (1511.99s)
Comment From: gopherbot
Found new dashboard test flakes for:
#!watchflakes
default <- pkg == "internal/trace" && test == "TestTraceStressStartStop/AllocFree"
2024-11-13 00:57 gotip-linux-amd64-longtest-race go@ab554650 internal/trace.TestTraceStressStartStop/AllocFree (log)
=== RUN TestTraceStressStartStop/AllocFree exec.go:213: test timed out while running command: /home/swarming/.swarming/w/ir/x/w/goroot/bin/go run -race testdata/testprog/stress-start-stop.go trace_test.go:610: signal: killed --- FAIL: TestTraceStressStartStop/AllocFree (1511.99s)Comment From: gopherbot
Found new dashboard test flakes for:
#!watchflakes
default <- pkg == "internal/trace" && test == "TestTraceStressStartStop/AllocFree"
2024-11-17 14:31 gotip-linux-386-longtest go@70207598 internal/trace.TestTraceStressStartStop/AllocFree (log)
=== RUN TestTraceStressStartStop/AllocFree trace_test.go:608: stderr: fatal error: schedule: holding locks runtime stack: runtime.throw({0x815e2a2, 0x17}) /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/panic.go:1084 +0x35 fp=0xf5efd2d0 sp=0xf5efd2bc pc=0x80b48f5 runtime.schedule() /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/proc.go:3988 +0x2c3 fp=0xf5efd2ec sp=0xf5efd2d0 pc=0x8088863 runtime.park_m(0x94025a8) /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/proc.go:4120 +0x1d9 fp=0xf5efd314 sp=0xf5efd2ec pc=0x8088a89 ... /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/trace.go:758 +0x40 fp=0x93a5fc8 sp=0x93a5f98 pc=0x80a0e20 runtime/trace.Start.func1() /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/trace/trace.go:130 +0x4e fp=0x93a5ff0 sp=0x93a5fc8 pc=0x812aabe runtime.goexit({}) /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/asm_386.s:1393 +0x1 fp=0x93a5ff4 sp=0x93a5ff0 pc=0x80b94f1 created by runtime/trace.Start in goroutine 1 /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/trace/trace.go:128 +0xb9 exit status 2 trace_test.go:610: exit status 1 --- FAIL: TestTraceStressStartStop/AllocFree (0.55s)Comment From: gopherbot
Found new dashboard test flakes for:
#!watchflakes
default <- pkg == "internal/trace" && test == "TestTraceStressStartStop/AllocFree"
2024-11-19 15:48 gotip-linux-amd64-longtest-aliastypeparams go@bedde1be internal/trace.TestTraceStressStartStop/AllocFree (log)
=== RUN TestTraceStressStartStop/AllocFree trace_test.go:608: stderr: fatal error: schedule: holding locks runtime stack: runtime.throw({0x5236b3?, 0x40d531?}) /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/panic.go:1099 +0x48 fp=0x7f7036a8edd8 sp=0x7f7036a8eda8 pc=0x4695c8 runtime.schedule() /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/proc.go:3989 +0x276 fp=0x7f7036a8ee10 sp=0x7f7036a8edd8 pc=0x43e6f6 runtime.park_m(0xc000102a80) /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/proc.go:4121 +0x21e fp=0x7f7036a8ee68 sp=0x7f7036a8ee10 pc=0x43e97e ... /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/trace.go:758 +0x31 fp=0xc000073fa0 sp=0xc000073f38 pc=0x456a51 runtime/trace.Start.func1() /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/trace/trace.go:130 +0x45 fp=0xc000073fe0 sp=0xc000073fa0 pc=0x4e22e5 runtime.goexit({}) /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/asm_amd64.s:1700 +0x1 fp=0xc000073fe8 sp=0xc000073fe0 pc=0x46f6c1 created by runtime/trace.Start in goroutine 1 /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/trace/trace.go:128 +0xcf exit status 2 trace_test.go:610: exit status 1 --- FAIL: TestTraceStressStartStop/AllocFree (0.72s)Comment From: gopherbot
Found new dashboard test flakes for:
#!watchflakes
default <- pkg == "internal/trace" && test == "TestTraceStressStartStop/AllocFree"
2025-02-12 18:20 gotip-linux-amd64-longtest go@127288b4 internal/trace.TestTraceStressStartStop/AllocFree (log)
=== RUN TestTraceStressStartStop/AllocFree exec.go:213: test timed out while running command: /home/swarming/.swarming/w/ir/x/w/goroot/bin/go run testdata/testprog/stress-start-stop.go trace_test.go:615: signal: killed --- FAIL: TestTraceStressStartStop/AllocFree (807.05s)Comment From: gopherbot
Found new dashboard test flakes for:
#!watchflakes
default <- pkg == "internal/trace" && test == "TestTraceStressStartStop/AllocFree"
2025-02-13 02:31 gotip-linux-386-longtest go@679cd8e7 internal/trace.TestTraceStressStartStop/AllocFree (log)
=== RUN TestTraceStressStartStop/AllocFree trace_test.go:613: stderr: fatal error: stopTheWorld: holding locks runtime stack: runtime.throw({0x8162f52, 0x1b}) /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/panic.go:1108 +0x35 fp=0xf38ff274 sp=0xf38ff260 pc=0x80bc2e5 runtime.stopTheWorldWithSema(0x9) /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/proc.go:1565 +0x540 fp=0xf38ff2ec sp=0xf38ff274 pc=0x808aac0 runtime.stopTheWorld.func1() /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/proc.go:1464 +0x46 fp=0xf38ff318 sp=0xf38ff2ec pc=0x808a336 ... /home/swarming/.swarming/w/ir/x/w/goroot/src/os/file.go:124 +0x70 fp=0x954dfc4 sp=0x954dfa0 pc=0x80ed680 main.main.func1.7() /home/swarming/.swarming/w/ir/x/w/goroot/src/internal/trace/testdata/testprog/stress-start-stop.go:98 +0x4b fp=0x954dff0 sp=0x954dfc4 pc=0x812cc3b runtime.goexit({}) /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/asm_386.s:1393 +0x1 fp=0x954dff4 sp=0x954dff0 pc=0x80c1181 created by main.main.func1 in goroutine 20 /home/swarming/.swarming/w/ir/x/w/goroot/src/internal/trace/testdata/testprog/stress-start-stop.go:96 +0x379 exit status 2 trace_test.go:615: exit status 1 --- FAIL: TestTraceStressStartStop/AllocFree (0.71s)Comment From: gopherbot
Found new dashboard test flakes for:
#!watchflakes
default <- pkg == "internal/trace" && test == "TestTraceStressStartStop/AllocFree"
2025-03-03 19:07 gotip-linux-amd64-longtest-noswissmap go@4b1ac7bb internal/trace.TestTraceStressStartStop/AllocFree (log)
=== RUN TestTraceStressStartStop/AllocFree trace_test.go:613: stderr: fatal error: schedule: holding locks runtime stack: runtime.throw({0x523891?, 0x7fffcf0f3468?}) /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/panic.go:1089 +0x48 fp=0x7fffcf0f3438 sp=0x7fffcf0f3408 pc=0x46fc68 runtime.schedule() /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/proc.go:3992 +0x276 fp=0x7fffcf0f3470 sp=0x7fffcf0f3438 pc=0x444ad6 runtime.park_m(0xc000102e00) /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/proc.go:4141 +0x285 fp=0x7fffcf0f34d0 sp=0x7fffcf0f3470 pc=0x444dc5 ... /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/trace.go:758 +0x31 fp=0xc000077fa0 sp=0xc000077f38 pc=0x45ce91 runtime/trace.Start.func1() /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/trace/trace.go:130 +0x45 fp=0xc000077fe0 sp=0xc000077fa0 pc=0x4e2d05 runtime.goexit({}) /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/asm_amd64.s:1692 +0x1 fp=0xc000077fe8 sp=0xc000077fe0 pc=0x4766a1 created by runtime/trace.Start in goroutine 1 /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/trace/trace.go:128 +0xcf exit status 2 trace_test.go:615: exit status 1 --- FAIL: TestTraceStressStartStop/AllocFree (0.18s)Comment From: gopherbot
Found new dashboard test flakes for:
#!watchflakes
default <- pkg == "internal/trace" && test == "TestTraceStressStartStop/AllocFree"
2025-04-04 22:04 gotip-linux-386-longtest go@2d050e91 internal/trace.TestTraceStressStartStop/AllocFree (log)
=== RUN TestTraceStressStartStop/AllocFree trace_test.go:613: stderr: fatal error: stopTheWorld: holding locks runtime stack: runtime.throw({0x81637b9, 0x1b}) /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/panic.go:1089 +0x35 fp=0xf42fe280 sp=0xf42fe26c pc=0x80bc745 runtime.stopTheWorldWithSema(0x9) /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/proc.go:1588 +0x528 fp=0xf42fe2ec sp=0xf42fe280 pc=0x808b368 runtime.stopTheWorld.func1() /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/proc.go:1487 +0x46 fp=0xf42fe318 sp=0xf42fe2ec pc=0x808abf6 ... goroutine 55 gp=0xa483688 m=nil [runnable]: main.main.func1.7() /home/swarming/.swarming/w/ir/x/w/goroot/src/internal/trace/testdata/testprog/stress-start-stop.go:96 fp=0xa4e3ff0 sp=0xa4e3fec pc=0x812d860 runtime.goexit({}) /home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/asm_386.s:1386 +0x1 fp=0xa4e3ff4 sp=0xa4e3ff0 pc=0x80c1db1 created by main.main.func1 in goroutine 20 /home/swarming/.swarming/w/ir/x/w/goroot/src/internal/trace/testdata/testprog/stress-start-stop.go:96 +0x379 exit status 2 trace_test.go:615: exit status 1 --- FAIL: TestTraceStressStartStop/AllocFree (0.64s)Comment From: mknyszek
This likely has something specifically to do with the allocfree trace experiment. I don't think we have evidence of it occurring anywhere else.
Comment From: mknyszek
Based on the failure, I'm feeling like this is a result of some kind of rare acquirem without a corresponding releasem perhaps specifically on an allocfree path, and that there's some distance between the acquirem and the crash. So, I suspect that we'll find that even if we know what happens the goroutines that are running in the stack traces in the failures in this issue, it won't help much. It'll just look like something very broken.