This is a long-ago patch I submitted to SF (1100924) to time the gc passes.

Barry approved it awhile ago.  Been sitting in my sandbox for awhile as
well.

1 files changed, 29 insertions, 0 deletions

diff --git a/Modules/gcmodule.c b/Modules/gcmodule.c
index 5d9e548..0176d6f 100644
--- a/Modules/gcmodule.c
+++ b/Modules/gcmodule.c
@@ -734,6 +734,8 @@ collect(int generation)
 	PyGC_Head unreachable; /* non-problematic unreachable trash */
 	PyGC_Head finalizers;  /* objects with, & reachable from, __del__ */
 	PyGC_Head *gc;
+	static PyObject *tmod = NULL;
+	double t1 = 0.0;
 
 	if (delstr == NULL) {
 		delstr = PyString_InternFromString("__del__");
@@ -741,7 +743,23 @@ collect(int generation)
 			Py_FatalError("gc couldn't allocate \"__del__\"");
 	}
 
+	if (tmod == NULL) {
+		tmod = PyImport_ImportModule("time");
+		if (tmod == NULL)
+			PyErr_Clear();
+	}
+
 	if (debug & DEBUG_STATS) {
+		if (tmod != NULL) {
+			PyObject *f = PyObject_CallMethod(tmod, "time", NULL);
+			if (f == NULL) {
+				PyErr_Clear();
+			}
+			else {
+				t1 = PyFloat_AsDouble(f);
+				Py_DECREF(f);
+			}
+		}
 		PySys_WriteStderr("gc: collecting generation %d...\n",
 				  generation);
 		PySys_WriteStderr("gc: objects in each generation:");
@@ -814,6 +832,17 @@ collect(int generation)
 		if (debug & DEBUG_COLLECTABLE) {
 			debug_cycle("collectable", FROM_GC(gc));
 		}
+		if (tmod != NULL && (debug & DEBUG_STATS)) {
+			PyObject *f = PyObject_CallMethod(tmod, "time", NULL);
+			if (f == NULL) {
+				PyErr_Clear();
+			}
+			else {
+				t1 = PyFloat_AsDouble(f)-t1;
+				Py_DECREF(f);
+				PySys_WriteStderr("gc: %.4fs elapsed.\n", t1);
+			}
+		}
 	}
 
 	/* Clear weakrefs and invoke callbacks as necessary. */