runtime: TestNotInGoMetric/CgoCallAndCallback failures

[gopherbot]

#!watchflakes
default <- pkg ~ `^runtime(|:.+)$` && test ~ `TestNotInGoMetric/CgoCall(|AndCallback)`

Issue created automatically to collect these failures.

Example (log):

=== RUN   TestNotInGoMetric/CgoCallAndCallback
    metrics_cgo_test.go:28: /home/swarming/.swarming/w/ir/x/t/go-build3645217862/testprogcgo.exe NotInGoMetricCgoCallAndCallback (9.58595ms): ok
    metrics_cgo_test.go:31: output:
        pre-STW: expected 10 not-in-go goroutines, found 9
        OK
        
        
        wanted:
        OK
--- FAIL: TestNotInGoMetric/CgoCallAndCallback (0.01s)

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "runtime" && test == "TestNotInGoMetric/CgoCallAndCallback"

2026-04-20 20:53 gotip-linux-386-longtest go@b7717e19 runtime.TestNotInGoMetric/CgoCallAndCallback (log)

=== RUN   TestNotInGoMetric/CgoCallAndCallback
    metrics_cgo_test.go:28: /home/swarming/.swarming/w/ir/x/t/go-build3645217862/testprogcgo.exe NotInGoMetricCgoCallAndCallback (9.58595ms): ok
    metrics_cgo_test.go:31: output:
        pre-STW: expected 10 not-in-go goroutines, found 9
        OK
        
        
        wanted:
        OK
--- FAIL: TestNotInGoMetric/CgoCallAndCallback (0.01s)

— watchflakes

[gopherbot]

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

#!watchflakes
default <- pkg == `^runtime(|:.+)$` && test == "TestNotInGoMetric/CgoCallAndCallback"

And the problems were:

script:2.19: == requires quoted string

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

— watchflakes

[randall77]

I can reproduce.

Edit runtime/testdata/testprogcgo/notingo.go, remove line 228 (the println("OK") one), just to make life easier.

go build runtime/testdata/testprogcgo/main.go runtime/testdata/testprogcgo/notingo.go 
repeat 10000 ./main NotInGoMetricCgoCallAndCallback

Tends to fail 1 or 2 times in those 10000 runs.

pre-STW: expected 10 not-in-go goroutines, found 9
pre-STW: expected 10 not-in-go goroutines, found 9

The two watchflakes failures are linux/386, but it fails on linux/amd64 also. I can reproduce on darwin/arm64 at a rate closer to 1 in 100000.

It always fails pre-STW, never post-STW.

[randall77]

My current theory is that access to schedStats.gNonGo when reading stats is not synchronized, so the read of the stats in runtime/metrics.go:479 might be reading a stale gNonGo.
I'm trying to verify by putting a lock/unlock of sched.lock around the access and see if the problem goes away.

[randall77]

That last theory is wrong, there's nothing racy about accessing gNonGo, at least for this test.

Suspicion has turned to either nondeterminism in setBlockOnExitSyscall or nGsyscallNoP, both accessed in (*runtime.schedStatsAggregate).compute.
I'm officially out of my depth here. Both seem like they could be nondeterministic, but both also don't seem like they should be in this particular test.
@prattmic who might know this code better.