internal/trace: TestTraceStacks failures

[gopherbot]

#!watchflakes
default <- pkg == "internal/trace" && test ~ `TestTraceStacks`

Issue created automatically to collect these failures.

Example (log):

=== RUN   TestTraceStacks/Default
    trace_test.go:499: no match for StateTransition Match=Goroutine Running->Runnable Stack=[]trace_test.frame{trace_test.frame{fn:"main.syncPreemptPoint", line:0}, trace_test.frame{fn:"main.main.func12", line:0}}
    trace_test.go:668: found bad trace; dumping to test log...
    trace_test.go:679: Trace Go1.25
        EventBatch gen=1 m=18446744073709551615 time=3561093234 size=23
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=122 mono=227909974775 sec=1751057236 nsec=143347899
        EventBatch gen=1 m=28599 time=3562885851 size=7
        ProcStart dt=217 p=2 p_seq=3
...
        String id=237
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/internal/poll/sock_cloexec.go"
        String id=238
        	data="runtime.createfing"
        String id=239
        	data="runtime.SetFinalizer"
        String id=240
        	data="net.(*netFD).setAddr"
        
--- FAIL: TestTraceStacks/Default (7.67s)

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

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

2025-06-27 20:38 gotip-linux-amd64-longtest go@2a22aefa internal/trace.TestTraceStacks/Default (log)

=== RUN   TestTraceStacks/Default
    trace_test.go:499: no match for StateTransition Match=Goroutine Running->Runnable Stack=[]trace_test.frame{trace_test.frame{fn:"main.syncPreemptPoint", line:0}, trace_test.frame{fn:"main.main.func12", line:0}}
    trace_test.go:668: found bad trace; dumping to test log...
    trace_test.go:679: Trace Go1.25
        EventBatch gen=1 m=18446744073709551615 time=3561093234 size=23
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=122 mono=227909974775 sec=1751057236 nsec=143347899
        EventBatch gen=1 m=28599 time=3562885851 size=7
        ProcStart dt=217 p=2 p_seq=3
...
        String id=237
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/internal/poll/sock_cloexec.go"
        String id=238
        	data="runtime.createfing"
        String id=239
        	data="runtime.SetFinalizer"
        String id=240
        	data="net.(*netFD).setAddr"
        
--- FAIL: TestTraceStacks/Default (7.67s)

2025-06-27 20:56 gotip-linux-amd64-asan-clang15 go@e81c6246 internal/trace.TestTraceStacks/Default (log)

=== RUN   TestTraceStacks/Default
    trace_test.go:499: no match for StateTransition Match=Goroutine Running->Runnable Stack=[]trace_test.frame{trace_test.frame{fn:"main.syncPreemptPoint", line:0}, trace_test.frame{fn:"main.main.func12", line:0}}
    trace_test.go:668: found bad trace; dumping to test log...
    trace_test.go:679: Trace Go1.25
        EventBatch gen=1 m=18446744073709551615 time=2564254135 size=23
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=121 mono=164112272358 sec=1751058486 nsec=147607058
        EventBatch gen=1 m=26939 time=2566829469 size=293
        ProcStart dt=194 p=4 p_seq=1
...
        String id=250
        	data="sync.(*WaitGroup).Done"
        String id=251
        	data="runtime.forcegchelper"
        String id=252
        	data="net.setNoDelay"
        String id=253
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/net/tcpsockopt_posix.go"
        
--- FAIL: TestTraceStacks/Default (4.68s)

— watchflakes

[thepudds]

CC @mknyszek. (Maybe related to runtime: account for missing frame pointer in preamble, or maybe not 😅)

[thepudds]

And watchflakes issue #74418 seems plausibly related.

[gopherbot]

Found new dashboard test flakes for:

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

2025-06-28 01:17 gotip-linux-arm go@b51f1cdb internal/trace.TestTraceStacks/Default (log)

=== RUN   TestTraceStacks/Default
    trace_test.go:499: no match for StateTransition Match=Goroutine Running->Runnable Stack=[]trace_test.frame{trace_test.frame{fn:"main.syncPreemptPoint", line:0}, trace_test.frame{fn:"main.main.func12", line:0}}
    trace_test.go:668: found bad trace; dumping to test log...
    trace_test.go:679: Trace Go1.25
        EventBatch gen=1 m=18446744073709551615 time=690126375019001 size=26
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=64 mono=44168088001220099 sec=1751081186 nsec=980487350
        EventBatch gen=1 m=2607139 time=690126375425763 size=94
        ProcStart dt=61 p=3 p_seq=1
...
        String id=236
        	data="sync.(*WaitGroup).Wait"
        String id=237
        	data="runtime.(*scavengerState).park"
        String id=238
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/mgcscavenge.go"
        String id=239
        	data="runtime.bgscavenge"
        
--- FAIL: TestTraceStacks/Default (4.89s)

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

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

2025-06-30 14:40 gotip-darwin-amd64_12 go@9d1cd0b8 internal/trace.TestTraceStacks/Default (log)

=== RUN   TestTraceStacks/Default
    trace_test.go:499: no match for StateTransition Match=Goroutine Running->Runnable Stack=[]trace_test.frame{trace_test.frame{fn:"main.syncPreemptPoint", line:0}, trace_test.frame{fn:"main.main.func12", line:0}}
    trace_test.go:668: found bad trace; dumping to test log...
    trace_test.go:679: Trace Go1.25
        EventBatch gen=1 m=18446744073709551615 time=479807028825 size=25
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=48 mono=30707649847905 sec=1751295124 nsec=397398000
        EventBatch gen=1 m=123145408192512 time=479807034415 size=289
        ProcStart dt=33 p=0 p_seq=4
...
        String id=221
        	data="runtime.(*cleanupQueue).dequeue"
        String id=222
        	data="/Users/swarming/.swarming/w/ir/x/w/goroot/src/runtime/mcleanup.go"
        String id=223
        	data="runtime.runCleanups"
        String id=224
        	data="runtime.updateMaxProcsGoroutine"
        
--- FAIL: TestTraceStacks/Default (2.68s)

— watchflakes

[mknyszek]

Yup, this is a new property the test is checking. Either:

1. The relevant goroutine isn't being synchronously preempted at all at the point we want in the trace.
2. There's still a bug in the traceback.

These should be evident from the failed traces, and indeed, it is. It appears to be (1). In one of the failed traces, the relevant goroutine is always being asynchronously preempted. It's a short test, so with enough runs it's certainly possible for the signals to consistently win out over the synchronous preemption.

That being said, this is just a test-only failure. I don't know what the best way to de-flake this is besides turning off async preemption for this test. (We could run it twice, once with, once without.)

[gopherbot]

Found new dashboard test flakes for:

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

2025-06-30 16:00 gotip-darwin-arm64_13 go@03ad694d internal/trace.TestTraceStacks/Default (log)

=== RUN   TestTraceStacks/Default
    trace_test.go:499: no match for StateTransition Match=Goroutine Running->Runnable Stack=[]trace_test.frame{trace_test.frame{fn:"main.syncPreemptPoint", line:0}, trace_test.frame{fn:"main.main.func12", line:0}}
    trace_test.go:668: found bad trace; dumping to test log...
    trace_test.go:679: Trace Go1.25
        EventBatch gen=1 m=18446744073709551615 time=343696552043 size=25
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=330 mono=21996579351666 sec=1751300246 nsec=8298000
        EventBatch gen=1 m=6132232192 time=343700195373 size=7
        ProcStart dt=33 p=4 p_seq=1
...
        String id=221
        	data="internal/poll.(*FD).Close"
        String id=222
        	data="net.(*netFD).Close"
        String id=223
        	data="net.(*conn).Close"
        String id=224
        	data="runtime.stopTheWorldGC"
        
--- FAIL: TestTraceStacks/Default (1.80s)

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

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

2025-06-30 20:32 gotip-linux-amd64-longtest go@8002d283 internal/trace.TestTraceStacks/Default (log)

=== RUN   TestTraceStacks/Default
    trace_test.go:499: no match for StateTransition Match=Goroutine Running->Runnable Stack=[]trace_test.frame{trace_test.frame{fn:"main.syncPreemptPoint", line:0}, trace_test.frame{fn:"main.main.func12", line:0}}
    trace_test.go:668: found bad trace; dumping to test log...
    trace_test.go:679: Trace Go1.25
        EventBatch gen=1 m=18446744073709551615 time=2285563626 size=25
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=131 mono=146276080222 sec=1751316011 nsec=441716856
        EventBatch gen=1 m=26097 time=2290407675 size=6
        ProcStart dt=117 p=4 p_seq=1
...
        String id=237
        	data="runtime.(*scavengerState).park"
        String id=238
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/mgcscavenge.go"
        String id=239
        	data="runtime.bgscavenge"
        String id=240
        	data="runtime.startTheWorldGC"
        
--- FAIL: TestTraceStacks/Default (9.16s)

2025-06-30 20:58 gotip-linux-amd64-longtest-noswissmap go@479b51ee internal/trace.TestTraceStacks/Default (log)

=== RUN   TestTraceStacks/Default
    trace_test.go:499: no match for StateTransition Match=Goroutine Running->Runnable Stack=[]trace_test.frame{trace_test.frame{fn:"main.syncPreemptPoint", line:0}, trace_test.frame{fn:"main.main.func12", line:0}}
    trace_test.go:668: found bad trace; dumping to test log...
    trace_test.go:679: Trace Go1.25
        EventBatch gen=1 m=18446744073709551615 time=2470485260 size=25
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=150 mono=158111066202 sec=1751317866 nsec=791711746
        EventBatch gen=1 m=25864 time=2473061949 size=57
        ProcStart dt=176 p=3 p_seq=9
...
        String id=244
        	data="runtime.runFinalizers"
        String id=245
        	data="syscall.getsockopt"
        String id=246
        	data="syscall.GetsockoptInt"
        String id=247
        	data="runtime.stopTheWorldGC"
        
--- FAIL: TestTraceStacks/Default (11.60s)

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

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

2025-06-30 23:52 gotip-linux-amd64-longtest-aliastypeparams go@86fca3dc internal/trace.TestTraceStacks/Default (log)

=== RUN   TestTraceStacks/Default
    trace_test.go:499: no match for StateTransition Match=Goroutine Running->Runnable Stack=[]trace_test.frame{trace_test.frame{fn:"main.syncPreemptPoint", line:0}, trace_test.frame{fn:"main.main.func12", line:0}}
    trace_test.go:668: found bad trace; dumping to test log...
    trace_test.go:679: Trace Go1.25
        EventBatch gen=1 m=18446744073709551615 time=3037749324 size=25
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=130 mono=194415964987 sec=1751328554 nsec=962946987
        EventBatch gen=1 m=28445 time=3039766726 size=62
        ProcStart dt=176 p=2 p_seq=11
...
        String id=244
        	data="runtime.createfing"
        String id=245
        	data="runtime.SetFinalizer"
        String id=246
        	data="net.(*netFD).setAddr"
        String id=247
        	data="main.main.func6"
        
--- FAIL: TestTraceStacks/Default (7.49s)

2025-07-01 15:29 gotip-linux-amd64-longtest go@27ad1f50 internal/trace.TestTraceStacks/Default (log)

=== RUN   TestTraceStacks/Default
    trace_test.go:499: no match for StateTransition Match=Goroutine Running->Runnable Stack=[]trace_test.frame{trace_test.frame{fn:"main.syncPreemptPoint", line:0}, trace_test.frame{fn:"main.main.func12", line:0}}
    trace_test.go:668: found bad trace; dumping to test log...
    trace_test.go:679: Trace Go1.25
        EventBatch gen=1 m=18446744073709551615 time=2329533093 size=24
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=122 mono=149090125725 sec=1751384450 nsec=787208967
        EventBatch gen=1 m=26115 time=2331892173 size=64
        ProcStart dt=244 p=3 p_seq=7
...
        String id=244
        	data="runtime.GOMAXPROCS"
        String id=245
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/debug.go"
        String id=246
        	data="runtime.startTheWorldGC"
        String id=247
        	data="internal/poll.(*FD).WaitWrite"
        
--- FAIL: TestTraceStacks/Default (9.42s)

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

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

2025-07-01 16:11 go1.25-linux-amd64-longtest-noswissmap release-branch.go1.25@6e95fd96 internal/trace.TestTraceStacks/Default (log)

=== RUN   TestTraceStacks/Default
    trace_test.go:499: no match for StateTransition Match=Goroutine Running->Runnable Stack=[]trace_test.frame{trace_test.frame{fn:"main.syncPreemptPoint", line:0}, trace_test.frame{fn:"main.main.func12", line:0}}
    trace_test.go:668: found bad trace; dumping to test log...
    trace_test.go:679: Trace Go1.25
        EventBatch gen=1 m=18446744073709551615 time=2385782643 size=23
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=119 mono=152690096706 sec=1751398155 nsec=77647660
        EventBatch gen=1 m=25910 time=2387861774 size=49
        ProcStart dt=919 p=3 p_seq=1
...
        String id=237
        	data="sync.(*Mutex).Lock"
        String id=238
        	data="os.(*file).close"
        String id=239
        	data="os.(*File).Close"
        String id=240
        	data="net.(*file).close"
        
--- FAIL: TestTraceStacks/Default (10.23s)

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

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

2025-06-30 16:31 go1.25-linux-amd64-longtest release-branch.go1.25@47318323 internal/trace.TestTraceStacks/Default (log)

=== RUN   TestTraceStacks/Default
    trace_test.go:499: no match for StateTransition Match=Goroutine Running->Runnable Stack=[]trace_test.frame{trace_test.frame{fn:"main.syncPreemptPoint", line:0}, trace_test.frame{fn:"main.main.func12", line:0}}
    trace_test.go:668: found bad trace; dumping to test log...
    trace_test.go:679: Trace Go1.25
        EventBatch gen=1 m=18446744073709551615 time=3609698225 size=24
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=133 mono=231020694901 sec=1751400309 nsec=252485960
        EventBatch gen=1 m=28857 time=3609698458 size=65455
        ProcStatus dt=114 p=0 pstatus=1
...
        String id=239
        	data="runtime.createfing"
        String id=240
        	data="runtime.SetFinalizer"
        String id=241
        	data="net.(*netFD).setAddr"
        String id=242
        	data="runtime.startTheWorldGC"
        
--- FAIL: TestTraceStacks/Default (11.41s)

2025-06-30 19:14 go1.25-linux-amd64-longtest-aliastypeparams release-branch.go1.25@fdd7713f internal/trace.TestTraceStacks/Default (log)

=== RUN   TestTraceStacks/Default
    trace_test.go:499: no match for StateTransition Match=Goroutine Running->Runnable Stack=[]trace_test.frame{trace_test.frame{fn:"main.syncPreemptPoint", line:0}, trace_test.frame{fn:"main.main.func12", line:0}}
    trace_test.go:668: found bad trace; dumping to test log...
    trace_test.go:679: Trace Go1.25
        EventBatch gen=1 m=18446744073709551615 time=38055326935 size=24
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=114 mono=2435540931075 sec=1751400434 nsec=977514543
        EventBatch gen=1 m=311593 time=38057311729 size=372
        ProcStart dt=122 p=2 p_seq=9
...
        String id=237
        	data="net.(*file).readLine"
        String id=238
        	data="net.setDefaultListenerSockopts"
        String id=239
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/net/sockopt_linux.go"
        String id=240
        	data="runtime.gcWaitOnMark"
        
--- FAIL: TestTraceStacks/Default (11.19s)

2025-06-30 23:52 go1.25-linux-amd64-longtest-aliastypeparams release-branch.go1.25@86fca3dc internal/trace.TestTraceStacks/Default (log)

=== RUN   TestTraceStacks/Default
    trace_test.go:499: no match for StateTransition Match=Goroutine Running->Runnable Stack=[]trace_test.frame{trace_test.frame{fn:"main.syncPreemptPoint", line:0}, trace_test.frame{fn:"main.main.func12", line:0}}
    trace_test.go:668: found bad trace; dumping to test log...
    trace_test.go:679: Trace Go1.25
        EventBatch gen=1 m=18446744073709551615 time=6512270004 size=25
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=129 mono=416785288462 sec=1751399301 nsec=873371365
        EventBatch gen=1 m=41721 time=6514424819 size=38
        ProcStart dt=146 p=3 p_seq=1
...
        String id=237
        	data="net.(*netFD).setAddr"
        String id=238
        	data="runtime.traceStartReadCPU"
        String id=239
        	data="syscall.connect"
        String id=240
        	data="syscall.Connect"
        
--- FAIL: TestTraceStacks/Default (9.82s)

2025-07-01 17:07 go1.25-darwin-amd64_12 release-branch.go1.25@2f653a5a internal/trace.TestTraceStacks/Default (log)

=== RUN   TestTraceStacks/Default
    trace_test.go:499: no match for StateTransition Match=Goroutine Running->Runnable Stack=[]trace_test.frame{trace_test.frame{fn:"main.syncPreemptPoint", line:0}, trace_test.frame{fn:"main.main.func12", line:0}}
    trace_test.go:668: found bad trace; dumping to test log...
    trace_test.go:679: Trace Go1.25
        EventBatch gen=1 m=18446744073709551615 time=323265972151 size=25
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=88 mono=20689022223282 sec=1751400020 nsec=329967000
        EventBatch gen=1 m=123145562816512 time=323265977061 size=286
        ProcStart dt=2 p=0 p_seq=4
...
        String id=226
        	data="syscall.getsockopt"
        String id=227
        	data="syscall.GetsockoptInt"
        String id=228
        	data="syscall.Listen"
        String id=229
        	data="net.setKeepAliveIdle"
        
--- FAIL: TestTraceStacks/Default (2.83s)

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

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

2025-07-01 16:11 gotip-linux-amd64-longtest go@6e95fd96 internal/trace.TestTraceStacks/Default (log)

=== RUN   TestTraceStacks/Default
    trace_test.go:499: no match for StateTransition Match=Goroutine Running->Runnable Stack=[]trace_test.frame{trace_test.frame{fn:"main.syncPreemptPoint", line:0}, trace_test.frame{fn:"main.main.func12", line:0}}
    trace_test.go:668: found bad trace; dumping to test log...
    trace_test.go:679: Trace Go1.25
        EventBatch gen=1 m=18446744073709551615 time=2227000688 size=23
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=127 mono=142528052148 sec=1751386913 nsec=11019048
        EventBatch gen=1 m=23706 time=2229189348 size=69
        ProcStart dt=168 p=3 p_seq=10
...
        String id=237
        	data="runtime.forcegchelper"
        String id=238
        	data="runtime.block"
        String id=239
        	data="net.setDefaultListenerSockopts"
        String id=240
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/net/sockopt_linux.go"
        
--- FAIL: TestTraceStacks/Default (7.56s)

2025-07-01 16:11 gotip-linux-amd64-longtest-noswissmap go@6e95fd96 internal/trace.TestTraceStacks/Default (log)

=== RUN   TestTraceStacks/Default
    trace_test.go:499: no match for StateTransition Match=Goroutine Running->Runnable Stack=[]trace_test.frame{trace_test.frame{fn:"main.syncPreemptPoint", line:0}, trace_test.frame{fn:"main.main.func12", line:0}}
    trace_test.go:668: found bad trace; dumping to test log...
    trace_test.go:679: Trace Go1.25
        EventBatch gen=1 m=18446744073709551615 time=2311517483 size=25
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=128 mono=147937127081 sec=1751386935 nsec=725700959
        EventBatch gen=1 m=24946 time=2313403219 size=45
        ProcStart dt=4 p=3 p_seq=8
...
        String id=237
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/time.go"
        String id=238
        	data="main.main.func5"
        String id=239
        	data="internal/poll.(*FD).WaitWrite"
        String id=240
        	data="runtime.forcegchelper"
        
--- FAIL: TestTraceStacks/Default (8.17s)

— watchflakes