internal/trace: broken traces produced by tests

[gopherbot]

#!watchflakes
default <- pkg == "internal/trace" && log ~ `(inconsistent status|failed to advance)`

Issue created automatically to collect these failures.

Example (log):

=== RUN   TestTraceCPUProfile/Default
    reader_test.go:112: unexpected error while reading the trace: inconsistent status for proc 1: old Syscall vs. new Running
    trace_test.go:627: found bad trace; dumping to test log...
    trace_test.go:638: Trace Go1.23
        EventBatch gen=1 m=28747 time=2687627497990 size=65459
        ProcStart dt=365 p=2 p_seq=1
        GoStart dt=223 g=1 g_seq=1
        HeapAlloc dt=839 heapalloc_value=4194304
        GoStop dt=301 reason_string=16 stack=8
        ProcStop dt=54
...
        String id=138
        	data="runtime.traceStartReadCPU.func1"
        String id=139
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/tracecpu.go"
        String id=140
        	data="runtime.traceLocker.ProcStart"
        String id=141
        	data="runtime.acquirep"
        
--- FAIL: TestTraceCPUProfile/Default (18.13s)

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "internal/trace" && test == "TestTraceCPUProfile/Default"

2025-01-03 00:10 gotip-netbsd-arm64 go@4b652e9f internal/trace.TestTraceCPUProfile/Default (log)

=== RUN   TestTraceCPUProfile/Default
    reader_test.go:112: unexpected error while reading the trace: inconsistent status for proc 1: old Syscall vs. new Running
    trace_test.go:627: found bad trace; dumping to test log...
    trace_test.go:638: Trace Go1.23
        EventBatch gen=1 m=28747 time=2687627497990 size=65459
        ProcStart dt=365 p=2 p_seq=1
        GoStart dt=223 g=1 g_seq=1
        HeapAlloc dt=839 heapalloc_value=4194304
        GoStop dt=301 reason_string=16 stack=8
        ProcStop dt=54
...
        String id=138
        	data="runtime.traceStartReadCPU.func1"
        String id=139
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/tracecpu.go"
        String id=140
        	data="runtime.traceLocker.ProcStart"
        String id=141
        	data="runtime.acquirep"
        
--- FAIL: TestTraceCPUProfile/Default (18.13s)

— watchflakes

[mknyszek]

Let's see if this same (or a similar) issue happens on other platforms...

[gopherbot]

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

#!watchflakes
default <- pkg == "internal/trace" && log ~ "inconsistent status for proc"

And the problems were:

script:2.45: ~ requires backquoted regexp

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

— watchflakes