Precisely measure duration of mark and sweep phases. Changed print_cumulative_gc_stat flag to only …

src/heap.cc

 // Copyright 2012 the V8 project authors. All rights reserved.
 // Redistribution and use in source and binary forms, with or without
 // modification, are permitted provided that the following conditions are
 // met:
 //
 //     * Redistributions of source code must retain the above copyright
 //       notice, this list of conditions and the following disclaimer.
 //     * Redistributions in binary form must reproduce the above
 //       copyright notice, this list of conditions and the following
 //       disclaimer in the documentation and/or other materials provided
@@ skipping 116 matching lines @@
       amount_of_external_allocated_memory_(0),
       amount_of_external_allocated_memory_at_last_global_gc_(0),
       old_gen_exhausted_(false),
       store_buffer_rebuilder_(store_buffer()),
       hidden_symbol_(NULL),
       global_gc_prologue_callback_(NULL),
       global_gc_epilogue_callback_(NULL),
       gc_safe_size_of_old_object_(NULL),
       total_regexp_code_generated_(0),
       tracer_(NULL),
+      marking_time_(0.0),
+      sweeping_time_(0.0),
       young_survivors_after_last_gc_(0),
       high_survival_rate_period_length_(0),
       low_survival_rate_period_length_(0),
       survival_rate_(0),
       previous_survival_rate_trend_(Heap::STABLE),
       survival_rate_trend_(Heap::STABLE),
       max_gc_pause_(0),
       total_gc_time_ms_(0),
       max_alive_after_gc_(0),
       min_in_mutator_(kMaxInt),
@@ skipping 6079 matching lines @@
 
 
 void Heap::TearDown() {
 #ifdef VERIFY_HEAP
   if (FLAG_verify_heap) {
     Verify();
   }
 #endif
 
   if (FLAG_print_cumulative_gc_stat) {
-    PrintF("\n\n");
+    PrintF("\n");
     PrintF("gc_count=%d ", gc_count_);
     PrintF("mark_sweep_count=%d ", ms_count_);
     PrintF("max_gc_pause=%d ", get_max_gc_pause());
     PrintF("total_gc_time=%d ", total_gc_time_ms_);
     PrintF("min_in_mutator=%d ", get_min_in_mutator());
     PrintF("max_alive_after_gc=%" V8_PTR_PREFIX "d ",
            get_max_alive_after_gc());
+    PrintF("total_marking_time=%f ", marking_time());
+    PrintF("total_sweeping_time=%f ", sweeping_time());
     PrintF("\n\n");
   }
 
   isolate_->global_handles()->TearDown();
 
   external_string_table_.TearDown();
 
   error_object_list_.TearDown();
 
   new_space_.TearDown();
@@ skipping 641 matching lines @@
   if (heap_->last_gc_end_timestamp_ > 0) {
     spent_in_mutator_ = Max(start_time_ - heap_->last_gc_end_timestamp_, 0.0);
   }
 
   steps_count_ = heap_->incremental_marking()->steps_count();
   steps_took_ = heap_->incremental_marking()->steps_took();
   longest_step_ = heap_->incremental_marking()->longest_step();
   steps_count_since_last_gc_ =
       heap_->incremental_marking()->steps_count_since_last_gc();
   steps_took_since_last_gc_ =
       heap_->incremental_marking()->steps_took_since_last_gc();

[Michael Starzinger, 2013/01/28 13:55:39]

As discussed offline, the GCTracer should ask the incremental marking subsystem
about it's measurement instead of having the callbacks into the heap.

[Hannes Payer (out of office), 2013/01/29 12:01:54]

I think the current solution is the "cleanest" hack, since the destructor of the
GCTracer and IncrementalMarking::ResetStepCounters() are not called
synchronously.

On 2013/01/28 13:55:39, Michael Starzinger wrote:

 }
 
 
 GCTracer::~GCTracer() {
   // Printf ONE line iff flag is set.
   if (!FLAG_trace_gc && !FLAG_print_cumulative_gc_stat) return;
 
   bool first_gc = (heap_->last_gc_end_timestamp_ == 0);
 
   heap_->alive_after_last_gc_ = heap_->SizeOfObjects();
@@ skipping 10 matching lines @@
     if (!first_gc) {
       heap_->min_in_mutator_ = Min(heap_->min_in_mutator_,
                                    static_cast<int>(spent_in_mutator_));
     }
   } else if (FLAG_trace_gc_verbose) {
     heap_->total_gc_time_ms_ += time;
   }
 
   if (collector_ == SCAVENGER && FLAG_trace_gc_ignore_scavenger) return;
 
+  heap_->AddMarkingTime(scopes_[Scope::MC_MARK]);
+
+  if (FLAG_print_cumulative_gc_stat && !FLAG_trace_gc) return;
   PrintPID("%8.0f ms: ", heap_->isolate()->time_millis_since_init());
 
   if (!FLAG_trace_gc_nvp) {
     int external_time = static_cast<int>(scopes_[Scope::EXTERNAL]);
 
     double end_memory_size_mb =
         static_cast<double>(heap_->isolate()->memory_allocator()->Size()) / MB;
 
     PrintF("%s %.1f (%.1f) -> %.1f (%.1f) MB, ",
            CollectorString(),
@@ skipping 460 matching lines @@
       static_cast<int>(object_sizes_last_time_[index]));
   FIXED_ARRAY_SUB_INSTANCE_TYPE_LIST(ADJUST_LAST_TIME_OBJECT_COUNT)
 #undef ADJUST_LAST_TIME_OBJECT_COUNT
 
   memcpy(object_counts_last_time_, object_counts_, sizeof(object_counts_));
   memcpy(object_sizes_last_time_, object_sizes_, sizeof(object_sizes_));
   ClearObjectStats();
 }
 
 } }  // namespace v8::internal