Skip to content

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

Open
overlorde wants to merge 1 commit into
python:mainfrom
overlorde:fix-issue-154969
Open

gh-154969: Record stop-the-world pause durations in pystats#155069
overlorde wants to merge 1 commit into
python:mainfrom
overlorde:fix-issue-154969

Conversation

@overlorde

@overlorde overlorde commented Aug 2, 2026

Copy link
Copy Markdown
Contributor

This covers both problems described in the issue.

The first is that stop-the-world pauses are counted but never timed. world_stops: 97 says nothing about whether those pauses cost microseconds or milliseconds, so there is no way to tell a healthy workload from one that is spending real time frozen. stop_the_world() now takes a monotonic timestamp when a pause is requested, and start_the_world() reads the clock again just before threads are released, recording both the total and the longest single pause. The window deliberately covers the whole time the application was denied parallelism, not just the time spent bringing threads to a halt. The new field in struct _stoptheworld_state and both clock reads sit under #ifdef Py_STATS inside the existing Py_GIL_DISABLED block, so every other configuration compiles unchanged.

The second is a bug I ran into while measuring the first. merge_ft_stats() assigned where every other merge helper in the file accumulates:

dest->mutex_sleeps = src->mutex_sleeps;
dest->qsbr_polls = src->qsbr_polls;
dest->world_stops = src->world_stops;

Threads fold their stats into the interpreter's one after another, so with assignment each counter ended up holding whichever thread merged last instead of the sum. Stop-the-world requests come mostly from the main thread, and the main thread merges last, so world_stops happened to look right the whole time. That is probably why this went unnoticed. The mutex and QSBR counters did not fare as well.

Eight threads appending 200k items each to one shared list, same binary, with only Python/pystats.c differing between the runs:

before after after (2nd run)
mutex_sleeps 14 198248 298419
qsbr_polls 9 240
world_stops 97 97 97
world_stop_total_ns 13202060 12476593
world_stop_max_ns 4404539 4109232

world_stops is unchanged, as expected from the above. The mutex count swings between runs because the contention itself does, but it is now in the right range rather than pinned to the main thread's 14.

The duration figures show why a count on its own is not much use here. Roughly 13 ms of total pause across 97 stops, but a single worst stop of 4.4 ms, so one pause accounts for a third of all the time spent frozen. A bare count cannot express that and an average would bury it, which is the reason for tracking the maximum separately.

One question for review: the merge fix is a bugfix against counters that already shipped, while the duration counters are new. If those want to go to different branches I am happy to split them into two PRs.

The free-threaded build counts stop-the-world pauses but never times
them, so a 1 us pause and a 5 ms pause are indistinguishable in the
stats output.  Record the elapsed time from the moment a pause is
requested until threads are about to be resumed, and report both the
total and the longest single pause.

Also fix merge_ft_stats(), which assigned rather than accumulated when
folding a thread's stats into the interpreter's.  With more than one
thread, every free-threading counter reported whichever thread happened
to merge last instead of the sum.  All the other merge helpers already
use +=.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant