Free-threading: add stop-the-world duration and contention counts to pystats

[overlorde]

Feature or enhancement

Proposal:

gh-131253 added the first free-threading counters to pystats (mutex_sleeps, world_stops, qsbr_polls) and was recently closed as complete. After spending some time measuring the free-threaded build with them, I think two small additions would make them considerably more useful. The numbers below are from current main on a 24-core Linux machine, using Tools/ftscalingbench plus uprobe tracing on _PyMutex_LockTimed to cross-check what the counters report.

Stop-the-world duration. world_stops counts pauses but says nothing about their cost. Two ftscalingbench runs I traced both did exactly 277 stops, but total pause time was 0.45 ms in one (pymethod) and 1.53 ms in the other (staticmethod_call) - a 3.4x difference the counter cannot distinguish. The original issue already floated "possibly total duration"; it just never got implemented. Two clock reads in stop_the_world() would cover it. A max would be nice as well, since the distribution has a long tail - most pauses I saw were 0.5-2 us, with outliers around 16 us.

Contention events, not just sleeps. mutex_sleeps counts a thread actually parking, but _PyMutex_LockTimed spins first, so any contention that resolves by spinning is invisible. On a deliberately contended workload (8 threads appending to one shared list) I measured 196 entries into _PyMutex_LockTimed against a mutex_sleeps of 14, so the one contention counter we have misses roughly 93% of contention. An entry counter in _PyMutex_LockTimed would close that gap, and since it sits on the slow path already the cost is one relaxed increment.

Two more observations from the same experiments, recorded here because they shaped what I'm not proposing:

The scaling losses in ftscalingbench are not lock waits. Three workloads losing 35-50% of ideal scaling at 8 threads each showed only about 0.5 ms of genuine lock waiting, nearly all of it the import machinery RLock during thread startup plus interpreter teardown - none of it in the benchmark loops themselves. So I don't think more lock counters beyond the above are worth adding; whatever those benchmarks are losing, it happens below the mutex layer (my guess is refcounting cache traffic), and hardware-level tools are the right instrument there.

Benchmarking the free-threaded build also has a warmup trap worth knowing about: bytecode is thread-local, so specialization warmup on one thread does nothing for workers spawned later. I initially measured cold-bytecode churn without realizing it - FOR_ITER re-specializing hundreds of times per run, disappearing entirely when I reversed the run order. Anything that benchmarks with freshly spawned threads is exposed to this. Happy to write it up for the free-threading HOWTO if there's interest.

I can prepare PRs for both counters. This deliberately doesn't touch ring-buffer stats support for the FT build, which came up at the end of gh-131253.

Has this already been discussed elsewhere?

This is a minor feature, which does not need previous discussion elsewhere

Links to previous discussion of this feature:

No response

Linked PRs

• gh-154969: Record stop-the-world pause durations in pystats #155069

[overlorde]

Correcting the second proposal above. I had the mechanism wrong, and the measurement I used to support it was wrong for an unrelated reason.

Saying mutex_sleeps "counts a thread actually parking" is not accurate. FT_STAT_MUTEX_SLEEP_INC() sits at Python/lock.c:68, before the spin loop is entered, so it fires whenever a thread reaches the slow path at all, spin-resolved contention included. The only two paths that skip it are the uncontended compare-exchange at the top and the timeout == 0 trylock failure, and both should be skipped. The counter I was proposing to add is therefore, in substance, the counter that already exists. The name is misleading but the behaviour is what I was asking for.

The 196 versus 14 comparison that appeared to show a 93% gap was wrong on both sides. The 14 came from a bug in merge_ft_stats(), which assigned instead of accumulating when folding per-thread stats into the interpreter's, so the number I read was whichever thread merged last rather than the sum. With that fixed the same workload reports somewhere between 200,000 and 300,000. The 196 was an uprobe count, and the tracing overhead turned out to be heavy enough to suppress the contention it was trying to measure, so that side was low as well. Two errors pointing the same direction, which is why the gap looked so convincing.

So the contention-event counter should be dropped from this issue. The real defect was the merge bug, which I only found because I went looking for the gap I thought existed. #155069 fixes it and implements the stop-the-world duration counters.

The duration half of the proposal is unaffected. Those pause timings came from tracing rather than from the counters, and world_stops itself was accidentally immune to the merge bug because stop-the-world requests come mostly from the main thread, and the main thread merges last. That is also, I suspect, why the bug survived this long: one of the three counters always looked correct.

One thing I am deliberately not proposing: separating "parked" from "spun" would still be real information, since those have very different costs. It is a different request from the one I made here though, and I would want to see a workload where the distinction changes a decision before asking for it.

Happy to retitle the issue to just the duration work if that is cleaner, and sorry for the noise on that half.