internal/trace/v2: TestTraceStressStartStop failures

[gopherbot]

#!watchflakes
default <- pkg == "internal/trace/v2" && test == "TestTraceStressStartStop"

Issue created automatically to collect these failures.

Example (log):

--- FAIL: TestTraceStressStartStop (2.31s)
    --- FAIL: TestTraceStressStartStop/Default (2.31s)
        reader_test.go:112: unexpected error while reading the trace: broken trace: failed to advance: frontier:
            [gen=5]

            M 136394 [ProcStart time=1207439980416 p=6 p_seq=9]

            G 4 [status=Waiting seq=0 (gen=5)]
            G 34 [status=Waiting seq=0 (gen=5)]
            G 14 [status=Waiting seq=0 (gen=5)]
...
            String id=125
            	data="/tmp/workdir/go/src/runtime/select.go"
            String id=126
            	data="runtime.systemstack_switch"
            String id=127
            	data="/tmp/workdir/go/src/runtime/asm_386.s"
            String id=128
            	data="runtime.startTheWorld"
            String id=129
            	data="/tmp/workdir/go/src/runtime/proc.go"

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "internal/trace/v2" && test == "TestTraceStressStartStop"

2024-01-24 21:35 openbsd-386-72 go@333ecd4b internal/trace/v2.TestTraceStressStartStop (log)

--- FAIL: TestTraceStressStartStop (2.31s)
    --- FAIL: TestTraceStressStartStop/Default (2.31s)
        reader_test.go:112: unexpected error while reading the trace: broken trace: failed to advance: frontier:
            [gen=5]

            M 136394 [ProcStart time=1207439980416 p=6 p_seq=9]

            G 4 [status=Waiting seq=0 (gen=5)]
            G 34 [status=Waiting seq=0 (gen=5)]
            G 14 [status=Waiting seq=0 (gen=5)]
...
            String id=125
            	data="/tmp/workdir/go/src/runtime/select.go"
            String id=126
            	data="runtime.systemstack_switch"
            String id=127
            	data="/tmp/workdir/go/src/runtime/asm_386.s"
            String id=128
            	data="runtime.startTheWorld"
            String id=129
            	data="/tmp/workdir/go/src/runtime/proc.go"

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "internal/trace/v2" && test == "TestTraceStressStartStop"

2024-02-23 00:19 openbsd-386-72 go@d9be6097 internal/trace/v2.TestTraceStressStartStop (log)

--- FAIL: TestTraceStressStartStop (1.73s)
    --- FAIL: TestTraceStressStartStop/Default (1.73s)
        reader_test.go:112: unexpected error while reading the trace: broken trace: failed to advance: frontier:
            [gen=5]

            M 418255 [ProcStart time=1464360968576 p=5 p_seq=47]
            M 347288 [ProcStart time=1464361031872 p=5 p_seq=48]
            M 410008 [ProcStart time=1464361105984 p=6 p_seq=26]
            M 179278 [ProcStart time=1464361925056 p=3 p_seq=5]
            M 208539 [ProcStart time=1464362345600 p=3 p_seq=9]
...
            String id=113
            	data="main.main.func1.5"
            String id=114
            	data="runtime.chanrecv1"
            String id=115
            	data="/tmp/workdir/go/src/runtime/chan.go"
            String id=116
            	data="runtime.(*wakeableSleep).sleep"
            String id=117
            	data="runtime.traceStartReadCPU"

— watchflakes

[mknyszek]

Duplicate of #65318.

Unfortunately, I can't close it because watchflakes will just reopen it until #65318 is fixed. It looks like watchflakes categorizes tests slightly differently with the old and new infrastructure.

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "internal/trace/v2" && test == "TestTraceStressStartStop"

2024-02-28 16:44 windows-arm64-11 go@db8c6c8c internal/trace/v2.TestTraceStressStartStop (log)

--- FAIL: TestTraceStressStartStop (0.75s)
    --- FAIL: TestTraceStressStartStop/Default (0.75s)
        reader_test.go:112: unexpected error while reading the trace: broken trace: failed to advance: frontier:
            [gen=5]

            M 4552 [ProcStart time=5032904270615 p=5 p_seq=4]
            M 10000 [ProcStart time=5032904271431 p=5 p_seq=5]
            M 4588 [ProcStart time=5032904271839 p=0 p_seq=7]
            M 6124 [ProcStart time=5032904272960 p=5 p_seq=6]
            M 8368 [ProcStart time=5032904273164 p=4 p_seq=5]
...
            String id=177
            	data="runtime.resettimer"
            String id=178
            	data="time.resetTimer"
            String id=179
            	data="runtime.systemstack_switch"
            String id=180
            	data="C:/workdir/go/src/runtime/asm_arm64.s"
            String id=181
            	data="syscall.connectEx"

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "internal/trace/v2" && test == "TestTraceStressStartStop"

2024-03-01 08:06 windows-arm64-11 go@b5a64ba6 internal/trace/v2.TestTraceStressStartStop (log)

--- FAIL: TestTraceStressStartStop (0.73s)
    --- FAIL: TestTraceStressStartStop/Default (0.73s)
        reader_test.go:112: unexpected error while reading the trace: broken trace: failed to advance: frontier:
            [gen=5]

            M 10568 [ProcStart time=5293757137482 p=5 p_seq=1]
            M 5316 [ProcStart time=5293757137582 p=5 p_seq=3]
            M 9604 [ProcStart time=5293757137983 p=0 p_seq=14]
            M 1388 [ProcStart time=5293757138082 p=5 p_seq=2]
            M 8856 [ProcStart time=5293757138082 p=5 p_seq=4]
...
            String id=110
            	data="runtime.startTheWorld"
            String id=111
            	data="C:/workdir/go/src/runtime/proc.go"
            String id=112
            	data="runtime.traceLocker.Gomaxprocs"
            String id=113
            	data="C:/workdir/go/src/runtime/trace2runtime.go"
            String id=114
            	data="main.main.func1.5"

— watchflakes

[mknyszek]

The fix for #65318 landed. Closing this issue as well.

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "internal/trace/v2" && test == "TestTraceStressStartStop"

2024-03-23 04:07 openbsd-386-72 go@83a6c13e internal/trace/v2.TestTraceStressStartStop (log)

--- FAIL: TestTraceStressStartStop (2.94s)
    --- FAIL: TestTraceStressStartStop/Default (2.94s)
        reader_test.go:112: unexpected error while reading the trace: expected a proc but didn't have one
        trace_test.go:588: found bad trace; dumping to test log...
        trace_test.go:589: dumping trace: mismatched version between writer (go 1.22) and event (go 1.23)

— watchflakes

[mknyszek]

We lost the trace here because of a mistake. I sent a CL to rectify the mistake. Unfortunately there's not much we can do here without being able to inspect the trace. These failures seem incredibly rare at this point.