GC time debug...

[David Jeske]

In debugging Python GC actions, it's really useful to know the amount
of time Python spends doing the GC cycle (i.e. the pause time). I made
a quick hack to do this, and I've attached the patch. It needs to be
fixed to be portable. I wanted to just call floattime() from
timemodule.c, but it wasn't clear how to do this from gcmodule.c.

My patch adds the gc time and the max gc time to the "done" line when
debugging is enabled, making it look like this:

gc: collecting generation 0...
gc: objects in each generation: 702 5608 72421
gc: done. (0.000267006 s, max 0.151359 s)

I'd like to see something like this added to gc module. 

I also think it would be useful if there were a debugging mode to
print out gc sweeps which take longer than a certain pause time.

(i.e. gc.debug_pauses(0.2) would print out a line for each gc pause
over 0.2 seconds)

-- 
David Jeske  
Neotonic Software Corporation
email   jeske at neotonic.com
phone   (415) 701-8003x1
fax     (415) 704-3283
-------------- next part --------------
*** Python-2.3b1/Modules/gcmodule.c	Thu Apr 17 10:29:21 2003
--- Python-2.3b1-gdtimedebug/Modules/gcmodule.c	Wed Jun 25 23:30:41 2003
***************
*** 48,53 ****
--- 48,61 ----
  
  PyGC_Head *_PyGC_generation0 = GEN_HEAD(0);
  
+ static double floattime(void) {
+     struct timeval t;
+     if (gettimeofday(&t, (struct timezone *)NULL) == 0) {
+        return (double)t.tv_sec + t.tv_usec*0.000001;
+     }
+     return 0.0;
+ }
+ 
  static int enabled = 1; /* automatic collection enabled? */
  
  /* true if we are currently running the collector */
***************
*** 524,529 ****
--- 532,538 ----
  		}
  	}
  }
+ static double max = 0.0;
  
  /* This is the main function.  Read this to understand how the
   * collection process works. */
***************
*** 538,543 ****
--- 547,553 ----
  	PyGC_Head unreachable;
  	PyGC_Head finalizers;
  	PyGC_Head *gc;
+ 	double start; /* for timing gc */
  
  	if (delstr == NULL) {
  		delstr = PyString_InternFromString("__del__");
***************
*** 553,558 ****
--- 563,569 ----
  			PySys_WriteStderr(" %ld", gc_list_size(GEN_HEAD(i)));
  		}
  		PySys_WriteStderr("\n");
+ 		start = floattime();
  	}
  
  	/* update collection and allocation counters */
***************
*** 634,646 ****
  			debug_cycle("uncollectable", FROM_GC(gc));
  	}
  	if (debug & DEBUG_STATS) {
  		if (m == 0 && n == 0) {
! 			PySys_WriteStderr("gc: done.\n");
  		}
  		else {
  			PySys_WriteStderr(
! 			    "gc: done, %ld unreachable, %ld uncollectable.\n",
! 			    n+m, n);
  		}
  	}
  
--- 645,660 ----
  			debug_cycle("uncollectable", FROM_GC(gc));
  	}
  	if (debug & DEBUG_STATS) {
+ 		double elapsed = floattime()-start;
+ 		if (elapsed > max) { max = elapsed; }
+ 
  		if (m == 0 && n == 0) {
! 			PySys_WriteStderr("gc: done. (%g s, max %g s)\n",elapsed,max);
  		}
  		else {
  			PySys_WriteStderr(
! 			    "gc: done (%g s, max %g s), %ld unreachable, %ld uncollectable.\n",
! 			    elapsed,max,n+m, n);
  		}
  	}