vm: get GC events working, -verbosegc switch now produces more info

basis/stack-checker/known-words/known-words.factor

@@ -501,8 +501,6 @@ M: bad-executable summary
 
 \ compact-gc { } { } define-primitive
 
-\ gc-stats { } { array } define-primitive
-
 \ (save-image) { byte-array } { } define-primitive
 
 \ (save-image-and-exit) { byte-array } { } define-primitive
@@ -701,10 +699,6 @@ M: bad-executable summary
 
 \ unimplemented { } { } define-primitive
 
-\ gc-reset { } { } define-primitive
-
-\ gc-stats { } { array } define-primitive
-
 \ jit-compile { quotation } { } define-primitive
 
 \ lookup-method { object array } { word } define-primitive

vm/aging_collector.cpp

@@ -21,9 +21,13 @@ void factor_vm::collect_aging()
 		current_gc->op = collect_to_tenured_op;
 
 		to_tenured_collector collector(this);
+
+		current_gc->event->started_code_scan();
 		collector.trace_cards(data->tenured,
 			card_points_to_aging,
 			simple_unmarker(card_mark_mask));
+		current_gc->event->ended_card_scan(collector.cards_scanned,collector.decks_scanned);
+
 		collector.tenure_reachable_objects();
 	}
 	{
@@ -37,10 +41,16 @@ void factor_vm::collect_aging()
 
 		collector.trace_roots();
 		collector.trace_contexts();
+
+		current_gc->event->started_code_scan();
 		collector.trace_code_heap_roots(&code->points_to_aging);
+		current_gc->event->ended_code_scan(collector.code_blocks_scanned);
+
 		collector.cheneys_algorithm();
 
+		current_gc->event->started_code_sweep();
 		update_code_heap_for_minor_gc(&code->points_to_aging);
+		current_gc->event->ended_code_sweep();
 
 		data->reset_generation(&nursery);
 		code->points_to_nursery.clear();

vm/code_heap.cpp

@@ -118,8 +118,10 @@ struct word_and_literal_code_heap_updater {
 
 void factor_vm::update_code_heap_words_and_literals()
 {
+	current_gc->event->started_code_sweep();
 	word_and_literal_code_heap_updater updater(this);
 	code->allocator->sweep(updater);
+	current_gc->event->ended_code_sweep();
 }
 
 /* After growing the heap, we have to perform a full relocation to update

vm/collector.hpp

@@ -79,7 +79,6 @@ template<typename TargetGeneration, typename Policy> struct collector {
 	slot_visitor<collector_workhorse<TargetGeneration,Policy> > workhorse;
 	cell cards_scanned;
 	cell decks_scanned;
-	cell card_scan_time;
 	cell code_blocks_scanned;
 
 	explicit collector(factor_vm *parent_, TargetGeneration *target_, Policy policy_) :
@@ -90,7 +89,6 @@ template<typename TargetGeneration, typename Policy> struct collector {
 		workhorse(make_collector_workhorse(parent_,target_,policy_)),
 		cards_scanned(0),
 		decks_scanned(0),
-		card_scan_time(0),
 		code_blocks_scanned(0) {}
 
 	void trace_handle(cell *handle)
@@ -179,8 +177,6 @@ template<typename TargetGeneration, typename Policy> struct collector {
 	template<typename SourceGeneration, typename Unmarker>
 	void trace_cards(SourceGeneration *gen, card mask, Unmarker unmarker)
 	{
-		u64 start_time = current_micros();
-	
 		card_deck *decks = data->decks;
 		card_deck *cards = data->cards;
 	
@@ -238,15 +234,13 @@ scan_next_object:				{
 	
 						unmarker(&cards[card_index]);
 	
-						if(!start) goto end;
+						if(!start) return;
 					}
 				}
 	
 				unmarker(&decks[deck_index]);
 			}
 		}
-
-end:		card_scan_time += (current_micros() - start_time);
 	}
 };
 

vm/compaction.cpp

@@ -112,6 +112,8 @@ struct code_block_compaction_updater {
 
 void factor_vm::collect_compact_impl(bool trace_contexts_p)
 {
+	current_gc->event->started_compaction();
+
 	tenured_space *tenured = data->tenured;
 	mark_bits<object> *data_forwarding_map = &tenured->state;
 	mark_bits<code_block> *code_forwarding_map = &code->allocator->state;
@@ -146,6 +148,8 @@ void factor_vm::collect_compact_impl(bool trace_contexts_p)
 		code_forwarder.visit_context_code_blocks();
 		code_forwarder.visit_callback_code_blocks();
 	}
+
+	current_gc->event->ended_compaction();
 }
 
 }

vm/full_collector.cpp

@@ -75,9 +75,11 @@ void factor_vm::collect_mark_impl(bool trace_contexts_p)
 
 void factor_vm::collect_sweep_impl()
 {
+	current_gc->event->started_data_sweep();
 	data->tenured->starts.clear_object_start_offsets();
 	object_start_map_updater updater(&data->tenured->starts);
 	data->tenured->sweep(updater);
+	current_gc->event->ended_data_sweep();
 }
 
 void factor_vm::collect_growing_heap(cell requested_bytes, bool trace_contexts_p)

vm/gc.cpp

@@ -3,14 +3,14 @@
 namespace factor
 {
 
-gc_state::gc_state(gc_op op_) : op(op_), start_time(current_micros()) {}
-
-gc_state::~gc_state() {}
-
 gc_event::gc_event(gc_op op_, factor_vm *parent) :
 	op(op_),
+	cards_scanned(0),
+	decks_scanned(0),
+	code_blocks_scanned(0),
 	start_time(current_micros()),
 	card_scan_time(0),
+	code_scan_time(0),
 	data_sweep_time(0),
 	code_sweep_time(0),
 	compaction_time(0)
@@ -33,7 +33,7 @@ void gc_event::ended_card_scan(cell cards_scanned_, cell decks_scanned_)
 {
 	cards_scanned += cards_scanned_;
 	decks_scanned += decks_scanned_;
-	card_scan_time = (card_scan_time - current_micros());
+	card_scan_time = (current_micros() - card_scan_time);
 }
 
 void gc_event::started_code_scan()
@@ -44,7 +44,7 @@ void gc_event::started_code_scan()
 void gc_event::ended_code_scan(cell code_blocks_scanned_)
 {
 	code_blocks_scanned += code_blocks_scanned_;
-	code_scan_time = (code_scan_time - current_micros());
+	code_scan_time = (current_micros() - code_scan_time);
 }
 
 void gc_event::started_data_sweep()
@@ -54,7 +54,7 @@ void gc_event::started_data_sweep()
 
 void gc_event::ended_data_sweep()
 {
-	data_sweep_time = (data_sweep_time - current_micros());
+	data_sweep_time = (current_micros() - data_sweep_time);
 }
 
 void gc_event::started_code_sweep()
@@ -64,7 +64,7 @@ void gc_event::started_code_sweep()
 
 void gc_event::ended_code_sweep()
 {
-	code_sweep_time = (code_sweep_time - current_micros());
+	code_sweep_time = (current_micros() - code_sweep_time);
 }
 
 void gc_event::started_compaction()
@@ -74,7 +74,7 @@ void gc_event::started_compaction()
 
 void gc_event::ended_compaction()
 {
-	compaction_time = (compaction_time - current_micros());
+	compaction_time = (current_micros() - compaction_time);
 }
 
 void gc_event::ended_gc(factor_vm *parent)
@@ -88,6 +88,55 @@ void gc_event::ended_gc(factor_vm *parent)
 	total_time = current_micros() - start_time;
 }
 
+std::ostream &operator<<(std::ostream &out, const gc_event *event)
+{
+	out << "<event\n"
+	    << " op                              = '" << event->op                              << "'\n"
+	    << " nursery_size_before             = '" << event->nursery_size_before             << "'\n"
+	    << " aging_size_before               = '" << event->aging_size_before               << "'\n"
+	    << " tenured_size_before             = '" << event->tenured_size_before             << "'\n"
+	    << " tenured_free_block_count_before = '" << event->tenured_free_block_count_before << "'\n"
+	    << " code_size_before                = '" << event->code_size_before                << "'\n"
+	    << " code_free_block_count_before    = '" << event->code_free_block_count_before    << "'\n"
+	    << " nursery_size_after              = '" << event->nursery_size_after              << "'\n"
+	    << " aging_size_after                = '" << event->aging_size_after                << "'\n"
+	    << " tenured_size_after              = '" << event->tenured_size_after              << "'\n"
+	    << " tenured_free_block_count_after  = '" << event->tenured_free_block_count_after  << "'\n"
+	    << " code_size_after                 = '" << event->code_size_after                 << "'\n"
+	    << " code_free_block_count_after     = '" << event->code_free_block_count_after     << "'\n"
+	    << " cards_scanned                   = '" << event->cards_scanned                   << "'\n"
+	    << " decks_scanned                   = '" << event->decks_scanned                   << "'\n"
+	    << " code_blocks_scanned             = '" << event->code_blocks_scanned             << "'\n"
+	    << " start_time                      = '" << event->start_time                      << "'\n"
+	    << " total_time                      = '" << event->total_time                      << "'\n"
+	    << " card_scan_time                  = '" << event->card_scan_time                  << "'\n"
+	    << " code_scan_time                  = '" << event->code_scan_time                  << "'\n"
+	    << " data_sweep_time                 = '" << event->data_sweep_time                 << "'\n"
+	    << " code_sweep_time                 = '" << event->code_sweep_time                 << "'\n"
+	    << " compaction_time                 = '" << event->compaction_time                 << "' />";
+	return out;
+}
+
+gc_state::gc_state(gc_op op_, factor_vm *parent) : op(op_), start_time(current_micros())
+{
+	event = new gc_event(op,parent);
+}
+
+gc_state::~gc_state()
+{
+	delete event;
+	event = NULL;
+}
+
+void gc_state::start_again(gc_op op_, factor_vm *parent)
+{
+	event->ended_gc(parent);
+	if(parent->verbose_gc) std::cout << event << std::endl;
+	delete event;
+	event = new gc_event(op_,parent);
+	op = op_;
+}
+
 void factor_vm::update_code_heap_for_minor_gc(std::set<code_block *> *remembered_set)
 {
 	/* The youngest generation that any code block can now reference */
@@ -104,10 +153,7 @@ void factor_vm::gc(gc_op op, cell requested_bytes, bool trace_contexts_p)
 
 	save_stacks();
 
-	current_gc = new gc_state(op);
+	current_gc = new gc_state(op,this);
-
-	if(verbose_gc)
-		std::cout << "GC requested, op=" << op << std::endl;
 
 	/* Keep trying to GC higher and higher generations until we don't run out
 	of space */
@@ -117,25 +163,22 @@ void factor_vm::gc(gc_op op, cell requested_bytes, bool trace_contexts_p)
 		switch(current_gc->op)
 		{
 		case collect_nursery_op:
-			current_gc->op = collect_aging_op;
+			current_gc->start_again(collect_aging_op,this);
 			break;
 		case collect_aging_op:
-			current_gc->op = collect_to_tenured_op;
+			current_gc->start_again(collect_to_tenured_op,this);
 			break;
 		case collect_to_tenured_op:
-			current_gc->op = collect_full_op;
+			current_gc->start_again(collect_full_op,this);
 			break;
 		case collect_full_op:
 		case collect_compact_op:
-			current_gc->op = collect_growing_heap_op;
+			current_gc->start_again(collect_growing_heap_op,this);
 			break;
 		default:
 			critical_error("Bad GC op",current_gc->op);
 			break;
 		}
-
-		if(verbose_gc)
-			std::cout << "GC rewind, op=" << current_gc->op << std::endl;
 	}
 
 	switch(current_gc->op)
@@ -166,8 +209,9 @@ void factor_vm::gc(gc_op op, cell requested_bytes, bool trace_contexts_p)
 		break;
 	}
 
-	if(verbose_gc)
+	current_gc->event->ended_gc(this);
-		std::cout << "GC done, op=" << current_gc->op << std::endl;
+
+	if(verbose_gc) std::cout << current_gc->event << std::endl;
 
 	delete current_gc;
 	current_gc = NULL;

vm/gc.hpp

@@ -10,15 +10,6 @@ enum gc_op {
 	collect_growing_heap_op
 };
 
-struct gc_state {
-	gc_op op;
-	u64 start_time;
-        jmp_buf gc_unwind;
-
-	explicit gc_state(gc_op op_);
-	~gc_state();
-};
-
 struct gc_event {
 	gc_op op;
 	cell nursery_size_before;
@@ -58,6 +49,17 @@ struct gc_event {
 	void ended_gc(factor_vm *parent);
 };
 
+struct gc_state {
+	gc_op op;
+	u64 start_time;
+        jmp_buf gc_unwind;
+	gc_event *event;
+
+	explicit gc_state(gc_op op_, factor_vm *parent);
+	~gc_state();
+	void start_again(gc_op op_, factor_vm *parent);
+};
+
 VM_C_API void inline_gc(cell *gc_roots_base, cell gc_roots_size, factor_vm *parent);
 
 }

vm/nursery_collector.cpp

@@ -17,15 +17,25 @@ void factor_vm::collect_nursery()
 
 	collector.trace_roots();
 	collector.trace_contexts();
+
+	current_gc->event->started_card_scan();
 	collector.trace_cards(data->tenured,
 		card_points_to_nursery,
 		simple_unmarker(card_points_to_nursery));
 	collector.trace_cards(data->aging,
 		card_points_to_nursery,
 		simple_unmarker(card_mark_mask));
+	current_gc->event->ended_card_scan(collector.cards_scanned,collector.decks_scanned);
+
+	current_gc->event->started_code_scan();
 	collector.trace_code_heap_roots(&code->points_to_nursery);
+	current_gc->event->ended_code_scan(collector.code_blocks_scanned);
+
 	collector.cheneys_algorithm();
+
+	current_gc->event->started_code_sweep();
 	update_code_heap_for_minor_gc(&code->points_to_nursery);
+	current_gc->event->ended_code_sweep();
 
 	data->reset_generation(&nursery);
 	code->points_to_nursery.clear();

vm/to_tenured_collector.cpp

@@ -29,12 +29,22 @@ void factor_vm::collect_to_tenured()
 
 	collector.trace_roots();
 	collector.trace_contexts();
+
+	current_gc->event->started_card_scan();
 	collector.trace_cards(data->tenured,
 		card_points_to_aging,
 		simple_unmarker(card_mark_mask));
+	current_gc->event->ended_card_scan(collector.cards_scanned,collector.decks_scanned);
+
+	current_gc->event->started_code_scan();
 	collector.trace_code_heap_roots(&code->points_to_aging);
+	current_gc->event->ended_code_scan(collector.code_blocks_scanned);
+
 	collector.tenure_reachable_objects();
+
+	current_gc->event->started_code_sweep();
 	update_code_heap_for_minor_gc(&code->points_to_aging);
+	current_gc->event->ended_code_sweep();
 
 	data->reset_generation(&nursery);
 	data->reset_generation(data->aging);