From c2bf816a757af2e43dc20299b842e90a5de906eb Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?P=C3=A5l=20Gr=C3=B8n=C3=A5s=20Drange?= Date: Sun, 19 Oct 2025 18:38:29 +0200 Subject: [PATCH 01/14] Bring back elapsed time and unreachable count to gc debug --- Python/gc.c | 15 +++++++++++++++ 1 file changed, 15 insertions(+) diff --git a/Python/gc.c b/Python/gc.c index 79c7476f4a9a74..e64f4b226e3bdc 100644 --- a/Python/gc.c +++ b/Python/gc.c @@ -10,6 +10,7 @@ #include "pycore_interpframe.h" // _PyFrame_GetLocalsArray() #include "pycore_object_alloc.h" // _PyObject_MallocWithType() #include "pycore_pystate.h" // _PyThreadState_GET() +#include "pycore_time.h" // _PyTime_MonotonicRaw() #include "pycore_tuple.h" // _PyTuple_MaybeUntrack() #include "pycore_weakref.h" // _PyWeakref_ClearRef() @@ -1816,6 +1817,7 @@ gc_collect_region(PyThreadState *tstate, /* Collect statistics on uncollectable objects found and print * debugging information. */ Py_ssize_t n = 0; + for (gc = GC_NEXT(&finalizers); gc != &finalizers; gc = GC_NEXT(gc)) { n++; if (gcstate->debug & _PyGC_DEBUG_UNCOLLECTABLE) @@ -2066,6 +2068,8 @@ _PyGC_Collect(PyThreadState *tstate, int generation, _PyGC_Reason reason) { GCState *gcstate = &tstate->interp->gc; assert(tstate->current_frame == NULL || tstate->current_frame->stackpointer != NULL); + PyTime_t now; + (void)PyTime_MonotonicRaw(&now); int expected = 0; if (!_Py_atomic_compare_exchange_int(&gcstate->collecting, &expected, 1)) { @@ -2115,6 +2119,17 @@ _PyGC_Collect(PyThreadState *tstate, int generation, _PyGC_Reason reason) #endif validate_spaces(gcstate); _Py_atomic_store_int(&gcstate->collecting, 0); + + if (gcstate->debug & _PyGC_DEBUG_STATS) { + PyTime_t endtime; + (void)PyTime_MonotonicRaw(&endtime); + double d = PyTime_AsSecondsDouble(endtime - now); + PySys_WriteStderr( + "gc: done, %zd unreachable, %zd uncollectable, %.4fs elapsed\n", + stats.collected, stats.uncollectable, d + ); + } + return stats.uncollectable + stats.collected; } From da965513cea7bf85985a99abb45b42b9ff775ad0 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?P=C3=A5l=20Gr=C3=B8n=C3=A5s=20Drange?= Date: Mon, 20 Oct 2025 11:24:56 +0200 Subject: [PATCH 02/14] Add blurb for gc-elapsed-time --- .../2025-10-20-11-24-36.gh-issue-140358.UQuKdV.rst | 3 +++ 1 file changed, 3 insertions(+) create mode 100644 Misc/NEWS.d/next/Core_and_Builtins/2025-10-20-11-24-36.gh-issue-140358.UQuKdV.rst diff --git a/Misc/NEWS.d/next/Core_and_Builtins/2025-10-20-11-24-36.gh-issue-140358.UQuKdV.rst b/Misc/NEWS.d/next/Core_and_Builtins/2025-10-20-11-24-36.gh-issue-140358.UQuKdV.rst new file mode 100644 index 00000000000000..c89b49af158a52 --- /dev/null +++ b/Misc/NEWS.d/next/Core_and_Builtins/2025-10-20-11-24-36.gh-issue-140358.UQuKdV.rst @@ -0,0 +1,3 @@ +Restore elapsed time and unreachable object count in GC debug output. These +were inadvertently removed during a refactor of `gc.c`. The debug log now +again reports elapsed collection time and the number of unreachable objects. From d6a6054e5a6e28a9a4cb5d86ff0ede687e84ec79 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?P=C3=A5l=20Gr=C3=B8n=C3=A5s=20Drange?= Date: Mon, 20 Oct 2025 11:25:38 +0200 Subject: [PATCH 03/14] Remove accidentally added linebrak --- Python/gc.c | 1 - 1 file changed, 1 deletion(-) diff --git a/Python/gc.c b/Python/gc.c index e64f4b226e3bdc..97ffcfe366e751 100644 --- a/Python/gc.c +++ b/Python/gc.c @@ -1817,7 +1817,6 @@ gc_collect_region(PyThreadState *tstate, /* Collect statistics on uncollectable objects found and print * debugging information. */ Py_ssize_t n = 0; - for (gc = GC_NEXT(&finalizers); gc != &finalizers; gc = GC_NEXT(gc)) { n++; if (gcstate->debug & _PyGC_DEBUG_UNCOLLECTABLE) From 38c12126350138ef49d44f8a8aeb59898036664e Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?P=C3=A5l=20Gr=C3=B8n=C3=A5s=20Drange?= Date: Mon, 20 Oct 2025 11:32:15 +0200 Subject: [PATCH 04/14] Initialize now under `if (gcstate->debug ...)` cond --- Python/gc.c | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/Python/gc.c b/Python/gc.c index 97ffcfe366e751..72eb2e908df123 100644 --- a/Python/gc.c +++ b/Python/gc.c @@ -2067,8 +2067,11 @@ _PyGC_Collect(PyThreadState *tstate, int generation, _PyGC_Reason reason) { GCState *gcstate = &tstate->interp->gc; assert(tstate->current_frame == NULL || tstate->current_frame->stackpointer != NULL); + PyTime_t now; - (void)PyTime_MonotonicRaw(&now); + if (gcstate->debug & _PyGC_DEBUG_STATS) { + (void)PyTime_MonotonicRaw(&now); + } int expected = 0; if (!_Py_atomic_compare_exchange_int(&gcstate->collecting, &expected, 1)) { From 56c6eab002c9aeea3c7c1de171d9693be1e8038c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?P=C3=A5l=20Gr=C3=B8n=C3=A5s=20Drange?= Date: Mon, 20 Oct 2025 11:34:33 +0200 Subject: [PATCH 05/14] Fix backticks in blurb --- .../2025-10-20-11-24-36.gh-issue-140358.UQuKdV.rst | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/Misc/NEWS.d/next/Core_and_Builtins/2025-10-20-11-24-36.gh-issue-140358.UQuKdV.rst b/Misc/NEWS.d/next/Core_and_Builtins/2025-10-20-11-24-36.gh-issue-140358.UQuKdV.rst index c89b49af158a52..2e4f6e674fb1ae 100644 --- a/Misc/NEWS.d/next/Core_and_Builtins/2025-10-20-11-24-36.gh-issue-140358.UQuKdV.rst +++ b/Misc/NEWS.d/next/Core_and_Builtins/2025-10-20-11-24-36.gh-issue-140358.UQuKdV.rst @@ -1,3 +1,3 @@ Restore elapsed time and unreachable object count in GC debug output. These -were inadvertently removed during a refactor of `gc.c`. The debug log now +were inadvertently removed during a refactor of ``gc.c``. The debug log now again reports elapsed collection time and the number of unreachable objects. From 2a37cd465668864a4788df0c41020710ec0589f1 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?P=C3=A5l=20Gr=C3=B8n=C3=A5s=20Drange?= Date: Mon, 20 Oct 2025 11:34:42 +0200 Subject: [PATCH 06/14] Fix unreachable = collected + uncollectable. --- Python/gc.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/Python/gc.c b/Python/gc.c index 72eb2e908df123..32e78f8f3a0c49 100644 --- a/Python/gc.c +++ b/Python/gc.c @@ -2128,7 +2128,7 @@ _PyGC_Collect(PyThreadState *tstate, int generation, _PyGC_Reason reason) double d = PyTime_AsSecondsDouble(endtime - now); PySys_WriteStderr( "gc: done, %zd unreachable, %zd uncollectable, %.4fs elapsed\n", - stats.collected, stats.uncollectable, d + stats.collected + stats.collected, stats.uncollectable, d ); } From 456a38ac0737a15f4aea49a96e294dcdda6d591d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?P=C3=A5l=20Gr=C3=B8n=C3=A5s=20Drange?= Date: Mon, 20 Oct 2025 11:39:08 +0200 Subject: [PATCH 07/14] Rename now and endtime to t1,t2 --- Python/gc.c | 12 +++++------- 1 file changed, 5 insertions(+), 7 deletions(-) diff --git a/Python/gc.c b/Python/gc.c index 32e78f8f3a0c49..d9abd75e1c712d 100644 --- a/Python/gc.c +++ b/Python/gc.c @@ -2068,10 +2068,7 @@ _PyGC_Collect(PyThreadState *tstate, int generation, _PyGC_Reason reason) GCState *gcstate = &tstate->interp->gc; assert(tstate->current_frame == NULL || tstate->current_frame->stackpointer != NULL); - PyTime_t now; - if (gcstate->debug & _PyGC_DEBUG_STATS) { - (void)PyTime_MonotonicRaw(&now); - } + PyTime_t t1; int expected = 0; if (!_Py_atomic_compare_exchange_int(&gcstate->collecting, &expected, 1)) { @@ -2084,6 +2081,7 @@ _PyGC_Collect(PyThreadState *tstate, int generation, _PyGC_Reason reason) invoke_gc_callback(gcstate, "start", generation, &stats); } if (gcstate->debug & _PyGC_DEBUG_STATS) { + (void)PyTime_MonotonicRaw(&t1); PySys_WriteStderr("gc: collecting generation %d...\n", generation); show_stats_each_generations(gcstate); } @@ -2123,9 +2121,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 endtime; - (void)PyTime_MonotonicRaw(&endtime); - double d = PyTime_AsSecondsDouble(endtime - now); + PyTime_t t2; + (void)PyTime_MonotonicRaw(&t2); + double d = PyTime_AsSecondsDouble(t2 - t1); PySys_WriteStderr( "gc: done, %zd unreachable, %zd uncollectable, %.4fs elapsed\n", stats.collected + stats.collected, stats.uncollectable, d From 60129b6daf9faed1c0adc09857a9cedb2cd87938 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?P=C3=A5l=20Gr=C3=B8n=C3=A5s=20Drange?= Date: Mon, 20 Oct 2025 11:39:28 +0200 Subject: [PATCH 08/14] Fix mistake --- Python/gc.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/Python/gc.c b/Python/gc.c index d9abd75e1c712d..52d5dd7bf3397a 100644 --- a/Python/gc.c +++ b/Python/gc.c @@ -2126,7 +2126,7 @@ _PyGC_Collect(PyThreadState *tstate, int generation, _PyGC_Reason reason) double d = PyTime_AsSecondsDouble(t2 - t1); PySys_WriteStderr( "gc: done, %zd unreachable, %zd uncollectable, %.4fs elapsed\n", - stats.collected + stats.collected, stats.uncollectable, d + stats.collected + stats.uncollectable, stats.uncollectable, d ); } From 5db0a98cb5e51969c26a777d853308bd486d809f Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?P=C3=A5l=20Gr=C3=B8n=C3=A5s=20Drange?= Date: Mon, 20 Oct 2025 11:57:32 +0200 Subject: [PATCH 09/14] Use PerfCounter instead of monotonic --- Python/gc.c | 11 +++++------ 1 file changed, 5 insertions(+), 6 deletions(-) diff --git a/Python/gc.c b/Python/gc.c index 52d5dd7bf3397a..7f15a1112323c0 100644 --- a/Python/gc.c +++ b/Python/gc.c @@ -10,7 +10,7 @@ #include "pycore_interpframe.h" // _PyFrame_GetLocalsArray() #include "pycore_object_alloc.h" // _PyObject_MallocWithType() #include "pycore_pystate.h" // _PyThreadState_GET() -#include "pycore_time.h" // _PyTime_MonotonicRaw() +#include "pycore_time.h" // _PyTime_PerfCounterUnchecked() #include "pycore_tuple.h" // _PyTuple_MaybeUntrack() #include "pycore_weakref.h" // _PyWeakref_ClearRef() @@ -2068,8 +2068,6 @@ _PyGC_Collect(PyThreadState *tstate, int generation, _PyGC_Reason reason) GCState *gcstate = &tstate->interp->gc; assert(tstate->current_frame == NULL || tstate->current_frame->stackpointer != NULL); - PyTime_t t1; - int expected = 0; if (!_Py_atomic_compare_exchange_int(&gcstate->collecting, &expected, 1)) { // Don't start a garbage collection if one is already in progress. @@ -2080,9 +2078,10 @@ _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 = 0; /* initialize to prevent a compiler warning */ if (gcstate->debug & _PyGC_DEBUG_STATS) { - (void)PyTime_MonotonicRaw(&t1); PySys_WriteStderr("gc: collecting generation %d...\n", generation); + (void)PyTime_PerfCounterRaw(&t1); show_stats_each_generations(gcstate); } if (PyDTrace_GC_START_ENABLED()) { @@ -2121,8 +2120,8 @@ _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_MonotonicRaw(&t2); + PyTime_t t2 = 0; /* initialize to prevent a compiler warning */ + (void)PyTime_PerfCounterRaw(&t2); double d = PyTime_AsSecondsDouble(t2 - t1); PySys_WriteStderr( "gc: done, %zd unreachable, %zd uncollectable, %.4fs elapsed\n", From d54283b3426c37ead8010dc1abb27b46256bd30b Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?P=C3=A5l=20Gr=C3=B8n=C3=A5s=20Drange?= Date: Mon, 20 Oct 2025 12:18:09 +0200 Subject: [PATCH 10/14] Add test to check debug info written to stderr in gc --- Lib/test/test_gc.py | 20 ++++++++++++++++++++ 1 file changed, 20 insertions(+) diff --git a/Lib/test/test_gc.py b/Lib/test/test_gc.py index 4328909053465e..b43372311be571 100644 --- a/Lib/test/test_gc.py +++ b/Lib/test/test_gc.py @@ -801,6 +801,26 @@ def __del__(self): rc, out, err = assert_python_ok('-c', code) self.assertEqual(out.strip(), b'__del__ called') + def test_gc_debug_stats(self): + # Checks that debug information is printed to stderr + # when DEBUG_STATS is set. + code = """if 1: + import gc + gc.set_debug(%s) + d = {} + d[(1,2)] = 1 + gc.collect() + """ + _, _, err = assert_python_ok("-c", code % "gc.DEBUG_STATS") + self.assertIn(b"gc: collecting generation", err) + self.assertIn(b"gc: objects in each generation:", err) + self.assertIn(b"gc: objects in permanent generation:", err) + self.assertIn(b"gc: done", err) + self.assertIn(b"elapsed", err) + + _, _, err = assert_python_ok("-c", code % "0") + self.assertNotIn(b"elapsed", err) + def test_global_del_SystemExit(self): code = """if 1: class ClassWithDel: From 3527d42f61210953600df3d2c984e23b8462f032 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?P=C3=A5l=20Gr=C3=B8n=C3=A5s=20Drange?= Date: Mon, 20 Oct 2025 12:52:19 +0200 Subject: [PATCH 11/14] Use assertRegex for check debug stats --- Lib/test/test_gc.py | 9 ++++----- 1 file changed, 4 insertions(+), 5 deletions(-) diff --git a/Lib/test/test_gc.py b/Lib/test/test_gc.py index b43372311be571..780a2e9f14d4e9 100644 --- a/Lib/test/test_gc.py +++ b/Lib/test/test_gc.py @@ -812,11 +812,10 @@ def test_gc_debug_stats(self): gc.collect() """ _, _, err = assert_python_ok("-c", code % "gc.DEBUG_STATS") - self.assertIn(b"gc: collecting generation", err) - self.assertIn(b"gc: objects in each generation:", err) - self.assertIn(b"gc: objects in permanent generation:", err) - self.assertIn(b"gc: done", err) - self.assertIn(b"elapsed", err) + self.assertRegex(err, b"gc: collecting generation [0-9]+") + self.assertRegex(err, b"gc: objects in each generation: [0-9]+ [0-9]+ [0-9]+") + self.assertRegex(err, b"gc: objects in permanent generation: [0-9]+") + self.assertRegex(err, b"gc: done, [0-9]+ unreachable, [0-9]+ uncollectable, [0-9]+.[0-9]+s elapsed") _, _, err = assert_python_ok("-c", code % "0") self.assertNotIn(b"elapsed", err) From 9a4523b0c4ba3ce7326f897320e2d88127a16265 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?P=C3=A5l=20Gr=C3=B8n=C3=A5s=20Drange?= Date: Mon, 20 Oct 2025 12:55:13 +0200 Subject: [PATCH 12/14] Add decorator for skip if gil disabled --- Lib/test/test_gc.py | 1 + 1 file changed, 1 insertion(+) diff --git a/Lib/test/test_gc.py b/Lib/test/test_gc.py index 780a2e9f14d4e9..18b87bd280f10d 100644 --- a/Lib/test/test_gc.py +++ b/Lib/test/test_gc.py @@ -801,6 +801,7 @@ def __del__(self): rc, out, err = assert_python_ok('-c', code) self.assertEqual(out.strip(), b'__del__ called') + @unittest.skipIf(Py_GIL_DISABLED, "requires GC generations or increments") def test_gc_debug_stats(self): # Checks that debug information is printed to stderr # when DEBUG_STATS is set. From 4a18a471489c3135327a1e52edda5827788d1d34 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?P=C3=A5l=20Gr=C3=B8n=C3=A5s=20Drange?= Date: Mon, 20 Oct 2025 13:27:14 +0200 Subject: [PATCH 13/14] Make lines shorter in test --- Lib/test/test_gc.py | 14 +++++++++++--- 1 file changed, 11 insertions(+), 3 deletions(-) diff --git a/Lib/test/test_gc.py b/Lib/test/test_gc.py index 18b87bd280f10d..99d187f64b8482 100644 --- a/Lib/test/test_gc.py +++ b/Lib/test/test_gc.py @@ -814,9 +814,17 @@ def test_gc_debug_stats(self): """ _, _, err = assert_python_ok("-c", code % "gc.DEBUG_STATS") self.assertRegex(err, b"gc: collecting generation [0-9]+") - self.assertRegex(err, b"gc: objects in each generation: [0-9]+ [0-9]+ [0-9]+") - self.assertRegex(err, b"gc: objects in permanent generation: [0-9]+") - self.assertRegex(err, b"gc: done, [0-9]+ unreachable, [0-9]+ uncollectable, [0-9]+.[0-9]+s elapsed") + self.assertRegex( + err, + b"gc: objects in each generation: [0-9]+ [0-9]+ [0-9]+", + ) + self.assertRegex( + err, b"gc: objects in permanent generation: [0-9]+" + ) + self.assertRegex( + err, + b"gc: done, .* unreachable, .* uncollectable, .* elapsed", + ) _, _, err = assert_python_ok("-c", code % "0") self.assertNotIn(b"elapsed", err) From 48ca72af736022f7851ce6528e465dfd3d4cfe6d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?P=C3=A5l=20Gr=C3=B8n=C3=A5s=20Drange?= Date: Mon, 20 Oct 2025 15:55:28 +0200 Subject: [PATCH 14/14] Address review comments --- Lib/test/test_gc.py | 2 -- .../2025-10-20-11-24-36.gh-issue-140358.UQuKdV.rst | 1 + Python/gc.c | 5 ++--- 3 files changed, 3 insertions(+), 5 deletions(-) diff --git a/Lib/test/test_gc.py b/Lib/test/test_gc.py index 99d187f64b8482..851dac32a3bca7 100644 --- a/Lib/test/test_gc.py +++ b/Lib/test/test_gc.py @@ -808,8 +808,6 @@ def test_gc_debug_stats(self): code = """if 1: import gc gc.set_debug(%s) - d = {} - d[(1,2)] = 1 gc.collect() """ _, _, err = assert_python_ok("-c", code % "gc.DEBUG_STATS") diff --git a/Misc/NEWS.d/next/Core_and_Builtins/2025-10-20-11-24-36.gh-issue-140358.UQuKdV.rst b/Misc/NEWS.d/next/Core_and_Builtins/2025-10-20-11-24-36.gh-issue-140358.UQuKdV.rst index 2e4f6e674fb1ae..739228f7e36f20 100644 --- a/Misc/NEWS.d/next/Core_and_Builtins/2025-10-20-11-24-36.gh-issue-140358.UQuKdV.rst +++ b/Misc/NEWS.d/next/Core_and_Builtins/2025-10-20-11-24-36.gh-issue-140358.UQuKdV.rst @@ -1,3 +1,4 @@ Restore elapsed time and unreachable object count in GC debug output. These were inadvertently removed during a refactor of ``gc.c``. The debug log now again reports elapsed collection time and the number of unreachable objects. +Contributed by Pål Grønås Drange. diff --git a/Python/gc.c b/Python/gc.c index 7f15a1112323c0..fd724301c769bf 100644 --- a/Python/gc.c +++ b/Python/gc.c @@ -10,7 +10,6 @@ #include "pycore_interpframe.h" // _PyFrame_GetLocalsArray() #include "pycore_object_alloc.h" // _PyObject_MallocWithType() #include "pycore_pystate.h" // _PyThreadState_GET() -#include "pycore_time.h" // _PyTime_PerfCounterUnchecked() #include "pycore_tuple.h" // _PyTuple_MaybeUntrack() #include "pycore_weakref.h" // _PyWeakref_ClearRef() @@ -2078,7 +2077,7 @@ _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 = 0; /* initialize to prevent a compiler warning */ + PyTime_t t1; if (gcstate->debug & _PyGC_DEBUG_STATS) { PySys_WriteStderr("gc: collecting generation %d...\n", generation); (void)PyTime_PerfCounterRaw(&t1); @@ -2120,7 +2119,7 @@ _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 = 0; /* initialize to prevent a compiler warning */ + PyTime_t t2; (void)PyTime_PerfCounterRaw(&t2); double d = PyTime_AsSecondsDouble(t2 - t1); PySys_WriteStderr(