From: Brandt Bucher Date: Wed, 19 Nov 2025 16:51:39 +0000 (-0800) Subject: GH-140638: Add a GC "duration" stat (GH-141720) X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=598d4c64deeec1857614007d1a2f0403508fe047;p=thirdparty%2FPython%2Fcpython.git GH-140638: Add a GC "duration" stat (GH-141720) --- diff --git a/Doc/library/gc.rst b/Doc/library/gc.rst index 2ef5c4b35a25..8e6f2342a286 100644 --- a/Doc/library/gc.rst +++ b/Doc/library/gc.rst @@ -108,10 +108,16 @@ The :mod:`gc` module provides the following functions: * ``uncollectable`` is the total number of objects which were found to be uncollectable (and were therefore moved to the :data:`garbage` - list) inside this generation. + list) inside this generation; + + * ``duration`` is the total time in seconds spent in collections for this + generation. .. versionadded:: 3.4 + .. versionchanged:: next + Add ``duration``. + .. function:: set_threshold(threshold0, [threshold1, [threshold2]]) @@ -313,6 +319,9 @@ values but should not rebind them): "uncollectable": When *phase* is "stop", the number of objects that could not be collected and were put in :data:`garbage`. + "duration": When *phase* is "stop", the time in seconds spent in the + collection. + Applications can add their own callbacks to this list. The primary use cases are: @@ -325,6 +334,9 @@ values but should not rebind them): .. versionadded:: 3.3 + .. versionchanged:: next + Add "duration". + The following constants are provided for use with :func:`set_debug`: diff --git a/Include/internal/pycore_interp_structs.h b/Include/internal/pycore_interp_structs.h index f861d3abd96d..d9f5d444a2dc 100644 --- a/Include/internal/pycore_interp_structs.h +++ b/Include/internal/pycore_interp_structs.h @@ -179,6 +179,8 @@ struct gc_collection_stats { Py_ssize_t collected; /* total number of uncollectable objects (put into gc.garbage) */ Py_ssize_t uncollectable; + // Duration of the collection in seconds: + double duration; }; /* Running stats per generation */ @@ -189,6 +191,8 @@ struct gc_generation_stats { Py_ssize_t collected; /* total number of uncollectable objects (put into gc.garbage) */ Py_ssize_t uncollectable; + // Duration of the collection in seconds: + double duration; }; enum _GCPhase { diff --git a/Lib/test/test_gc.py b/Lib/test/test_gc.py index 10c3a6221077..e65da0f61d94 100644 --- a/Lib/test/test_gc.py +++ b/Lib/test/test_gc.py @@ -847,10 +847,11 @@ class GCTests(unittest.TestCase): for st in stats: self.assertIsInstance(st, dict) self.assertEqual(set(st), - {"collected", "collections", "uncollectable"}) + {"collected", "collections", "uncollectable", "duration"}) self.assertGreaterEqual(st["collected"], 0) self.assertGreaterEqual(st["collections"], 0) self.assertGreaterEqual(st["uncollectable"], 0) + self.assertGreaterEqual(st["duration"], 0) # Check that collection counts are incremented correctly if gc.isenabled(): self.addCleanup(gc.enable) @@ -861,11 +862,25 @@ class GCTests(unittest.TestCase): self.assertEqual(new[0]["collections"], old[0]["collections"] + 1) self.assertEqual(new[1]["collections"], old[1]["collections"]) self.assertEqual(new[2]["collections"], old[2]["collections"]) + self.assertGreater(new[0]["duration"], old[0]["duration"]) + self.assertEqual(new[1]["duration"], old[1]["duration"]) + self.assertEqual(new[2]["duration"], old[2]["duration"]) + for stat in ["collected", "uncollectable"]: + self.assertGreaterEqual(new[0][stat], old[0][stat]) + self.assertEqual(new[1][stat], old[1][stat]) + self.assertEqual(new[2][stat], old[2][stat]) gc.collect(2) - new = gc.get_stats() - self.assertEqual(new[0]["collections"], old[0]["collections"] + 1) + old, new = new, gc.get_stats() + self.assertEqual(new[0]["collections"], old[0]["collections"]) self.assertEqual(new[1]["collections"], old[1]["collections"]) self.assertEqual(new[2]["collections"], old[2]["collections"] + 1) + self.assertEqual(new[0]["duration"], old[0]["duration"]) + self.assertEqual(new[1]["duration"], old[1]["duration"]) + self.assertGreater(new[2]["duration"], old[2]["duration"]) + for stat in ["collected", "uncollectable"]: + self.assertEqual(new[0][stat], old[0][stat]) + self.assertEqual(new[1][stat], old[1][stat]) + self.assertGreaterEqual(new[2][stat], old[2][stat]) def test_freeze(self): gc.freeze() @@ -1298,9 +1313,10 @@ class GCCallbackTests(unittest.TestCase): # Check that we got the right info dict for all callbacks for v in self.visit: info = v[2] - self.assertTrue("generation" in info) - self.assertTrue("collected" in info) - self.assertTrue("uncollectable" in info) + self.assertIn("generation", info) + self.assertIn("collected", info) + self.assertIn("uncollectable", info) + self.assertIn("duration", info) def test_collect_generation(self): self.preclean() diff --git a/Misc/NEWS.d/next/Core_and_Builtins/2025-11-18-07-45-37.gh-issue-140638.i06qxD.rst b/Misc/NEWS.d/next/Core_and_Builtins/2025-11-18-07-45-37.gh-issue-140638.i06qxD.rst new file mode 100644 index 000000000000..891e24d76448 --- /dev/null +++ b/Misc/NEWS.d/next/Core_and_Builtins/2025-11-18-07-45-37.gh-issue-140638.i06qxD.rst @@ -0,0 +1,2 @@ +Expose a ``"duration"`` stat in :func:`gc.get_stats` and +:data:`gc.callbacks`. diff --git a/Modules/gcmodule.c b/Modules/gcmodule.c index 8a8c72842834..6a44d8a9d17a 100644 --- a/Modules/gcmodule.c +++ b/Modules/gcmodule.c @@ -358,10 +358,11 @@ gc_get_stats_impl(PyObject *module) for (i = 0; i < NUM_GENERATIONS; i++) { PyObject *dict; st = &stats[i]; - dict = Py_BuildValue("{snsnsn}", + dict = Py_BuildValue("{snsnsnsd}", "collections", st->collections, "collected", st->collected, - "uncollectable", st->uncollectable + "uncollectable", st->uncollectable, + "duration", st->duration ); if (dict == NULL) goto error; diff --git a/Python/gc.c b/Python/gc.c index 27364ecfdcd5..7e3e93e6e01b 100644 --- a/Python/gc.c +++ b/Python/gc.c @@ -1363,6 +1363,7 @@ gc_list_set_space(PyGC_Head *list, int space) static void add_stats(GCState *gcstate, int gen, struct gc_collection_stats *stats) { + gcstate->generation_stats[gen].duration += stats->duration; gcstate->generation_stats[gen].collected += stats->collected; gcstate->generation_stats[gen].uncollectable += stats->uncollectable; gcstate->generation_stats[gen].collections += 1; @@ -1387,7 +1388,6 @@ gc_collect_young(PyThreadState *tstate, validate_spaces(gcstate); gcstate->young.count = 0; gcstate->old[gcstate->visited_space].count++; - add_stats(gcstate, 0, stats); validate_spaces(gcstate); } @@ -1701,7 +1701,6 @@ gc_collect_increment(PyThreadState *tstate, struct gc_collection_stats *stats) assert(gc_list_is_empty(&increment)); gcstate->work_to_do -= increment_size; - add_stats(gcstate, 1, stats); if (gc_list_is_empty(not_visited)) { completed_scavenge(gcstate); } @@ -1736,7 +1735,6 @@ gc_collect_full(PyThreadState *tstate, completed_scavenge(gcstate); _PyGC_ClearAllFreeLists(tstate->interp); validate_spaces(gcstate); - add_stats(gcstate, 2, stats); } /* This is the main function. Read this to understand how the @@ -1846,10 +1844,11 @@ do_gc_callback(GCState *gcstate, const char *phase, assert(PyList_CheckExact(gcstate->callbacks)); PyObject *info = NULL; if (PyList_GET_SIZE(gcstate->callbacks) != 0) { - info = Py_BuildValue("{sisnsn}", + info = Py_BuildValue("{sisnsnsd}", "generation", generation, "collected", stats->collected, - "uncollectable", stats->uncollectable); + "uncollectable", stats->uncollectable, + "duration", stats->duration); if (info == NULL) { PyErr_FormatUnraisable("Exception ignored while invoking gc callbacks"); return; @@ -2080,15 +2079,15 @@ _PyGC_Collect(PyThreadState *tstate, int generation, _PyGC_Reason reason) if (reason != _Py_GC_REASON_SHUTDOWN) { invoke_gc_callback(gcstate, "start", generation, &stats); } - PyTime_t t1; if (gcstate->debug & _PyGC_DEBUG_STATS) { PySys_WriteStderr("gc: collecting generation %d...\n", generation); - (void)PyTime_PerfCounterRaw(&t1); show_stats_each_generations(gcstate); } if (PyDTrace_GC_START_ENABLED()) { PyDTrace_GC_START(generation); } + PyTime_t start, stop; + (void)PyTime_PerfCounterRaw(&start); PyObject *exc = _PyErr_GetRaisedException(tstate); switch(generation) { case 0: @@ -2103,6 +2102,9 @@ _PyGC_Collect(PyThreadState *tstate, int generation, _PyGC_Reason reason) default: Py_UNREACHABLE(); } + (void)PyTime_PerfCounterRaw(&stop); + stats.duration = PyTime_AsSecondsDouble(stop - start); + add_stats(gcstate, generation, &stats); if (PyDTrace_GC_DONE_ENABLED()) { PyDTrace_GC_DONE(stats.uncollectable + stats.collected); } @@ -2124,12 +2126,9 @@ _PyGC_Collect(PyThreadState *tstate, int generation, _PyGC_Reason reason) _Py_atomic_store_int(&gcstate->collecting, 0); if (gcstate->debug & _PyGC_DEBUG_STATS) { - PyTime_t t2; - (void)PyTime_PerfCounterRaw(&t2); - double d = PyTime_AsSecondsDouble(t2 - t1); PySys_WriteStderr( "gc: done, %zd unreachable, %zd uncollectable, %.4fs elapsed\n", - stats.collected + stats.uncollectable, stats.uncollectable, d + stats.collected + stats.uncollectable, stats.uncollectable, stats.duration ); } diff --git a/Python/gc_free_threading.c b/Python/gc_free_threading.c index 7724676c2426..9f424db88945 100644 --- a/Python/gc_free_threading.c +++ b/Python/gc_free_threading.c @@ -1911,7 +1911,7 @@ handle_resurrected_objects(struct collection_state *state) static void invoke_gc_callback(PyThreadState *tstate, const char *phase, int generation, Py_ssize_t collected, - Py_ssize_t uncollectable) + Py_ssize_t uncollectable, double duration) { assert(!_PyErr_Occurred(tstate)); @@ -1925,10 +1925,11 @@ invoke_gc_callback(PyThreadState *tstate, const char *phase, assert(PyList_CheckExact(gcstate->callbacks)); PyObject *info = NULL; if (PyList_GET_SIZE(gcstate->callbacks) != 0) { - info = Py_BuildValue("{sisnsn}", + info = Py_BuildValue("{sisnsnsd}", "generation", generation, "collected", collected, - "uncollectable", uncollectable); + "uncollectable", uncollectable, + "duration", duration); if (info == NULL) { PyErr_FormatUnraisable("Exception ignored while " "invoking gc callbacks"); @@ -2340,7 +2341,6 @@ gc_collect_main(PyThreadState *tstate, int generation, _PyGC_Reason reason) { Py_ssize_t m = 0; /* # objects collected */ Py_ssize_t n = 0; /* # unreachable objects that couldn't be collected */ - PyTime_t t1 = 0; /* initialize to prevent a compiler warning */ GCState *gcstate = &tstate->interp->gc; // gc_collect_main() must not be called before _PyGC_Init @@ -2372,19 +2372,19 @@ gc_collect_main(PyThreadState *tstate, int generation, _PyGC_Reason reason) GC_STAT_ADD(generation, collections, 1); if (reason != _Py_GC_REASON_SHUTDOWN) { - invoke_gc_callback(tstate, "start", generation, 0, 0); + invoke_gc_callback(tstate, "start", generation, 0, 0, 0); } if (gcstate->debug & _PyGC_DEBUG_STATS) { PySys_WriteStderr("gc: collecting generation %d...\n", generation); show_stats_each_generations(gcstate); - // ignore error: don't interrupt the GC if reading the clock fails - (void)PyTime_PerfCounterRaw(&t1); } if (PyDTrace_GC_START_ENABLED()) { PyDTrace_GC_START(generation); } + PyTime_t start, stop; + (void)PyTime_PerfCounterRaw(&start); PyInterpreterState *interp = tstate->interp; @@ -2399,13 +2399,13 @@ gc_collect_main(PyThreadState *tstate, int generation, _PyGC_Reason reason) m = state.collected; n = state.uncollectable; + (void)PyTime_PerfCounterRaw(&stop); + double duration = PyTime_AsSecondsDouble(stop - start); + if (gcstate->debug & _PyGC_DEBUG_STATS) { - PyTime_t t2; - (void)PyTime_PerfCounterRaw(&t2); - double d = PyTime_AsSecondsDouble(t2 - t1); PySys_WriteStderr( "gc: done, %zd unreachable, %zd uncollectable, %.4fs elapsed\n", - n+m, n, d); + n+m, n, duration); } // Clear the current thread's free-list again. @@ -2426,6 +2426,7 @@ gc_collect_main(PyThreadState *tstate, int generation, _PyGC_Reason reason) stats->collections++; stats->collected += m; stats->uncollectable += n; + stats->duration += duration; GC_STAT_ADD(generation, objects_collected, m); #ifdef Py_STATS @@ -2444,7 +2445,7 @@ gc_collect_main(PyThreadState *tstate, int generation, _PyGC_Reason reason) } if (reason != _Py_GC_REASON_SHUTDOWN) { - invoke_gc_callback(tstate, "stop", generation, m, n); + invoke_gc_callback(tstate, "stop", generation, m, n, duration); } assert(!_PyErr_Occurred(tstate));