runtime: tracer seems to stop the world or enter scheduler while holding locks when traceallocfree is enabled

[gopherbot]

#!watchflakes
default <- pkg == "internal/trace" && log ~ `holding locks`

Issue created automatically to collect these failures.

Example (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)

— watchflakes

[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)

— watchflakes

[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)

— watchflakes

[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)

— watchflakes

[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)

— watchflakes

[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)

— watchflakes

[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)

— watchflakes

[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)

— watchflakes