simple GC instrumentation

simple GC instrumentation

[Dan Nicolaescu]

I have a small patch that prints the GC statistics, this is interesting
during dumping, it shows which files allocate memory/generate garbage, etc.

There's also a counter for the number of calls to "mark_object", we want
to keep that low to speed up GC.

There's also a new command garbage-collect-with-print that prints all
the strings found during GC
Use:
emacs -batch -f garbage-collect-with-print |& more
to see what strings are there, and move as many as possible to pure
memory.

Maybe someone here will find this stuff useful...

Index: alloc.c
===================================================================
RCS file: /cvsroot/emacs/emacs/src/alloc.c,v
retrieving revision 1.450
diff -u -3 -p -u -p -r1.450 alloc.c
--- alloc.c	19 Oct 2009 04:27:11 -0000	1.450
+++ alloc.c	23 Oct 2009 16:52:52 -0000
@@ -2051,6 +2049,7 @@ allocate_string_data (s, nchars, nbytes)
   consing_since_gc += needed;
 }
 
+static int enable_gc_print=0;
 
 /* Sweep and compact strings.  */
 
@@ -2089,6 +2088,14 @@ sweep_strings ()
 
 		  ++total_strings;
 		  total_string_size += STRING_BYTES (s);
+
+		  if (enable_gc_print)
+		    {
+		      Lisp_Object string;
+		      XSETSTRING (string, s);
+		      Fprin1 (string, Qnil);
+		    }
+
 		}
 	      else
 		{
@@ -4957,6 +4964,7 @@ inhibit_garbage_collection ()
   return count;
 }
 
+int call_count_mark_object = 0;
 
 DEFUN ("garbage-collect", Fgarbage_collect, Sgarbage_collect, 0, 0, "",
        doc: /* Reclaim storage for Lisp objects no longer needed.
@@ -4980,6 +4988,9 @@ returns nil, because real GC can't be do
   Lisp_Object total[8];
   int count = SPECPDL_INDEX ();
   EMACS_TIME t1, t2, t3;
+  int bef = call_count_mark_object;
+
+  /* fprintf (stderr, "bef gc mark_object count = %d\n", call_count_mark_object); */
 
   if (abort_on_gc)
     abort ();
@@ -5272,9 +5283,20 @@ returns nil, because real GC can't be do
 			      EMACS_USECS (t3) * 1.0e-6);
   gcs_done++;
 
+  fprintf (stderr, "after gc mark_object delta==%d conses=%d free_conses=%d symbols=%d free_symbols=%d markers=%d free_markers=%d string_ssize=%d vectors=%d floats=%d free_floats=%d interv=%d free_interv=%d strings=%d free_strings=%d pure-bytes-nonlisp=%d pure-bytes=%d\n", call_count_mark_object - bef, total_conses,  total_free_conses,  total_symbols,  total_free_symbols, total_markers,  total_free_markers,  total_string_size,  total_vector_size,  total_floats,  total_free_floats, total_intervals,  total_free_intervals,  total_strings,  total_free_strings, pure_bytes_used_non_lisp, pure_bytes_used);
+
   return Flist (sizeof total / sizeof *total, total);
 }
 
+DEFUN ("garbage-collect-with-print", Fgarbage_collect_with_print, Sgarbage_collect_with_print, 0, 0, "",
+       doc: /*  */)
+     ()
+{
+  enable_gc_print=1;
+  Fgarbage_collect();
+  enable_gc_print=0;
+  return Qnil;
+}
 
 /* Mark Lisp objects in glyph matrix MATRIX.  Currently the
    only interesting objects referenced from glyphs are strings.  */
@@ -5404,6 +5426,8 @@ mark_object (arg)
 #endif
   int cdr_count = 0;
 
+  call_count_mark_object++;
+
  loop:
 
   if (PURE_POINTER_P (XPNTR (obj)))
@@ -5902,6 +5926,7 @@ gc_sweep ()
 	    cons_free_list = cblk->conses[0].u.chain;
 	    lisp_align_free (cblk);
 	    n_cons_blocks--;
+	    fprintf(stderr, "deallocate block\n");
 	  }
 	else
 	  {
@@ -6047,6 +6073,12 @@ gc_sweep ()
 		if (!pure_p)
 		  UNMARK_STRING (XSTRING (sym->xname));
 		sym->gcmarkbit = 0;
+		if (enable_gc_print)
+		  {
+		    Lisp_Object string;
+		    XSETSTRING (string, s);
+		    Fprin1 (string, Qnil);
+		  }
 	      }
 	  }
 
@@ -6343,6 +6375,9 @@ If this portion is smaller than `gc-cons
   DEFVAR_INT ("pure-bytes-used", &pure_bytes_used,
 	      doc: /* Number of bytes of sharable Lisp data allocated so far.  */);
 
+  DEFVAR_INT ("pure-bytes-used-nonlisp", &pure_bytes_used_non_lisp,
+	      doc: /* Number of bytes of sharable non Lisp data allocated so far.  */);
+
   DEFVAR_INT ("cons-cells-consed", &cons_cells_consed,
 	      doc: /* Number of cons cells that have been consed so far.  */);
 
@@ -6417,6 +6452,7 @@ The time is in seconds as a floating poi
   defsubr (&Smake_marker);
   defsubr (&Spurecopy);
   defsubr (&Sgarbage_collect);
+  defsubr (&Sgarbage_collect_with_print);
   defsubr (&Smemory_limit);
   defsubr (&Smemory_use_counts);