From 58c59123342adc5e9a0aabf4c5b00350b7d5720a Mon Sep 17 00:00:00 2001 From: Farhan Saif Date: Sun, 2 Aug 2026 01:06:43 -0500 Subject: [PATCH 1/2] gh-154969: Record stop-the-world pause durations in pystats 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 +=. --- Include/cpython/pystats.h | 4 ++++ Include/internal/pycore_interp_structs.h | 4 ++++ Include/internal/pycore_stats.h | 13 +++++++++++++ ...6-07-31-10-27-20.gh-issue-154969.rl2m1PNJIw.rst | 1 + Python/pystate.c | 12 ++++++++++++ Python/pystats.c | 14 +++++++++++--- 6 files changed, 45 insertions(+), 3 deletions(-) create mode 100644 Misc/NEWS.d/next/Core_and_Builtins/2026-07-31-10-27-20.gh-issue-154969.rl2m1PNJIw.rst diff --git a/Include/cpython/pystats.h b/Include/cpython/pystats.h index 738e342d1407686..11be7a45b7ca60a 100644 --- a/Include/cpython/pystats.h +++ b/Include/cpython/pystats.h @@ -120,6 +120,10 @@ typedef struct _ft_stats { uint64_t qsbr_polls; // number of times stop-the-world mechanism was used uint64_t world_stops; + // total time the world was stopped, in nanoseconds + uint64_t world_stop_total_ns; + // duration of the longest single world stop, in nanoseconds + uint64_t world_stop_max_ns; } FTStats; #endif diff --git a/Include/internal/pycore_interp_structs.h b/Include/internal/pycore_interp_structs.h index 0623adce693d465..7857afa323bbfe8 100644 --- a/Include/internal/pycore_interp_structs.h +++ b/Include/internal/pycore_interp_structs.h @@ -422,6 +422,10 @@ struct _stoptheworld_state { Py_ssize_t thread_countdown; // Number of threads that must pause. PyThreadState *requester; // Thread that requested the pause (may be NULL). + +#ifdef Py_STATS + PyTime_t start_time; // When the current pause was requested (for pystats). +#endif }; /* Tracks some rare events per-interpreter, used by the optimizer to turn on/off diff --git a/Include/internal/pycore_stats.h b/Include/internal/pycore_stats.h index 850e6ea455227c0..6fbcf6cb4e9051a 100644 --- a/Include/internal/pycore_stats.h +++ b/Include/internal/pycore_stats.h @@ -60,10 +60,22 @@ extern "C" { #define FT_STAT_MUTEX_SLEEP_INC() _Py_STATS_EXPR(ft_stats.mutex_sleeps++) #define FT_STAT_QSBR_POLL_INC() _Py_STATS_EXPR(ft_stats.qsbr_polls++) #define FT_STAT_WORLD_STOP_INC() _Py_STATS_EXPR(ft_stats.world_stops++) +#define FT_STAT_WORLD_STOP_TIME(ns) \ + do { \ + PyStats *s = _PyStats_GET(); \ + if (s != NULL) { \ + uint64_t stw_ns = (uint64_t)(ns); \ + s->ft_stats.world_stop_total_ns += stw_ns; \ + if (stw_ns > s->ft_stats.world_stop_max_ns) { \ + s->ft_stats.world_stop_max_ns = stw_ns; \ + } \ + } \ + } while (0) #else #define FT_STAT_MUTEX_SLEEP_INC() #define FT_STAT_QSBR_POLL_INC() #define FT_STAT_WORLD_STOP_INC() +#define FT_STAT_WORLD_STOP_TIME(ns) #endif // Export for '_opcode' shared extension @@ -91,6 +103,7 @@ PyAPI_FUNC(PyObject*) _Py_GetSpecializationStats(void); #define FT_STAT_MUTEX_SLEEP_INC() #define FT_STAT_QSBR_POLL_INC() #define FT_STAT_WORLD_STOP_INC() +#define FT_STAT_WORLD_STOP_TIME(ns) #endif // !Py_STATS diff --git a/Misc/NEWS.d/next/Core_and_Builtins/2026-07-31-10-27-20.gh-issue-154969.rl2m1PNJIw.rst b/Misc/NEWS.d/next/Core_and_Builtins/2026-07-31-10-27-20.gh-issue-154969.rl2m1PNJIw.rst new file mode 100644 index 000000000000000..2f20260eeacf502 --- /dev/null +++ b/Misc/NEWS.d/next/Core_and_Builtins/2026-07-31-10-27-20.gh-issue-154969.rl2m1PNJIw.rst @@ -0,0 +1 @@ +Statistics builds (``--enable-pystats``) of free-threaded CPython now record the total and maximum duration of stop-the-world pauses, and no longer overwrite the per-thread free-threading counters (mutex sleeps, QSBR polls, world stops) when merging thread statistics. diff --git a/Python/pystate.c b/Python/pystate.c index d10b38def32911d..4e67a8b3a52e165 100644 --- a/Python/pystate.c +++ b/Python/pystate.c @@ -2455,6 +2455,10 @@ stop_the_world(struct _stoptheworld_state *stw) stw->stop_event = (PyEvent){0}; // zero-initialize (unset) stw->requester = _PyThreadState_GET(); // may be NULL FT_STAT_WORLD_STOP_INC(); +#ifdef Py_STATS + // silently ignore error: cannot report error to the caller + (void)PyTime_MonotonicRaw(&stw->start_time); +#endif _Py_FOR_EACH_STW_INTERP(stw, i) { _Py_FOR_EACH_TSTATE_UNLOCKED(i, t) { @@ -2499,6 +2503,14 @@ start_the_world(struct _stoptheworld_state *stw) assert(PyMutex_IsLocked(&stw->mutex)); HEAD_LOCK(runtime); +#ifdef Py_STATS + // Records the full pause, from the stop request until the threads are + // about to be resumed. + PyTime_t now; + if (PyTime_MonotonicRaw(&now) == 0) { + FT_STAT_WORLD_STOP_TIME(now - stw->start_time); + } +#endif stw->requested = 0; stw->world_stopped = 0; // Switch threads back to the detached state. diff --git a/Python/pystats.c b/Python/pystats.c index 6862521f659f202..4358d6c513f8e40 100644 --- a/Python/pystats.c +++ b/Python/pystats.c @@ -343,6 +343,10 @@ print_ft_stats(FILE *out, FTStats *stats) fprintf(out, "Mutex sleeps (mutex_sleeps): %" PRIu64 "\n", stats->mutex_sleeps); fprintf(out, "QSBR polls (qsbr_polls): %" PRIu64 "\n", stats->qsbr_polls); fprintf(out, "World stops (world_stops): %" PRIu64 "\n", stats->world_stops); + fprintf(out, "World stop total ns (world_stop_total_ns): %" PRIu64 "\n", + stats->world_stop_total_ns); + fprintf(out, "World stop max ns (world_stop_max_ns): %" PRIu64 "\n", + stats->world_stop_max_ns); } #endif @@ -506,9 +510,13 @@ merge_optimization_stats(OptimizationStats *dest, const OptimizationStats *src) static void merge_ft_stats(FTStats *dest, const FTStats *src) { - dest->mutex_sleeps = src->mutex_sleeps; - dest->qsbr_polls = src->qsbr_polls; - dest->world_stops = src->world_stops; + dest->mutex_sleeps += src->mutex_sleeps; + dest->qsbr_polls += src->qsbr_polls; + dest->world_stops += src->world_stops; + dest->world_stop_total_ns += src->world_stop_total_ns; + if (src->world_stop_max_ns > dest->world_stop_max_ns) { + dest->world_stop_max_ns = src->world_stop_max_ns; + } } static void From 09cc362212228f6b6b0d7ad7f1392fa94715983b Mon Sep 17 00:00:00 2001 From: Farhan Saif Date: Sun, 2 Aug 2026 11:02:12 -0500 Subject: [PATCH 2/2] gh-154969: Add tests for the free-threading stats counters Cover the two things the previous commit changed: that a thread's counters are added to the interpreter's rather than replacing them, and that stop-the-world pauses are timed as well as counted. Four threads each collect ten times, so a merge that overwrites leaves roughly a quarter of the stops behind and the first test notices. The durations are checked for consistency instead of against wall-clock figures, which would differ from machine to machine. run_test_code() grew a `stat_names` argument so one run can report several counters; it still keeps the first value printed for each, since a test that calls sys._stats_dump() gets more than one block of output. --- Lib/test/test_pystats.py | 92 +++++++++++++++++++++++++++++++++++++--- 1 file changed, 87 insertions(+), 5 deletions(-) diff --git a/Lib/test/test_pystats.py b/Lib/test/test_pystats.py index c50cecfcfddfe6d..c7cb445d7e19263 100644 --- a/Lib/test/test_pystats.py +++ b/Lib/test/test_pystats.py @@ -1,6 +1,7 @@ import sys import textwrap import unittest +from test import support from test.support import script_helper # This function is available for the --enable-pystats config. @@ -70,8 +71,12 @@ def run_test_code( test_code, args=[], env_vars=None, + stat_names=None, ): - """Run test code and return the value of the "set_class" stats counter. + """Run test code and return stats counters printed when it exits. + + Returns the value of the "set_class" counter, or, when `stat_names` is + given, a dict of those counters collected from the same run. """ code = textwrap.dedent(TEST_TEMPLATE) code = code.replace('_TEST_CODE_', textwrap.dedent(test_code)) @@ -79,11 +84,26 @@ def run_test_code( env_vars = env_vars or {} res, _ = script_helper.run_python_until_end(*script_args, **env_vars) stderr = res.err.decode("ascii", "backslashreplace") + + if stat_names is None: + stat_names = ('Rare event (set_class)',) + wanted_one = True + else: + wanted_one = False + + # A run may print more than one block of stats, e.g. when it calls + # sys._stats_dump() itself and then prints again on the way out. Keep the + # first value seen for each counter. + found = {} for line in stderr.split('\n'): - if 'Rare event (set_class)' in line: - label, _, value = line.partition(':') - return value.strip() - return '' + label, sep, value = line.partition(':') + label = label.strip() + if sep and label in stat_names and label not in found: + found[label] = value.strip() + + if wanted_one: + return found.get('Rare event (set_class)', '') + return found @unittest.skipUnless(HAVE_PYSTATS, "requires pystats build option") @@ -211,5 +231,67 @@ def func_test(thread_id): self.assertEqual(stat_count, '0') +@unittest.skipUnless(HAVE_PYSTATS, "requires pystats build option") +@unittest.skipUnless(support.Py_GIL_DISABLED, "requires free-threaded build") +class TestFreeThreadingStats(unittest.TestCase): + """Tests for the counters that only the free-threaded build keeps. + """ + + # How many times each worker thread stops the world. + COLLECTS = 10 + WORKERS = 4 + + WORLD_STOPS = 'World stops (world_stops)' + TOTAL_NS = 'World stop total ns (world_stop_total_ns)' + MAX_NS = 'World stop max ns (world_stop_max_ns)' + + def collect_in_threads(self): + """Stop the world from several threads, then report the counters. + """ + code = f""" + import gc + + THREADS = {self.WORKERS} + + def func_start(): + # Discard whatever start-up accumulated, so the counts below come + # from the collections the workers do and nothing else. + sys._stats_clear() + + def func_test(thread_id): + for _ in range({self.COLLECTS}): + gc.collect() + """ + return run_test_code( + code, + args=['-X', 'pystats'], + stat_names=(self.WORLD_STOPS, self.TOTAL_NS, self.MAX_NS), + ) + + def test_counters_are_summed_over_threads(self): + """Each thread's counts must be added, not overwrite the previous one. + """ + stats = self.collect_in_threads() + stops = int(stats[self.WORLD_STOPS]) + # Every worker stops the world COLLECTS times. Merging a thread's stats + # into the interpreter's by assignment would leave just one worker's + # share, so anything close to a single worker's count means the counts + # of the others were thrown away. + self.assertGreater(stops, 2 * self.COLLECTS) + + def test_world_stop_durations_are_recorded(self): + stats = self.collect_in_threads() + stops = int(stats[self.WORLD_STOPS]) + total = int(stats[self.TOTAL_NS]) + longest = int(stats[self.MAX_NS]) + + self.assertGreater(stops, 0) + # Pauses that were counted must also have been timed. + self.assertGreater(total, 0) + self.assertGreater(longest, 0) + # A single pause cannot last longer than all of them put together. + self.assertLessEqual(longest, total) + + if __name__ == "__main__": unittest.main()