internal/trace: TestTraceStacks/AllocFree failures

[gopherbot]

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

Issue created automatically to collect these failures.

Example (log):

=== RUN   TestTraceStacks/AllocFree
    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=21526743195 size=26
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=66028 mono=1377715789992 sec=1751058383 nsec=970828722
        ExperimentalBatch exp=1 gen=1 m=18446744073709551615 time=21526810000
        	data="\x01\x80\x80\x80\x80\x80\x18\x80@\b\x80\x10"
...
        String id=237
        	data="runtime.traceLocker.GoUnpark"
        String id=238
        	data="runtime.injectglist"
        String id=239
        	data="runtime.bgsweep"
        String id=240
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/mgcsweep.go"
        
--- FAIL: TestTraceStacks/AllocFree (2.01s)

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

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

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

=== RUN   TestTraceStacks/AllocFree
    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=21526743195 size=26
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=66028 mono=1377715789992 sec=1751058383 nsec=970828722
        ExperimentalBatch exp=1 gen=1 m=18446744073709551615 time=21526810000
        	data="\x01\x80\x80\x80\x80\x80\x18\x80@\b\x80\x10"
...
        String id=237
        	data="runtime.traceLocker.GoUnpark"
        String id=238
        	data="runtime.injectglist"
        String id=239
        	data="runtime.bgsweep"
        String id=240
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/mgcsweep.go"
        
--- FAIL: TestTraceStacks/AllocFree (2.01s)

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

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

2025-06-30 16:00 gotip-linux-amd64-longtest-noswissmap go@03ad694d internal/trace.TestTraceStacks/AllocFree (log)

=== RUN   TestTraceStacks/AllocFree
    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=10432767308 size=24
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=131 mono=667697116040 sec=1751300146 nsec=218277355
        ExperimentalBatch exp=1 gen=1 m=18446744073709551615 time=10432767947
        	data="\x01\x80\x80\x80\x80\x80\x18\x80@\b\x80\x10"
...
        String id=237
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/mgcsweep.go"
        String id=238
        	data="runtime.updateMaxProcsGoroutine"
        String id=239
        	data="syscall.getsockopt"
        String id=240
        	data="syscall.GetsockoptInt"
        
--- FAIL: TestTraceStacks/AllocFree (4.06s)

2025-06-30 16:31 gotip-linux-amd64-longtest go@47318323 internal/trace.TestTraceStacks/AllocFree (log)

=== RUN   TestTraceStacks/AllocFree
    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=12937011216 size=23
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=125 mono=827968725758 sec=1751302144 nsec=236294488
        ExperimentalBatch exp=1 gen=1 m=18446744073709551615 time=12937011789
        	data="\x01\x80\x80\x80\x80\x80\x18\x80@\b\x80\x10"
...
        String id=244
        	data="io.ReadFull"
        String id=245
        	data="net.(*file).readLine"
        String id=246
        	data="time.Sleep"
        String id=247
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/time.go"
        
--- FAIL: TestTraceStacks/AllocFree (2.74s)

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

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

2025-06-30 17:44 gotip-linux-amd64-longtest-aliastypeparams go@9ae38be3 internal/trace.TestTraceStacks/AllocFree (log)

=== RUN   TestTraceStacks/AllocFree
    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=2281330242 size=24
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=127 mono=146005143593 sec=1751306565 nsec=642537769
        ExperimentalBatch exp=1 gen=1 m=18446744073709551615 time=2281330866
        	data="\x01\x80\x80\x80\x80\x80\x18\x80@\b\x80\x10"
...
        String id=250
        	data="io.ReadAtLeast"
        String id=251
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/io/io.go"
        String id=252
        	data="io.ReadFull"
        String id=253
        	data="net.(*file).readLine"
        
--- FAIL: TestTraceStacks/AllocFree (1.48s)

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

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

2025-06-30 23:52 gotip-linux-amd64-longtest-noswissmap go@6bd9944c internal/trace.TestTraceStacks/AllocFree (log)

=== RUN   TestTraceStacks/AllocFree
    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=2526532060 size=24
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=142 mono=161698060873 sec=1751328568 nsec=126554427
        ExperimentalBatch exp=1 gen=1 m=18446744073709551615 time=2526533464
        	data="\x01\x80\x80\x80\x80\x80\x18\x80@\b\x80\x10"
...
        String id=237
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/mfinal.go"
        String id=238
        	data="runtime.createfing"
        String id=239
        	data="runtime.SetFinalizer"
        String id=240
        	data="net.(*netFD).setAddr"
        
--- FAIL: TestTraceStacks/AllocFree (1.89s)

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

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

2025-07-01 17:07 go1.25-linux-arm64-longtest release-branch.go1.25@2f653a5a internal/trace.TestTraceStacks/AllocFree (log)

=== RUN   TestTraceStacks/AllocFree
    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=8929047050 size=23
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=73 mono=571459015868 sec=1751398229 nsec=266429868
        ExperimentalBatch exp=1 gen=1 m=18446744073709551615 time=8929047287
        	data="\x01\x80\x80\x80\x80\x80\b\x80@\b\x80\x10"
...
        String id=237
        	data="syscall.connect"
        String id=238
        	data="syscall.Connect"
        String id=239
        	data="runtime.forcegchelper"
        String id=240
        	data="sync.(*Mutex).Lock"
        
--- FAIL: TestTraceStacks/AllocFree (1.19s)

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

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

2025-06-28 01:17 go1.25-linux-amd64-longtest-noswissmap release-branch.go1.25@b51f1cdb internal/trace.TestTraceStacks/AllocFree (log)

=== RUN   TestTraceStacks/AllocFree
    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=63583888133 size=25
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=140 mono=4069368849453 sec=1751401731 nsec=482043055
        ExperimentalBatch exp=1 gen=1 m=18446744073709551615 time=63583888767
        	data="\x01\x80\x80\x80\x80\x80\x18\x80@\b\x80\x10"
...
        String id=242
        	data="net.(*file).close"
        String id=243
        	data="sync.(*Mutex).Lock"
        String id=244
        	data="runtime.updateMaxProcsGoroutine"
        String id=245
        	data="runtime.gcBgMarkStartWorkers"
        
--- FAIL: TestTraceStacks/AllocFree (2.64s)

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

=== RUN   TestTraceStacks/AllocFree
    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=3698888547 size=25
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=138 mono=236728875803 sec=1751400314 nsec=960666846
        ExperimentalBatch exp=1 gen=1 m=18446744073709551615 time=3698889133
        	data="\x01\x80\x80\x80\x80\x80\x18\x80@\b\x80\x10"
...
        String id=244
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/io/io.go"
        String id=245
        	data="io.ReadFull"
        String id=246
        	data="net.(*file).readLine"
        String id=247
        	data="runtime.startTheWorldGC"
        
--- FAIL: TestTraceStacks/AllocFree (1.77s)

2025-06-30 17:44 go1.25-linux-amd64-longtest-aliastypeparams release-branch.go1.25@9ae38be3 internal/trace.TestTraceStacks/AllocFree (log)

=== RUN   TestTraceStacks/AllocFree
    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=24647784039 size=24
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=278 mono=1577458185850 sec=1751400452 nsec=23293544
        ExperimentalBatch exp=1 gen=1 m=18446744073709551615 time=24647784739
        	data="\x01\x80\x80\x80\x80\x80\x18\x80@\b\x80\x10"
...
        String id=244
        	data="io.ReadAtLeast"
        String id=245
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/io/io.go"
        String id=246
        	data="io.ReadFull"
        String id=247
        	data="net.(*file).readLine"
        
--- FAIL: TestTraceStacks/AllocFree (2.12s)

2025-06-30 20:32 go1.25-linux-amd64-longtest-noswissmap release-branch.go1.25@8002d283 internal/trace.TestTraceStacks/AllocFree (log)

=== RUN   TestTraceStacks/AllocFree
    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=38349028839 size=24
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=122 mono=2454337853314 sec=1751400463 nsec=575102952
        ExperimentalBatch exp=1 gen=1 m=18446744073709551615 time=38349029430
        	data="\x01\x80\x80\x80\x80\x80\x18\x80@\b\x80\x10"
...
        String id=244
        	data="runtime.SetFinalizer"
        String id=245
        	data="net.(*netFD).setAddr"
        String id=246
        	data="runtime.startTheWorldGC"
        String id=247
        	data="runtime.gcWaitOnMark"
        
--- FAIL: TestTraceStacks/AllocFree (2.46s)

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

=== RUN   TestTraceStacks/AllocFree
    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=2925252491 size=24
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=126 mono=187216167481 sec=1751399070 nsec=592626293
        ExperimentalBatch exp=1 gen=1 m=18446744073709551615 time=2925253082
        	data="\x01\x80\x80\x80\x80\x80\x18\x80@\b\x80\x10"
...
        String id=237
        	data="syscall.accept4"
        String id=238
        	data="syscall.Accept4"
        String id=239
        	data="internal/poll.accept"
        String id=240
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/internal/poll/sock_cloexec.go"
        
--- FAIL: TestTraceStacks/AllocFree (2.19s)

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

=== RUN   TestTraceStacks/AllocFree
    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=6564853976 size=24
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=164 mono=420150664943 sec=1751399305 nsec=238747833
        ExperimentalBatch exp=1 gen=1 m=18446744073709551615 time=6564854677
        	data="\x01\x80\x80\x80\x80\x80\x18\x80@\b\x80\x10"
...
        String id=240
        	data="internal/poll.(*FD).WaitWrite"
        String id=241
        	data="sync.(*Mutex).Unlock"
        String id=242
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/sync/cond.go"
        String id=243
        	data="sync.(*Cond).Signal"
        
--- FAIL: TestTraceStacks/AllocFree (1.58s)

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

=== RUN   TestTraceStacks/AllocFree
    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=21319641468 size=24
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=132 mono=1364457062374 sec=1751399367 nsec=212887693
        ExperimentalBatch exp=1 gen=1 m=18446744073709551615 time=21319642064
        	data="\x01\x80\x80\x80\x80\x80\x18\x80@\b\x80\x10"
...
        String id=237
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/os/pipe2_unix.go"
        String id=238
        	data="runtime.traceStartReadCPU"
        String id=239
        	data="internal/poll.(*FD).WaitWrite"
        String id=240
        	data="sync.(*Mutex).Unlock"
        
--- FAIL: TestTraceStacks/AllocFree (3.17s)

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

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

2025-07-01 17:07 gotip-linux-amd64-longtest go@2f653a5a internal/trace.TestTraceStacks/AllocFree (log)

=== RUN   TestTraceStacks/AllocFree
    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=6633892548 size=25
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=128 mono=424569131224 sec=1751390371 nsec=605714807
        ExperimentalBatch exp=1 gen=1 m=18446744073709551615 time=6633893130
        	data="\x01\x80\x80\x80\x80\x80\x18\x80@\b\x80\x10"
...
        String id=240
        	data="runtime.bgsweep"
        String id=241
        	data="/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/mgcsweep.go"
        String id=242
        	data="sync.(*WaitGroup).Add"
        String id=243
        	data="sync.(*WaitGroup).Done"
        
--- FAIL: TestTraceStacks/AllocFree (2.12s)

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

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

2025-07-01 21:05 gotip-linux-amd64-longtest-aliastypeparams go@de646d94 internal/trace.TestTraceStacks/AllocFree (log)

=== RUN   TestTraceStacks/AllocFree
    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=17163541715 size=23
        Sync
        Frequency freq=15625000
        ClockSnapshot dt=127 mono=1098466677837 sec=1751404489 nsec=84511491
        ExperimentalBatch exp=1 gen=1 m=18446744073709551615 time=17163542367
        	data="\x01\x80\x80\x80\x80\x80\x18\x80@\b\x80\x10"
...
        String id=237
        	data="os.ignoringEINTR"
        String id=238
        	data="sync.(*Cond).Signal"
        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/AllocFree (2.46s)

— watchflakes

[cherrymui]

Dup of #74417