#!watchflakes
default <- pkg == "internal/trace" && log ~ `(inconsistent status|failed to advance|bad trace)`
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)
Comment From: 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)Comment From: 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.
Comment From: 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)Comment From: gopherbot
Found new dashboard test flakes for:
#!watchflakes
default <- pkg == "internal/trace" && test == "TestTraceStress/AllocFree"
2025-03-07 19:33 gotip-linux-amd64-longtest-aliastypeparams go@e6908846 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 124030 [GoUnblock time=722617322432 g=4 g_seq=1 stack=12] M 124011 [GoStart time=722623436928 g=4 g_seq=2] M 124024 [ProcStart time=722623445312 p=2 p_seq=2] M 124451 [GoStart time=722623466432 g=19 g_seq=2] M 124068 [ProcStart time=722623566528 p=4 p_seq=3] M 124073 [ProcStart time=722624696960 p=4 p_seq=4] ... String id=272 data="internal/poll.accept" String id=273 data="/home/swarming/.swarming/w/ir/x/w/goroot/src/internal/poll/sock_cloexec.go" String id=274 data="runtime.selectnbsend" String id=275 data="runtime.clearpools" --- FAIL: TestTraceStress/AllocFree (4.62s)Comment From: gopherbot
Found new dashboard test flakes for:
#!watchflakes
default <- pkg == "internal/trace" && test == "TestTraceStress/AllocFree"
2025-04-19 23:07 gotip-windows-amd64-longtest go@ad043420 internal/trace.TestTraceStress/AllocFree (log)
=== RUN TestTraceStress/AllocFree reader_test.go:112: unexpected error while reading the trace: inconsistent status for proc 1: old Idle vs. new Running trace_test.go:632: found bad trace; dumping to test log... trace_test.go:643: Trace Go1.23 ExperimentalBatch exp=1 gen=1 m=18446744073709551615 time=1954611829 data="\x01\x80\x80\x80\x80\x80\x18\x80@\b\x80@" EventBatch gen=1 m=8872 time=1954613605 size=65459 ProcStart dt=28 p=0 p_seq=1 ProcStop dt=7 ProcStart dt=740 p=0 p_seq=2 ... String id=274 data="net.(*TCPListener).Close" String id=275 data="runtime.(*mheap).alloc" String id=276 data="C:/b/s/w/ir/x/w/goroot/src/runtime/mheap.go" String id=277 data="sync.(*WaitGroup).Wait" --- FAIL: TestTraceStress/AllocFree (5.95s)Comment From: gopherbot
Found new dashboard test flakes for:
#!watchflakes
default <- pkg == "internal/trace" && test == "TestTraceStress/AllocFree"