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

diff --git a/basis/stack-checker/known-words/known-words.factor b/basis/stack-checker/known-words/known-words.factor
index d064776673b51e586b7c78520bd8010d42194cad..1f03df9642ca9bc0cfe85078e457efb3702e6ecc 100644 (file)
--- a/basis/stack-checker/known-words/known-words.factor
+++ b/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

diff --git a/vm/aging_collector.cpp b/vm/aging_collector.cpp
index 7b74a00f996b4c4de9e83c2c7ebae290166f0184..e39e7e7d6f5a47e90cdfe04101b91a92f4bd9ba4 100644 (file)
--- a/vm/aging_collector.cpp
+++ b/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();

diff --git a/vm/code_heap.cpp b/vm/code_heap.cpp
index d38ec9e3f55a866e107b55fd5d9c3a830db31f67..444ec486f47b28ad4c9c3969a446f7a2695624cf 100755 (executable)
--- a/vm/code_heap.cpp
+++ b/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

diff --git a/vm/collector.hpp b/vm/collector.hpp
index d3cfa246425f6f0a3c1a88d40729b613f9a2b116..4535f98dd7f6b3d5639987e13e2f7a0cfa3cb929 100644 (file)
--- a/vm/collector.hpp
+++ b/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);
        }
 };
 

diff --git a/vm/compaction.cpp b/vm/compaction.cpp
index 399971805b7e673c25a533b2a62406433fc8fdea..4540560ac44e05e363b4fa758254027daf81dce5 100644 (file)
--- a/vm/compaction.cpp
+++ b/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();
 }
 
 }

diff --git a/vm/full_collector.cpp b/vm/full_collector.cpp
index 0c90719b51a46c394fde6f9fd5b14835500dc303..6167c73ab5d7a1ab9a5068fd4ba5dcb86724f9fc 100644 (file)
--- a/vm/full_collector.cpp
+++ b/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)

diff --git a/vm/gc.cpp b/vm/gc.cpp
index be505b4ef92b974fd3f499e736ab5d69a2279107..5d9f68e6b89db8a96c14519d98ca0c1012be9ea7 100755 (executable)
--- a/vm/gc.cpp
+++ b/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);
-
-       if(verbose_gc)
-               std::cout << "GC requested, op=" << op << std::endl;
+       current_gc = new gc_state(op,this);
 
        /* 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)
-               std::cout << "GC done, op=" << current_gc->op << std::endl;
+       current_gc->event->ended_gc(this);
+
+       if(verbose_gc) std::cout << current_gc->event << std::endl;
 
        delete current_gc;
        current_gc = NULL;

diff --git a/vm/gc.hpp b/vm/gc.hpp
index e6713af52f25d70784e45738d527b4530ce15375..fe19f93ff1beb29696e8b091507bd7786219688f 100755 (executable)
--- a/vm/gc.hpp
+++ b/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);
 
 }

diff --git a/vm/nursery_collector.cpp b/vm/nursery_collector.cpp
index 096bf7f7575cd253dc147762b29515c4ba9c4bb1..240fac60d9b7fcbd6bb297fa95052d203f9fc7c1 100644 (file)
--- a/vm/nursery_collector.cpp
+++ b/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();

diff --git a/vm/to_tenured_collector.cpp b/vm/to_tenured_collector.cpp
index 97009a5cebf694f73803cd39c41928c57078758c..a39d92d869687b7081c4193a7f1ac03f64660cac 100644 (file)
--- a/vm/to_tenured_collector.cpp
+++ b/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);