Add debug messages

vm/data_gc.c

@@ -1,5 +1,20 @@
 #include "master.h"
 
+#define GC_DEBUG 1
+
+#define ALLOC_DATA_HEAP "alloc_data_heap: gens=%ld, young_size=%ld, aging_size=%ld\n"
+#define GC_REQUESTED "garbage_collection: code_gc=%d, growing_data_heap=%d, requested_bytes=%ld\n"
+#define BEGIN_GC "begin_gc: code_gc=%d, growing_data_heap=%d, collecting_gen=%ld\n"
+#define END_GC "end_gc: gc_elapsed=%ld\n"
+#define END_AGING_GC "end_gc: aging_collections=%ld, cards_scanned=%ld\n"
+#define END_NURSERY_GC "end_gc: nursery_collections=%ld, cards_scanned=%ld\n"
+
+#ifdef GC_DEBUG
+	#define GC_PRINT printf
+#else
+	INLINE void GC_PRINT(...) { }
+#endif
+
 CELL init_zone(F_ZONE *z, CELL size, CELL start)
 {
 	z->size = size;
@@ -16,6 +31,8 @@ void init_cards_offset(void)
 
 F_DATA_HEAP *alloc_data_heap(CELL gens, CELL young_size, CELL aging_size)
 {
+	GC_PRINT(ALLOC_DATA_HEAP,gens,young_size,aging_size);
+
 	young_size = align_page(young_size);
 	aging_size = align_page(aging_size);
 
@@ -133,7 +150,8 @@ void init_data_heap(CELL gens,
 	extra_roots = extra_roots_region->start - CELLS;
 
 	gc_time = 0;
-	minor_collections = 0;
+	aging_collections = 0;
+	nursery_collections = 0;
 	cards_scanned = 0;
 	secure_gc = secure_gc_;
 }
@@ -618,16 +636,14 @@ void begin_gc(CELL requested_bytes)
 		so we set the newspace so the next generation. */
 		newspace = &data_heap->generations[collecting_gen + 1];
 	}
-}
 
-void major_gc_message(void)
+#ifdef GC_DEBUG
-{
+	//printf("\n");
-	fprintf(stderr,"*** %s GC (%ld minor, %ld cards)\n",
+	dump_generations();
-		collecting_code ? "Code and data" : "Data",
+	printf("Newspace: ");
-		minor_collections,cards_scanned);
+	dump_zone(newspace);
-	fflush(stderr);
+	//printf("\n");
-	minor_collections = 0;
+#endif;
-	cards_scanned = 0;
 }
 
 void end_gc(void)
@@ -637,9 +653,6 @@ void end_gc(void)
 		dealloc_data_heap(old_data_heap);
 		old_data_heap = NULL;
 		growing_data_heap = false;
-
-		fprintf(stderr,"*** Data heap resized to %lu bytes\n",
-			data_heap->segment->size);
 	}
 
 	if(collecting_accumulation_gen_p())
@@ -651,9 +664,19 @@ void end_gc(void)
 			reset_generations(NURSERY,collecting_gen - 1);
 
 		if(collecting_gen == TENURED)
-			major_gc_message();
+		{
+			GC_PRINT(END_AGING_GC,aging_collections,cards_scanned);
+			aging_collections = 0;
+			cards_scanned = 0;
+		}
 		else if(HAVE_AGING_P && collecting_gen == AGING)
-			minor_collections++;
+		{
+			aging_collections++;
+
+			GC_PRINT(END_NURSERY_GC,nursery_collections,cards_scanned);
+			nursery_collections = 0;
+			cards_scanned = 0;
+		}
 	}
 	else
 	{
@@ -661,7 +684,7 @@ void end_gc(void)
 		collected are now empty */
 		reset_generations(NURSERY,collecting_gen);
 
-		minor_collections++;
+		nursery_collections++;
 	}
 
 	if(collecting_code)
@@ -688,6 +711,8 @@ void garbage_collection(CELL gen,
 		return;
 	}
 
+	GC_PRINT(GC_REQUESTED,code_gc,growing_data_heap_,requested_bytes);
+
 	s64 start = current_millis();
 
 	performing_gc = true;
@@ -701,13 +726,17 @@ void garbage_collection(CELL gen,
 		/* We have no older generations we can try collecting, so we
 		resort to growing the data heap */
 		if(collecting_gen == TENURED)
+		{
+			if(collecting_code)
 			{
 				growing_data_heap = true;
 
 				/* see the comment in unmark_marked() */
-			if(collecting_code)
 				unmark_marked(&code_heap);
 			}
+			else
+				collecting_code = true;
+		}
 		/* we try collecting AGING space twice before going on to
 		collect TENURED */
 		else if(HAVE_AGING_P
@@ -723,6 +752,7 @@ void garbage_collection(CELL gen,
 		}
 	}
 
+	GC_PRINT(BEGIN_GC,collecting_code,growing_data_heap,collecting_gen);
 	begin_gc(requested_bytes);
 
 	/* initialize chase pointer */
@@ -754,9 +784,12 @@ void garbage_collection(CELL gen,
 	while(scan < newspace->here)
 		scan = collect_next(scan);
 
+	CELL gc_elapsed = (current_millis() - start);
+
+	GC_PRINT(END_GC,gc_elapsed);
 	end_gc();
 
-	gc_time += (current_millis() - start);
+	gc_time += gc_elapsed;
 	performing_gc = false;
 }
 

vm/data_gc.h

@@ -138,7 +138,8 @@ void init_data_heap(CELL gens,
 
 /* statistics */
 s64 gc_time;
-CELL minor_collections;
+CELL nursery_collections;
+CELL aging_collections;
 CELL cards_scanned;
 
 /* only meaningful during a GC */

vm/debug.c

@@ -218,10 +218,10 @@ void dump_memory(CELL from, CELL to)
 		dump_cell(from);
 }
 
-void dump_zone(F_ZONE z)
+void dump_zone(F_ZONE *z)
 {
-	printf("start=%lx, size=%lx, end=%lx, here=%lx\n",
+	printf("start=%ld, size=%ld, here=%ld\n",
-		z.start,z.size,z.end,z.here - z.start);
+		z->start,z->size,z->here - z->start);
 }
 
 void dump_generations(void)
@@ -230,13 +230,13 @@ void dump_generations(void)
 	for(i = 0; i < data_heap->gen_count; i++)
 	{
 		printf("Generation %d: ",i);
-		dump_zone(data_heap->generations[i]);
+		dump_zone(&data_heap->generations[i]);
 	}
 
 	for(i = 0; i < data_heap->gen_count; i++)
 	{
 		printf("Semispace %d: ",i);
-		dump_zone(data_heap->semispaces[i]);
+		dump_zone(&data_heap->semispaces[i]);
 	}
 
 	printf("Cards: base=%lx, size=%lx\n",

vm/debug.h

@@ -2,5 +2,6 @@ void print_obj(CELL obj);
 void print_nested_obj(CELL obj, F_FIXNUM nesting);
 void dump_generations(void);
 void factorbug(void);
+void dump_zone(F_ZONE *z);
 
 DECLARE_PRIMITIVE(die);

vm/master.h

@@ -20,13 +20,13 @@
 #include "layouts.h"
 #include "platform.h"
 #include "primitives.h"
-#include "debug.h"
 #include "run.h"
 #include "profiler.h"
 #include "errors.h"
 #include "bignumint.h"
 #include "bignum.h"
 #include "data_gc.h"
+#include "debug.h"
 #include "types.h"
 #include "math.h"
 #include "float_bits.h"