internal/trace: TestTraceStress/AllocFree failures

[gopherbot]

#!watchflakes
default <- pkg == "internal/trace" && test == "TestTraceStress/AllocFree"

Issue created automatically to collect these failures.

Example (log):

=== RUN   TestTraceStress/AllocFree
    reader_test.go:112: unexpected error while reading the trace: broken trace: failed to advance: frontier:
        [gen=2]
        
        M 140704631527360 [GoUnblock time=6706882767040 g=18 g_seq=1 stack=11]
        M 123145318756352 [GoStart time=6706885268416 g=1 g_seq=4]
        M 123145314463744 [ProcStart time=6706885574208 p=0 p_seq=3]
        M 123145316073472 [ProcStart time=6706885754368 p=4 p_seq=3]
        M 123145315000320 [ProcStart time=6706886095680 p=4 p_seq=4]
        M 123145317683200 [ProcStart time=6706888264768 p=2 p_seq=10]
...
        String id=250
        	data="net.(*TCPListener).close"
        String id=251
        	data="net.(*TCPListener).Close"
        String id=252
        	data="runtime.CallersFrames"
        String id=253
        	data="/Users/swarming/.swarming/w/ir/x/w/goroot/src/runtime/symtab.go"
        
--- FAIL: TestTraceStress/AllocFree (6.02s)

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "internal/trace" && test == "TestTraceStress/AllocFree"

2024-12-08 15:34 go1.24-darwin-amd64-longtest release-branch.go1.24@c8fb6ae6 internal/trace.TestTraceStress/AllocFree (log)

=== RUN   TestTraceStress/AllocFree
    reader_test.go:112: unexpected error while reading the trace: broken trace: failed to advance: frontier:
        [gen=2]
        
        M 140704631527360 [GoUnblock time=6706882767040 g=18 g_seq=1 stack=11]
        M 123145318756352 [GoStart time=6706885268416 g=1 g_seq=4]
        M 123145314463744 [ProcStart time=6706885574208 p=0 p_seq=3]
        M 123145316073472 [ProcStart time=6706885754368 p=4 p_seq=3]
        M 123145315000320 [ProcStart time=6706886095680 p=4 p_seq=4]
        M 123145317683200 [ProcStart time=6706888264768 p=2 p_seq=10]
...
        String id=250
        	data="net.(*TCPListener).close"
        String id=251
        	data="net.(*TCPListener).Close"
        String id=252
        	data="runtime.CallersFrames"
        String id=253
        	data="/Users/swarming/.swarming/w/ir/x/w/goroot/src/runtime/symtab.go"
        
--- FAIL: TestTraceStress/AllocFree (6.02s)

— watchflakes

[mknyszek]

I suspect this has the same root cause as #70883. What I'm finding is that the trace can't progress since there's no status event for g=18 in gen=2.

AFAICT, the last event for g=18 in gen=1 (a GoUnblock event) seemed to come from sysmon, and sysmon always only unblocks goroutines via injectglist. So, that's how we can end up in another kind of inconsistent state like #70883.

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "internal/trace" && test == "TestTraceStress/AllocFree"

2025-02-26 22:39 gotip-linux-amd64-longtest-noswissmap go@2e71ae33 internal/trace.TestTraceStress/AllocFree (log)

=== RUN   TestTraceStress/AllocFree
    reader_test.go:112: unexpected error while reading the trace: broken trace: failed to advance: frontier:
        [gen=2]
        
        M 74774 [GoUnblock time=166767834432 g=4 g_seq=1 stack=11]
        M 74817 [GoStart time=166772551936 g=4 g_seq=2]
        M 74789 [ProcStart time=166772704192 p=1 p_seq=17]
        M 74773 [GoStart time=166772737152 g=10 g_seq=3]
        M 74751 [ProcStart time=166773276672 p=0 p_seq=419]
        M 74769 [ProcStart time=166773286144 p=0 p_seq=420]
...
        String id=269
        	data="internal/poll.(*FD).WaitWrite"
        String id=270
        	data="syscall.Listen"
        String id=271
        	data="runtime.(*scavengerState).sleep"
        String id=272
        	data="runtime.(*scavengerState).park"
        
--- FAIL: TestTraceStress/AllocFree (5.19s)

— watchflakes