go icon indicating copy to clipboard operation
go copied to clipboard
Published 3 weeks ago • verified publisher icon golang

runtime: TestTraceGCSTW failures

Open gopherbot opened this issue 1 month ago • 3 comments 

#!watchflakes
default <- pkg == "runtime" && test == "TestTraceGCSTW"

Issue created automatically to collect these failures.

Example (log):

=== RUN   TestTraceGCSTW
    proc_test.go:1275: Run 0
    proc_test.go:1282: /home/swarming/.swarming/w/ir/x/t/go-build3898362297/testprog.exe TraceGCSTW (39.772652ms): ok
    proc_test.go:1339: Event: M=-1 P=-1 G=-1 Sync Time=424639844096 N=1 Trace=424639867456 Mono=424639867442 Wall=2025-11-20T16:24:27.42930533Z
    proc_test.go:1339: Event: M=98668 P=-1 G=-1 StateTransition Time=424639879744 ProcID=0 Undetermined->Running Reason=""
    proc_test.go:1339: Event: M=98668 P=0 G=-1 StateTransition Time=424639880064 GoID=1 Undetermined->Running Reason=""
    proc_test.go:1339: Event: M=98668 P=0 G=1 Metric Time=424639897216 Name="/sched/gomaxprocs:threads" Value=Value{Uint64(8)}
        Stack=
        	runtime.traceLocker.Gomaxprocs @ 0x80d58d9
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/traceruntime.go:289
...
    proc_test.go:1455: Event: M=99237 P=7 G=1 Log Time=429515486208 Task=0 Category="TraceSTW" Message="end"
        Stack=
        	main.TraceGCSTW @ 0x8175aee
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/testdata/testprog/stw_trace.go:136
        	main.main @ 0x816e32d
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/testdata/testprog/main.go:34
    proc_test.go:1544: Found end message
    proc_test.go:1268: Errors: 18/50 = 36.000000%
    proc_test.go:1270: Error rate too high
--- FAIL: TestTraceGCSTW (4.94s)

— watchflakes

gopherbot avatar Nov 27 '25 18:11 gopherbot

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "runtime" && test == "TestTraceGCSTW"
2025-11-20 16:10 gotip-linux-386-longtest go@a18aff80 runtime.TestTraceGCSTW (log) 
=== RUN   TestTraceGCSTW
    proc_test.go:1275: Run 0
    proc_test.go:1282: /home/swarming/.swarming/w/ir/x/t/go-build3898362297/testprog.exe TraceGCSTW (39.772652ms): ok
    proc_test.go:1339: Event: M=-1 P=-1 G=-1 Sync Time=424639844096 N=1 Trace=424639867456 Mono=424639867442 Wall=2025-11-20T16:24:27.42930533Z
    proc_test.go:1339: Event: M=98668 P=-1 G=-1 StateTransition Time=424639879744 ProcID=0 Undetermined->Running Reason=""
    proc_test.go:1339: Event: M=98668 P=0 G=-1 StateTransition Time=424639880064 GoID=1 Undetermined->Running Reason=""
    proc_test.go:1339: Event: M=98668 P=0 G=1 Metric Time=424639897216 Name="/sched/gomaxprocs:threads" Value=Value{Uint64(8)}
        Stack=
        	runtime.traceLocker.Gomaxprocs @ 0x80d58d9
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/traceruntime.go:289
...
    proc_test.go:1455: Event: M=99237 P=7 G=1 Log Time=429515486208 Task=0 Category="TraceSTW" Message="end"
        Stack=
        	main.TraceGCSTW @ 0x8175aee
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/testdata/testprog/stw_trace.go:136
        	main.main @ 0x816e32d
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/testdata/testprog/main.go:34
    proc_test.go:1544: Found end message
    proc_test.go:1268: Errors: 18/50 = 36.000000%
    proc_test.go:1270: Error rate too high
--- FAIL: TestTraceGCSTW (4.94s)
2025-11-20 17:19 gotip-linux-386-longtest go@32f5aadd runtime.TestTraceGCSTW (log) 
=== RUN   TestTraceGCSTW
    proc_test.go:1275: Run 0
    proc_test.go:1282: /home/swarming/.swarming/w/ir/x/t/go-build1298642080/testprog.exe TraceGCSTW (75.401257ms): ok
    proc_test.go:1339: Event: M=-1 P=-1 G=-1 Sync Time=368243966720 N=1 Trace=368244018432 Mono=368244018389 Wall=2025-11-20T17:34:45.629240737Z
    proc_test.go:1339: Event: M=84259 P=-1 G=-1 StateTransition Time=368244032576 ProcID=0 Undetermined->Running Reason=""
    proc_test.go:1339: Event: M=84259 P=0 G=-1 StateTransition Time=368244033216 GoID=1 Undetermined->Running Reason=""
    proc_test.go:1339: Event: M=84259 P=0 G=1 Metric Time=368244061184 Name="/sched/gomaxprocs:threads" Value=Value{Uint64(8)}
        Stack=
        	runtime.traceLocker.Gomaxprocs @ 0x80d5fd9
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/traceruntime.go:289
...
        	data="runtime.gcTrigger.test"
        String id=130
        	data="runtime.mallocgcSmallScanNoHeaderSC2"
        EndOfGeneration
        
    helpers.go:39: Convert this to a raw trace with `go test internal/trace/testtrace -convert in.tracetxt -out out.trace`
    proc_test.go:1262: Run 49 failed: P ran incorrect goroutine
    proc_test.go:1268: Errors: 25/50 = 50.000000%
    proc_test.go:1270: Error rate too high
--- FAIL: TestTraceGCSTW (5.05s)
2025-11-20 18:14 gotip-linux-amd64-longtest-race go@a49b0302 runtime.TestTraceGCSTW (log) 
=== RUN   TestTraceGCSTW
    proc_test.go:1275: Run 0
    proc_test.go:1282: /home/swarming/.swarming/w/ir/x/t/go-build1681907029/testprog.exe TraceGCSTW (47.978838ms): ok
    proc_test.go:1339: Event: M=-1 P=-1 G=-1 Sync Time=789551959616 N=1 Trace=789551980544 Mono=789551980540 Wall=2025-11-20T18:38:15.38408406Z
    proc_test.go:1339: Event: M=119251 P=-1 G=-1 StateTransition Time=789551989760 ProcID=0 Undetermined->Running Reason=""
    proc_test.go:1339: Event: M=119251 P=0 G=-1 StateTransition Time=789551990208 GoID=1 Undetermined->Running Reason=""
    proc_test.go:1339: Event: M=119251 P=0 G=1 Metric Time=789552043456 Name="/sched/gomaxprocs:threads" Value=Value{Uint64(8)}
        Stack=
        	runtime.traceLocker.Gomaxprocs @ 0x4b2f83
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/traceruntime.go:289
...
        	data="runtime.updateMaxProcsGoroutine"
        String id=128
        	data="runtime.initMetrics"
        EndOfGeneration
        
    helpers.go:39: Convert this to a raw trace with `go test internal/trace/testtrace -convert in.tracetxt -out out.trace`
    proc_test.go:1262: Run 49 failed: P ran incorrect goroutine
    proc_test.go:1268: Errors: 16/50 = 32.000000%
    proc_test.go:1270: Error rate too high
--- FAIL: TestTraceGCSTW (6.19s)
2025-11-20 19:05 gotip-linux-amd64-longtest-race go@4b740af5 runtime.TestTraceGCSTW (log) 
=== RUN   TestTraceGCSTW
    proc_test.go:1275: Run 0
    proc_test.go:1282: /home/swarming/.swarming/w/ir/x/t/go-build2482108105/testprog.exe TraceGCSTW (49.115105ms): ok
    proc_test.go:1339: Event: M=-1 P=-1 G=-1 Sync Time=801016743744 N=1 Trace=801016765056 Mono=801016765021 Wall=2025-11-20T19:28:35.742171507Z
    proc_test.go:1339: Event: M=119416 P=-1 G=-1 StateTransition Time=801016774336 ProcID=0 Undetermined->Running Reason=""
    proc_test.go:1339: Event: M=119416 P=0 G=-1 StateTransition Time=801016774720 GoID=1 Undetermined->Running Reason=""
    proc_test.go:1339: Event: M=119416 P=0 G=1 Metric Time=801016816128 Name="/sched/gomaxprocs:threads" Value=Value{Uint64(8)}
        Stack=
        	runtime.traceLocker.Gomaxprocs @ 0x4b2f83
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/traceruntime.go:289
...
    proc_test.go:1455: Event: M=119980 P=1 G=1 Log Time=807699598912 Task=0 Category="TraceSTW" Message="end"
        Stack=
        	main.TraceGCSTW @ 0x5b192a
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/testdata/testprog/stw_trace.go:136
        	main.main @ 0x5a7dcb
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/testdata/testprog/main.go:34
    proc_test.go:1544: Found end message
    proc_test.go:1268: Errors: 13/50 = 26.000000%
    proc_test.go:1270: Error rate too high
--- FAIL: TestTraceGCSTW (6.78s)
2025-11-20 22:25 gotip-linux-386-longtest go@ff654ea1 runtime.TestTraceGCSTW (log) 
=== RUN   TestTraceGCSTW
    proc_test.go:1275: Run 0
    proc_test.go:1282: /home/swarming/.swarming/w/ir/x/t/go-build3900539204/testprog.exe TraceGCSTW (47.661828ms): ok
    proc_test.go:1339: Event: M=-1 P=-1 G=-1 Sync Time=380501421440 N=1 Trace=380501447872 Mono=380501447843 Wall=2025-11-20T22:39:38.909628572Z
    proc_test.go:1339: Event: M=91226 P=-1 G=-1 StateTransition Time=380501459584 ProcID=0 Undetermined->Running Reason=""
    proc_test.go:1339: Event: M=91226 P=0 G=-1 StateTransition Time=380501459968 GoID=1 Undetermined->Running Reason=""
    proc_test.go:1339: Event: M=91226 P=0 G=1 Metric Time=380501482048 Name="/sched/gomaxprocs:threads" Value=Value{Uint64(8)}
        Stack=
        	runtime.traceLocker.Gomaxprocs @ 0x80d5fd9
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/traceruntime.go:289
...
    proc_test.go:1455: Event: M=91774 P=5 G=1 Log Time=385676584448 Task=0 Category="TraceSTW" Message="end"
        Stack=
        	main.TraceGCSTW @ 0x817652e
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/testdata/testprog/stw_trace.go:136
        	main.main @ 0x816ed6d
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/testdata/testprog/main.go:34
    proc_test.go:1544: Found end message
    proc_test.go:1268: Errors: 18/50 = 36.000000%
    proc_test.go:1270: Error rate too high
--- FAIL: TestTraceGCSTW (5.23s)
2025-11-20 22:42 gotip-linux-386-longtest go@8c319597 runtime.TestTraceGCSTW (log) 
=== RUN   TestTraceGCSTW
    proc_test.go:1275: Run 0
    proc_test.go:1282: /home/swarming/.swarming/w/ir/x/t/go-build2154522934/testprog.exe TraceGCSTW (47.149623ms): ok
    proc_test.go:1339: Event: M=-1 P=-1 G=-1 Sync Time=1441780558144 N=1 Trace=1441780583936 Mono=1441780583908 Wall=2025-11-20T22:54:27.192744006Z
    proc_test.go:1339: Event: M=116835 P=-1 G=-1 StateTransition Time=1441780594496 ProcID=0 Undetermined->Running Reason=""
    proc_test.go:1339: Event: M=116835 P=0 G=-1 StateTransition Time=1441780594880 GoID=1 Undetermined->Running Reason=""
    proc_test.go:1339: Event: M=116835 P=0 G=1 Metric Time=1441780609408 Name="/sched/gomaxprocs:threads" Value=Value{Uint64(8)}
        Stack=
        	runtime.traceLocker.Gomaxprocs @ 0x80d5fd9
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/traceruntime.go:289
...
    proc_test.go:1455: Event: M=117547 P=6 G=1 Log Time=1446755954944 Task=0 Category="TraceSTW" Message="end"
        Stack=
        	main.TraceGCSTW @ 0x817652e
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/testdata/testprog/stw_trace.go:136
        	main.main @ 0x816ed6d
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/testdata/testprog/main.go:34
    proc_test.go:1544: Found end message
    proc_test.go:1268: Errors: 17/50 = 34.000000%
    proc_test.go:1270: Error rate too high
--- FAIL: TestTraceGCSTW (5.02s)
2025-11-20 22:44 gotip-linux-386-longtest go@1bc54868 runtime.TestTraceGCSTW (log) 
=== RUN   TestTraceGCSTW
    proc_test.go:1275: Run 0
    proc_test.go:1282: /home/swarming/.swarming/w/ir/x/t/go-build307376323/testprog.exe TraceGCSTW (43.611826ms): ok
    proc_test.go:1339: Event: M=-1 P=-1 G=-1 Sync Time=307088857152 N=1 Trace=307088880704 Mono=307088880640 Wall=2025-11-20T22:56:42.546942022Z
    proc_test.go:1339: Event: M=80983 P=-1 G=-1 StateTransition Time=307088891136 ProcID=0 Undetermined->Running Reason=""
    proc_test.go:1339: Event: M=80983 P=0 G=-1 StateTransition Time=307088891584 GoID=1 Undetermined->Running Reason=""
    proc_test.go:1339: Event: M=80983 P=0 G=1 Metric Time=307088910080 Name="/sched/gomaxprocs:threads" Value=Value{Uint64(8)}
        Stack=
        	runtime.traceLocker.Gomaxprocs @ 0x80d5fd9
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/traceruntime.go:289
...
    proc_test.go:1455: Event: M=81698 P=6 G=1 Log Time=312080733504 Task=0 Category="TraceSTW" Message="end"
        Stack=
        	main.TraceGCSTW @ 0x817652e
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/testdata/testprog/stw_trace.go:136
        	main.main @ 0x816ed6d
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/testdata/testprog/main.go:34
    proc_test.go:1544: Found end message
    proc_test.go:1268: Errors: 17/50 = 34.000000%
    proc_test.go:1270: Error rate too high
--- FAIL: TestTraceGCSTW (5.06s)
2025-11-21 01:47 gotip-linux-386-longtest go@4d26d66a runtime.TestTraceGCSTW (log) 
=== RUN   TestTraceGCSTW
    proc_test.go:1275: Run 0
    proc_test.go:1282: /home/swarming/.swarming/w/ir/x/t/go-build689603926/testprog.exe TraceGCSTW (148.646719ms): ok
    proc_test.go:1339: Event: M=-1 P=-1 G=-1 Sync Time=2642178366208 N=1 Trace=2642178427136 Mono=2642178427092 Wall=2025-11-24T21:56:23.36023862Z
    proc_test.go:1339: Event: M=550349 P=-1 G=-1 StateTransition Time=2642178439168 ProcID=0 Undetermined->Running Reason=""
    proc_test.go:1339: Event: M=550349 P=0 G=-1 StateTransition Time=2642178439680 GoID=1 Undetermined->Running Reason=""
    proc_test.go:1339: Event: M=550349 P=0 G=1 Metric Time=2642178481152 Name="/sched/gomaxprocs:threads" Value=Value{Uint64(8)}
        Stack=
        	runtime.traceLocker.Gomaxprocs @ 0x80d60a9
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/traceruntime.go:289
...
    proc_test.go:1455: Event: M=552132 P=5 G=1 Log Time=2650881138112 Task=0 Category="TraceSTW" Message="end"
        Stack=
        	main.TraceGCSTW @ 0x81765fe
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/testdata/testprog/stw_trace.go:136
        	main.main @ 0x816ee3d
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/testdata/testprog/main.go:34
    proc_test.go:1544: Found end message
    proc_test.go:1268: Errors: 17/50 = 34.000000%
    proc_test.go:1270: Error rate too high
--- FAIL: TestTraceGCSTW (8.78s)
2025-11-21 19:31 gotip-linux-386-longtest go@3fdd183a runtime.TestTraceGCSTW (log) 
=== RUN   TestTraceGCSTW
    proc_test.go:1275: Run 0
    proc_test.go:1282: /home/swarming/.swarming/w/ir/x/t/go-build1299358831/testprog.exe TraceGCSTW (43.360629ms): ok
    proc_test.go:1339: Event: M=-1 P=-1 G=-1 Sync Time=297767335488 N=1 Trace=297767366720 Mono=297767366710 Wall=2025-11-24T21:53:17.718710859Z
    proc_test.go:1339: Event: M=76708 P=-1 G=-1 StateTransition Time=297767379840 ProcID=0 Undetermined->Running Reason=""
    proc_test.go:1339: Event: M=76708 P=0 G=-1 StateTransition Time=297767380352 GoID=1 Undetermined->Running Reason=""
    proc_test.go:1339: Event: M=76708 P=0 G=1 Metric Time=297767407040 Name="/sched/gomaxprocs:threads" Value=Value{Uint64(8)}
        Stack=
        	runtime.traceLocker.Gomaxprocs @ 0x80d60a9
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/traceruntime.go:289
...
    proc_test.go:1455: Event: M=80683 P=7 G=1 Log Time=310747845632 Task=0 Category="TraceSTW" Message="end"
        Stack=
        	main.TraceGCSTW @ 0x81765fe
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/testdata/testprog/stw_trace.go:136
        	main.main @ 0x816ee3d
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/testdata/testprog/main.go:34
    proc_test.go:1544: Found end message
    proc_test.go:1268: Errors: 18/50 = 36.000000%
    proc_test.go:1270: Error rate too high
--- FAIL: TestTraceGCSTW (13.04s)
2025-11-21 21:14 gotip-linux-386-longtest go@da92168e runtime.TestTraceGCSTW (log) 
=== RUN   TestTraceGCSTW
    proc_test.go:1275: Run 0
    proc_test.go:1282: /home/swarming/.swarming/w/ir/x/t/go-build161289073/testprog.exe TraceGCSTW (58.766558ms): ok
    proc_test.go:1339: Event: M=-1 P=-1 G=-1 Sync Time=2431494296256 N=1 Trace=2431494320128 Mono=2431494320095 Wall=2025-11-24T21:52:51.468409463Z
    proc_test.go:1339: Event: M=577598 P=-1 G=-1 StateTransition Time=2431494329792 ProcID=0 Undetermined->Running Reason=""
    proc_test.go:1339: Event: M=577598 P=0 G=-1 StateTransition Time=2431494330112 GoID=1 Undetermined->Running Reason=""
    proc_test.go:1339: Event: M=577598 P=0 G=1 Metric Time=2431494357952 Name="/sched/gomaxprocs:threads" Value=Value{Uint64(8)}
        Stack=
        	runtime.traceLocker.Gomaxprocs @ 0x80d60a9
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/traceruntime.go:289
...
    proc_test.go:1455: Event: M=581553 P=2 G=1 Log Time=2444097623808 Task=0 Category="TraceSTW" Message="end"
        Stack=
        	main.TraceGCSTW @ 0x81765fe
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/testdata/testprog/stw_trace.go:136
        	main.main @ 0x816ee3d
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/testdata/testprog/main.go:34
    proc_test.go:1544: Found end message
    proc_test.go:1268: Errors: 18/50 = 36.000000%
    proc_test.go:1270: Error rate too high
--- FAIL: TestTraceGCSTW (12.69s)
2025-11-21 21:14 gotip-linux-amd64-longtest-race go@da92168e runtime.TestTraceGCSTW (log) 
=== RUN   TestTraceGCSTW
    proc_test.go:1275: Run 0
    proc_test.go:1282: /home/swarming/.swarming/w/ir/x/t/go-build86956571/testprog.exe TraceGCSTW (49.457498ms): ok
    proc_test.go:1339: Event: M=-1 P=-1 G=-1 Sync Time=15351988123904 N=1 Trace=15351988145984 Mono=15351988145959 Wall=2025-11-24T22:41:51.113762685Z
    proc_test.go:1339: Event: M=455505 P=-1 G=-1 StateTransition Time=15351988155456 ProcID=0 Undetermined->Running Reason=""
    proc_test.go:1339: Event: M=455505 P=0 G=-1 StateTransition Time=15351988155776 GoID=1 Undetermined->Running Reason=""
    proc_test.go:1339: Event: M=455505 P=0 G=1 Metric Time=15351988207872 Name="/sched/gomaxprocs:threads" Value=Value{Uint64(8)}
        Stack=
        	runtime.traceLocker.Gomaxprocs @ 0x4b4623
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/traceruntime.go:289
...
    proc_test.go:1455: Event: M=456082 P=7 G=1 Log Time=15358807023616 Task=0 Category="TraceSTW" Message="end"
        Stack=
        	main.TraceGCSTW @ 0x5b3b6a
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/testdata/testprog/stw_trace.go:136
        	main.main @ 0x5a9fcb
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/testdata/testprog/main.go:34
    proc_test.go:1544: Found end message
    proc_test.go:1268: Errors: 13/50 = 26.000000%
    proc_test.go:1270: Error rate too high
--- FAIL: TestTraceGCSTW (6.90s)
2025-11-24 15:54 gotip-linux-386-longtest go@0c69e773 runtime.TestTraceGCSTW (log) 
=== RUN   TestTraceGCSTW
    proc_test.go:1275: Run 0
    proc_test.go:1282: /home/swarming/.swarming/w/ir/x/t/go-build1978268604/testprog.exe TraceGCSTW (48.286934ms): ok
    proc_test.go:1339: Event: M=-1 P=-1 G=-1 Sync Time=1702278984128 N=1 Trace=1702279027840 Mono=1702279027786 Wall=2025-11-24T21:36:31.889601134Z
    proc_test.go:1339: Event: M=263941 P=-1 G=-1 StateTransition Time=1702279045184 ProcID=0 Undetermined->Running Reason=""
    proc_test.go:1339: Event: M=263941 P=0 G=-1 StateTransition Time=1702279045824 GoID=1 Undetermined->Running Reason=""
    proc_test.go:1339: Event: M=263941 P=0 G=1 Metric Time=1702279068736 Name="/sched/gomaxprocs:threads" Value=Value{Uint64(8)}
        Stack=
        	runtime.traceLocker.Gomaxprocs @ 0x80d60a9
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/traceruntime.go:289
...
        	data="runtime.traceAdvance.func1"
        String id=150
        	data="runtime.forEachGRace"
        EndOfGeneration
        
    helpers.go:39: Convert this to a raw trace with `go test internal/trace/testtrace -convert in.tracetxt -out out.trace`
    proc_test.go:1262: Run 49 failed: P ran incorrect goroutine
    proc_test.go:1268: Errors: 24/50 = 48.000000%
    proc_test.go:1270: Error rate too high
--- FAIL: TestTraceGCSTW (6.28s)
2025-11-24 15:54 gotip-linux-amd64-longtest-race go@0c69e773 runtime.TestTraceGCSTW (log) 
=== RUN   TestTraceGCSTW
    proc_test.go:1275: Run 0
    proc_test.go:1282: /home/swarming/.swarming/w/ir/x/t/go-build4068673781/testprog.exe TraceGCSTW (54.445559ms): ok
    proc_test.go:1339: Event: M=-1 P=-1 G=-1 Sync Time=1984038904320 N=1 Trace=1984038928960 Mono=1984038928906 Wall=2025-11-24T22:13:32.019159066Z
    proc_test.go:1339: Event: M=463167 P=-1 G=-1 StateTransition Time=1984038938496 ProcID=0 Undetermined->Running Reason=""
    proc_test.go:1339: Event: M=463167 P=0 G=-1 StateTransition Time=1984038938752 GoID=1 Undetermined->Running Reason=""
    proc_test.go:1339: Event: M=463167 P=0 G=1 Metric Time=1984038990336 Name="/sched/gomaxprocs:threads" Value=Value{Uint64(8)}
        Stack=
        	runtime.traceLocker.Gomaxprocs @ 0x4b4563
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/traceruntime.go:289
...
    proc_test.go:1455: Event: M=463744 P=5 G=1 Log Time=1990275772480 Task=0 Category="TraceSTW" Message="end"
        Stack=
        	main.TraceGCSTW @ 0x5b3a2a
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/testdata/testprog/stw_trace.go:136
        	main.main @ 0x5a9e8b
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/testdata/testprog/main.go:34
    proc_test.go:1544: Found end message
    proc_test.go:1268: Errors: 17/50 = 34.000000%
    proc_test.go:1270: Error rate too high
--- FAIL: TestTraceGCSTW (6.36s)

— watchflakes

gopherbot avatar Nov 27 '25 18:11 gopherbot

Fixed in https://go.dev/cl/722520

prattmic avatar Dec 03 '25 21:12 prattmic

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "runtime" && test == "TestTraceGCSTW"
2025-12-05 19:22 go1.26-linux-amd64-longtest release-branch.go1.26@44cb8244 runtime.TestTraceGCSTW (log) 
=== RUN   TestTraceGCSTW
    proc_test.go:1275: Run 0
    proc_test.go:1282: /home/swarming/.swarming/w/ir/x/t/go-build2369269626/testprog.exe TraceGCSTW (377.131604ms): ok
    proc_test.go:1341: Event: M=-1 P=-1 G=-1 Sync Time=2146530351552 N=1 Trace=2146534085632 Mono=2146534085578 Wall=2025-12-05T23:17:05.08720444Z
    proc_test.go:1341: Event: M=664663 P=-1 G=-1 StateTransition Time=2146534098880 ProcID=0 Undetermined->Running Reason=""
    proc_test.go:1341: Event: M=664663 P=0 G=-1 StateTransition Time=2146534099328 GoID=1 Undetermined->Running Reason=""
    proc_test.go:1341: Event: M=664663 P=0 G=1 Metric Time=2146534109056 Name="/sched/gomaxprocs:threads" Value=Value{Uint64(8)}
        Stack=
        	runtime.traceLocker.Gomaxprocs @ 0x487b63
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/traceruntime.go:282
...
        	data="runtime.bgscavenge"
        String id=134
        	data="runtime.(*traceAdvancerState).start"
        EndOfGeneration
        
    helpers.go:39: Convert this to a raw trace with `go test internal/trace/testtrace -convert in.tracetxt -out out.trace`
    proc_test.go:1262: Run 49 failed: P did not remain on M
    proc_test.go:1268: Errors: 14/50 = 28.000000%
    proc_test.go:1270: Error rate too high
--- FAIL: TestTraceGCSTW (34.04s)

— watchflakes

gopherbot avatar Dec 06 '25 00:12 gopherbot

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "runtime" && test == "TestTraceGCSTW"
2025-12-09 16:51 go1.26-linux-amd64-longtest release-branch.go1.26@1274d58d runtime.TestTraceGCSTW (log) 
=== RUN   TestTraceGCSTW
    proc_test.go:1275: Run 0
    proc_test.go:1282: /home/swarming/.swarming/w/ir/x/t/go-build3301571503/testprog.exe TraceGCSTW (164.656165ms): ok
    proc_test.go:1341: Event: M=-1 P=-1 G=-1 Sync Time=12260815479296 N=1 Trace=12260817863424 Mono=12260817863386 Wall=2025-12-16T01:49:32.166416704Z
    proc_test.go:1341: Event: M=2484673 P=-1 G=-1 StateTransition Time=12260817876544 ProcID=0 Undetermined->Running Reason=""
    proc_test.go:1341: Event: M=2484673 P=0 G=-1 StateTransition Time=12260817876992 GoID=1 Undetermined->Running Reason=""
    proc_test.go:1341: Event: M=2484673 P=0 G=1 Metric Time=12260817887488 Name="/sched/gomaxprocs:threads" Value=Value{Uint64(8)}
        Stack=
        	runtime.traceLocker.Gomaxprocs @ 0x487bc3
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/traceruntime.go:282
...
    proc_test.go:1472: Event: M=2514010 P=5 G=1 Log Time=12312646174144 Task=0 Category="TraceSTW" Message="end"
        Stack=
        	main.TraceGCSTW @ 0x52aee7
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/testdata/testprog/stw_trace.go:136
        	main.main @ 0x524632
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/testdata/testprog/main.go:34
    proc_test.go:1561: Found end message
    proc_test.go:1268: Errors: 13/50 = 26.000000%
    proc_test.go:1270: Error rate too high
--- FAIL: TestTraceGCSTW (56.23s)
2025-12-10 21:46 go1.26-linux-amd64-longtest release-branch.go1.26@fc66a565 runtime.TestTraceGCSTW (log) 
=== RUN   TestTraceGCSTW
    proc_test.go:1275: Run 0
    proc_test.go:1282: /home/swarming/.swarming/w/ir/x/t/go-build726996447/testprog.exe TraceGCSTW (289.331699ms): ok
    proc_test.go:1341: Event: M=-1 P=-1 G=-1 Sync Time=9006496753792 N=1 Trace=9006530100224 Mono=9006530100193 Wall=2025-12-16T00:55:38.41891742Z
    proc_test.go:1341: Event: M=1468670 P=-1 G=-1 StateTransition Time=9006530114432 ProcID=0 Undetermined->Running Reason=""
    proc_test.go:1341: Event: M=1468670 P=0 G=-1 StateTransition Time=9006530114752 GoID=1 Undetermined->Running Reason=""
    proc_test.go:1341: Event: M=1468670 P=0 G=1 Metric Time=9006530127040 Name="/sched/gomaxprocs:threads" Value=Value{Uint64(8)}
        Stack=
        	runtime.traceLocker.Gomaxprocs @ 0x487bc3
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/traceruntime.go:282
...
        	data="runtime.(*timer).reset"
        String id=141
        	data="runtime.chansend1"
        EndOfGeneration
        
    helpers.go:39: Convert this to a raw trace with `go test internal/trace/testtrace -convert in.tracetxt -out out.trace`
    proc_test.go:1262: Run 49 failed: P did not remain on M
    proc_test.go:1268: Errors: 13/50 = 26.000000%
    proc_test.go:1270: Error rate too high
--- FAIL: TestTraceGCSTW (22.67s)
2025-12-11 16:33 go1.26-linux-amd64-longtest release-branch.go1.26@c0ba5197 runtime.TestTraceGCSTW (log) 
=== RUN   TestTraceGCSTW
    proc_test.go:1275: Run 0
    proc_test.go:1282: /home/swarming/.swarming/w/ir/x/t/go-build3035696748/testprog.exe TraceGCSTW (460.154811ms): ok
    proc_test.go:1341: Event: M=-1 P=-1 G=-1 Sync Time=7469185207808 N=1 Trace=7469204583168 Mono=7469204583101 Wall=2025-12-16T00:29:21.946846303Z
    proc_test.go:1341: Event: M=1232471 P=-1 G=-1 StateTransition Time=7469204596032 ProcID=0 Undetermined->Running Reason=""
    proc_test.go:1341: Event: M=1232471 P=0 G=-1 StateTransition Time=7469204596416 GoID=1 Undetermined->Running Reason=""
    proc_test.go:1341: Event: M=1232471 P=0 G=1 Metric Time=7469204609728 Name="/sched/gomaxprocs:threads" Value=Value{Uint64(8)}
        Stack=
        	runtime.traceLocker.Gomaxprocs @ 0x487c23
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/traceruntime.go:282
...
    proc_test.go:1472: Event: M=1267464 P=4 G=1 Log Time=7524070297280 Task=0 Category="TraceSTW" Message="end"
        Stack=
        	main.TraceGCSTW @ 0x52af47
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/testdata/testprog/stw_trace.go:136
        	main.main @ 0x524692
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/testdata/testprog/main.go:34
    proc_test.go:1561: Found end message
    proc_test.go:1268: Errors: 14/50 = 28.000000%
    proc_test.go:1270: Error rate too high
--- FAIL: TestTraceGCSTW (55.05s)
2025-12-11 18:27 go1.26-linux-amd64-longtest release-branch.go1.26@bb2337f2 runtime.TestTraceGCSTW (log) 
=== RUN   TestTraceGCSTW
    proc_test.go:1275: Run 0
    proc_test.go:1282: /home/swarming/.swarming/w/ir/x/t/go-build1491569568/testprog.exe TraceGCSTW (383.36627ms): ok
    proc_test.go:1341: Event: M=-1 P=-1 G=-1 Sync Time=4880825468096 N=1 Trace=4880825561600 Mono=4880825561601 Wall=2025-12-15T23:51:18.40970676Z
    proc_test.go:1341: Event: M=1040320 P=-1 G=-1 StateTransition Time=4880825575168 ProcID=0 Undetermined->Running Reason=""
    proc_test.go:1341: Event: M=1040320 P=0 G=-1 StateTransition Time=4880825575616 GoID=1 Undetermined->Running Reason=""
    proc_test.go:1341: Event: M=1040320 P=0 G=1 Metric Time=4880825587648 Name="/sched/gomaxprocs:threads" Value=Value{Uint64(8)}
        Stack=
        	runtime.traceLocker.Gomaxprocs @ 0x487b83
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/traceruntime.go:282
...
    proc_test.go:1472: Event: M=1062229 P=4 G=1 Log Time=4923305314688 Task=0 Category="TraceSTW" Message="end"
        Stack=
        	main.TraceGCSTW @ 0x52ae27
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/testdata/testprog/stw_trace.go:136
        	main.main @ 0x524572
        		/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/testdata/testprog/main.go:34
    proc_test.go:1561: Found end message
    proc_test.go:1268: Errors: 13/50 = 26.000000%
    proc_test.go:1270: Error rate too high
--- FAIL: TestTraceGCSTW (43.71s)

— watchflakes

gopherbot avatar Dec 18 '25 18:12 gopherbot