Track history of events in GCTracer.

src/heap.cc

Index: src/heap.cc
diff --git a/src/heap.cc b/src/heap.cc
index f5f4604d3b98ed34969bf952bdbded6ee61d7c84..0ff224a7f0ff919eb6a544804156a0ebf739ab60 100644
--- a/src/heap.cc
+++ b/src/heap.cc
@@ -113,8 +113,6 @@ Heap::Heap()
       total_gc_time_ms_(0.0),
       max_alive_after_gc_(0),
       min_in_mutator_(kMaxInt),
-      alive_after_last_gc_(0),
-      last_gc_end_timestamp_(base::OS::TimeCurrentMillis()),
       marking_time_(0.0),
       sweeping_time_(0.0),
       mark_compact_collector_(this),
@@ -840,7 +838,7 @@ bool Heap::CollectGarbage(GarbageCollector collector,
 
   bool next_gc_likely_to_collect_more = false;
 
-  { tracer()->start(collector, gc_reason, collector_reason);
+  { tracer()->Start(collector, gc_reason, collector_reason);
     ASSERT(AllowHeapAllocation::IsAllowed());
     DisallowHeapAllocation no_allocation_during_gc;
     GarbageCollectionPrologue();
@@ -854,7 +852,7 @@ bool Heap::CollectGarbage(GarbageCollector collector,
     }
 
     GarbageCollectionEpilogue();
-    tracer()->stop();
+    tracer()->Stop();
   }
 
   // Start incremental marking for the next cycle. The heap snapshot
@@ -5958,18 +5956,13 @@ static intptr_t CountTotalHolesSize(Heap* heap) {
 }
 
 
-void Heap::UpdateGCStatistics(double start_time,
-                              double end_time,
-                              double spent_in_mutator,
-                              double marking_time) {
-  double duration = end_time - start_time;
-  alive_after_last_gc_ = SizeOfObjects();
-  last_gc_end_timestamp_ = end_time;
-
+void Heap::UpdateCumulativeGCStatistics(double duration,
+                                        double spent_in_mutator,
+                                        double marking_time) {
   if (FLAG_print_cumulative_gc_stat) {
     total_gc_time_ms_ += duration;
     max_gc_pause_ = Max(max_gc_pause_, duration);
-    max_alive_after_gc_ = Max(max_alive_after_gc_, alive_after_last_gc_);
+    max_alive_after_gc_ = Max(max_alive_after_gc_, SizeOfObjects());
     min_in_mutator_ = Min(min_in_mutator_, spent_in_mutator);
   } else if (FLAG_trace_gc_verbose) {
     total_gc_time_ms_ += duration;
@@ -5979,77 +5972,121 @@ void Heap::UpdateGCStatistics(double start_time,
 }
 
 
-GCTracer::GCTracer(Heap* heap)
-    : start_time_(0.0),
-      end_time_(0.0),
-      start_object_size_(0),
-      end_object_size_(0),
-      start_memory_size_(0),
-      end_memory_size_(0),
-      in_free_list_or_wasted_before_gc_(0),
-      allocated_since_last_gc_(0),
-      spent_in_mutator_(0),
-      steps_count_(0),
-      steps_took_(0.0),
-      longest_step_(0.0),
-      steps_count_since_last_gc_(0),
-      steps_took_since_last_gc_(0.0),
-      heap_(heap),
-      gc_reason_(NULL),
-      collector_reason_(NULL) {
+GCTracer::Event::Event(Type type,
+                       const char* gc_reason,
+                       const char* collector_reason)
+    : type(type),
+      gc_reason(gc_reason),
+      collector_reason(collector_reason),
+      start_time(0.0),
+      end_time(0.0),
+      start_object_size(0),
+      end_object_size(0),
+      start_memory_size(0),
+      end_memory_size(0),
+      start_holes_size(0),
+      end_holes_size(0),
+      incremental_marking_steps(0),
+      incremental_marking_duration(0.0) {
   for (int i = 0; i < Scope::NUMBER_OF_SCOPES; i++) {
-    scopes_[i] = 0;
+    scopes[i] = 0;
   }
 }
 
 
-void GCTracer::start(GarbageCollector collector,
-                      const char* gc_reason,
-                      const char* collector_reason) {
-  if (!FLAG_trace_gc && !FLAG_print_cumulative_gc_stat) return;
+const char* GCTracer::Event::TypeName(bool short_name) const {
+  switch (type) {
+    case SCAVENGER:
+      if (short_name) {
+        return "s";
+      } else {
+        return "Scavenge";
+      }
+    case MARK_COMPACTOR:
+      if (short_name) {
+        return "ms";
+      } else {
+        return "Mark-sweep";
+      }
+    case START:
+      if (short_name) {
+        return "st";
+      } else {
+        return "Start";
+      }
+  }
+  return "Unknown Event Type";
+}
 
-  collector_ = collector;
-  gc_reason_ = gc_reason;
-  collector_reason_ = collector_reason;
 
-  start_time_ = base::OS::TimeCurrentMillis();
-  start_object_size_ = heap_->SizeOfObjects();
-  start_memory_size_ = heap_->isolate()->memory_allocator()->Size();
+GCTracer::GCTracer(Heap* heap)
+    : heap_(heap),
+      incremental_marking_steps_(0),
+      incremental_marking_duration_(0.0),
+      longest_incremental_marking_step_(0.0) {
+  current_ = Event(Event::START, NULL, NULL);
+  current_.end_time = base::OS::TimeCurrentMillis();
+  previous_ = previous_mark_compactor_ = current_;
+}
 
-  for (int i = 0; i < Scope::NUMBER_OF_SCOPES; i++) {
-    scopes_[i] = 0;
-  }
 
-  in_free_list_or_wasted_before_gc_ = CountTotalHolesSize(heap_);
+void GCTracer::Start(GarbageCollector collector,
+                     const char* gc_reason,
+                     const char* collector_reason) {
+  if (!FLAG_trace_gc && !FLAG_print_cumulative_gc_stat) return;
+
+  previous_ = current_;
+  if (current_.type == Event::MARK_COMPACTOR)
+    previous_mark_compactor_ = current_;
+
+  if (collector == SCAVENGER) {
+    current_ = Event(Event::SCAVENGER, gc_reason, collector_reason);
+  } else {
+    current_ = Event(Event::MARK_COMPACTOR, gc_reason, collector_reason);
+  }
 
-  allocated_since_last_gc_ =
-      heap_->SizeOfObjects() - heap_->alive_after_last_gc_;
+  current_.start_time = base::OS::TimeCurrentMillis();
+  current_.start_object_size = heap_->SizeOfObjects();
+  current_.start_memory_size = heap_->isolate()->memory_allocator()->Size();
+  current_.start_holes_size = CountTotalHolesSize(heap_);
 
-  spent_in_mutator_ = Max(start_time_ - heap_->last_gc_end_timestamp_, 0.0);
+  current_.incremental_marking_steps = incremental_marking_steps_;
+  current_.incremental_marking_duration = incremental_marking_duration_;
+  current_.longest_incremental_marking_step = longest_incremental_marking_step_;
 
-  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();
+  for (int i = 0; i < Scope::NUMBER_OF_SCOPES; i++) {
+    current_.scopes[i] = 0;
+  }
 }
 
 
-void GCTracer::stop() {
+void GCTracer::Stop() {
   if (!FLAG_trace_gc && !FLAG_print_cumulative_gc_stat) return;
 
-  end_time_ = base::OS::TimeCurrentMillis();
-  end_object_size_ = heap_->SizeOfObjects();
-  end_memory_size_ = heap_->isolate()->memory_allocator()->Size();
+  current_.end_time = base::OS::TimeCurrentMillis();
+  current_.end_object_size = heap_->SizeOfObjects();
+  current_.end_memory_size = heap_->isolate()->memory_allocator()->Size();
+  current_.end_holes_size = CountTotalHolesSize(heap_);
+
+  if (current_.type == Event::SCAVENGER) {
+    scavenger_events_.push_front(current_);
+  } else {
+    mark_compactor_events_.push_front(current_);
+  }
 
-  heap_->UpdateGCStatistics(start_time_,
-                            end_time_,
-                            spent_in_mutator_,
-                            scopes_[Scope::MC_MARK]);
+  if (current_.type == Event::MARK_COMPACTOR)
+    longest_incremental_marking_step_ = 0.0;
 
-  if (collector_ == SCAVENGER && FLAG_trace_gc_ignore_scavenger) return;
+  double duration = current_.end_time - current_.start_time;
+  double spent_in_mutator =
+      Max(current_.start_time - previous_.end_time, 0.0);

[Hannes Payer (out of office), 2014/07/23 14:35:15]

Can this line be negative? That's strange, it should always be a positive value.

[ernstm, 2014/07/23 14:59:27]

This was migrated from the old implementation of GCTracer. Not all clocks are
monotonic. Maybe this showed up as an issue when two events were back to back?
I'll leave it for now. We can still remove it in a subsequent CL.

+
+  heap_->UpdateCumulativeGCStatistics(duration,
+                                      spent_in_mutator,
+                                      current_.scopes[Scope::MC_MARK]);
+
+  if (current_.type == Event::SCAVENGER && FLAG_trace_gc_ignore_scavenger)
+    return;
 
   if (FLAG_trace_gc) {
     if (FLAG_trace_gc_nvp)
@@ -6062,40 +6099,57 @@ void GCTracer::stop() {
 }
 
 
+void GCTracer::AddIncrementalMarkingStep(double duration) {
+  incremental_marking_steps_++;
+  incremental_marking_duration_ += duration;
+  longest_incremental_marking_step_ =
+      Max(longest_incremental_marking_step_, duration);
+}
+
+
 void GCTracer::Print() const {
   PrintPID("%8.0f ms: ", heap_->isolate()->time_millis_since_init());
 
   PrintF("%s %.1f (%.1f) -> %.1f (%.1f) MB, ",
-         CollectorString(),
-         static_cast<double>(start_object_size_) / MB,
-         static_cast<double>(start_memory_size_) / MB,
-         static_cast<double>(end_object_size_) / MB,
-         static_cast<double>(end_memory_size_) / MB);
+         current_.TypeName(false),
+         static_cast<double>(current_.start_object_size) / MB,
+         static_cast<double>(current_.start_memory_size) / MB,
+         static_cast<double>(current_.end_object_size) / MB,
+         static_cast<double>(current_.end_memory_size) / MB);
 
-  int external_time = static_cast<int>(scopes_[Scope::EXTERNAL]);
+  int external_time = static_cast<int>(current_.scopes[Scope::EXTERNAL]);
   if (external_time > 0) PrintF("%d / ", external_time);
 
-  PrintF("%.1f ms", end_time_ - start_time_);
-  if (steps_count_ > 0) {
-    if (collector_ == SCAVENGER) {
+  double duration = current_.end_time - current_.start_time;
+  PrintF("%.1f ms", duration);
+  if (current_.type == Event::SCAVENGER) {
+    int steps = current_.incremental_marking_steps -
+        previous_.incremental_marking_steps;
+    if (steps > 0) {
       PrintF(" (+ %.1f ms in %d steps since last GC)",
-             steps_took_since_last_gc_,
-             steps_count_since_last_gc_);
-    } else {
+             current_.incremental_marking_duration -
+             previous_.incremental_marking_duration,
+             steps);
+    }
+  } else {
+    int steps = current_.incremental_marking_steps -
+        previous_mark_compactor_.incremental_marking_steps;
+    if (steps > 0) {
       PrintF(" (+ %.1f ms in %d steps since start of marking, "
              "biggest step %.1f ms)",
-             steps_took_,
-             steps_count_,
-             longest_step_);
+             current_.incremental_marking_duration -
+             previous_mark_compactor_.incremental_marking_duration,
+             steps,
+             current_.longest_incremental_marking_step);
     }
   }
 
-  if (gc_reason_ != NULL) {
-    PrintF(" [%s]", gc_reason_);
+  if (current_.gc_reason != NULL) {
+    PrintF(" [%s]", current_.gc_reason);
   }
 
-  if (collector_reason_ != NULL) {
-    PrintF(" [%s]", collector_reason_);
+  if (current_.collector_reason != NULL) {
+    PrintF(" [%s]", current_.collector_reason);
   }
 
   PrintF(".\n");
@@ -6105,50 +6159,47 @@ void GCTracer::Print() const {
 void GCTracer::PrintNVP() const {
   PrintPID("%8.0f ms: ", heap_->isolate()->time_millis_since_init());
 
-  PrintF("pause=%.1f ", end_time_ - start_time_);
-  PrintF("mutator=%.1f ", spent_in_mutator_);
-  PrintF("gc=");
-  switch (collector_) {
-    case SCAVENGER:
-      PrintF("s");
-      break;
-    case MARK_COMPACTOR:
-      PrintF("ms");
-      break;
-    default:
-      UNREACHABLE();
-  }
-  PrintF(" ");
-
-  PrintF("external=%.1f ", scopes_[Scope::EXTERNAL]);
-  PrintF("mark=%.1f ", scopes_[Scope::MC_MARK]);
-  PrintF("sweep=%.2f ", scopes_[Scope::MC_SWEEP]);
-  PrintF("sweepns=%.2f ", scopes_[Scope::MC_SWEEP_NEWSPACE]);
-  PrintF("sweepos=%.2f ", scopes_[Scope::MC_SWEEP_OLDSPACE]);
-  PrintF("sweepcode=%.2f ", scopes_[Scope::MC_SWEEP_CODE]);
-  PrintF("sweepcell=%.2f ", scopes_[Scope::MC_SWEEP_CELL]);
-  PrintF("sweepmap=%.2f ", scopes_[Scope::MC_SWEEP_MAP]);
-  PrintF("evacuate=%.1f ", scopes_[Scope::MC_EVACUATE_PAGES]);
-  PrintF("new_new=%.1f ", scopes_[Scope::MC_UPDATE_NEW_TO_NEW_POINTERS]);
-  PrintF("root_new=%.1f ", scopes_[Scope::MC_UPDATE_ROOT_TO_NEW_POINTERS]);
-  PrintF("old_new=%.1f ", scopes_[Scope::MC_UPDATE_OLD_TO_NEW_POINTERS]);
+  double duration = current_.end_time - current_.start_time;
+  double spent_in_mutator = current_.start_time - previous_.end_time;
+
+  PrintF("pause=%.1f ", duration);
+  PrintF("mutator=%.1f ", spent_in_mutator);
+  PrintF("gc=%s ", current_.TypeName(true));
+
+  PrintF("external=%.1f ", current_.scopes[Scope::EXTERNAL]);
+  PrintF("mark=%.1f ", current_.scopes[Scope::MC_MARK]);
+  PrintF("sweep=%.2f ", current_.scopes[Scope::MC_SWEEP]);
+  PrintF("sweepns=%.2f ", current_.scopes[Scope::MC_SWEEP_NEWSPACE]);
+  PrintF("sweepos=%.2f ", current_.scopes[Scope::MC_SWEEP_OLDSPACE]);
+  PrintF("sweepcode=%.2f ", current_.scopes[Scope::MC_SWEEP_CODE]);
+  PrintF("sweepcell=%.2f ", current_.scopes[Scope::MC_SWEEP_CELL]);
+  PrintF("sweepmap=%.2f ", current_.scopes[Scope::MC_SWEEP_MAP]);
+  PrintF("evacuate=%.1f ", current_.scopes[Scope::MC_EVACUATE_PAGES]);
+  PrintF("new_new=%.1f ",
+         current_.scopes[Scope::MC_UPDATE_NEW_TO_NEW_POINTERS]);
+  PrintF("root_new=%.1f ",
+         current_.scopes[Scope::MC_UPDATE_ROOT_TO_NEW_POINTERS]);
+  PrintF("old_new=%.1f ",
+         current_.scopes[Scope::MC_UPDATE_OLD_TO_NEW_POINTERS]);
   PrintF("compaction_ptrs=%.1f ",
-         scopes_[Scope::MC_UPDATE_POINTERS_TO_EVACUATED]);
+         current_.scopes[Scope::MC_UPDATE_POINTERS_TO_EVACUATED]);
   PrintF("intracompaction_ptrs=%.1f ",
-         scopes_[Scope::MC_UPDATE_POINTERS_BETWEEN_EVACUATED]);
-  PrintF("misc_compaction=%.1f ", scopes_[Scope::MC_UPDATE_MISC_POINTERS]);
+         current_.scopes[Scope::MC_UPDATE_POINTERS_BETWEEN_EVACUATED]);
+  PrintF("misc_compaction=%.1f ",
+         current_.scopes[Scope::MC_UPDATE_MISC_POINTERS]);
   PrintF("weakcollection_process=%.1f ",
-         scopes_[Scope::MC_WEAKCOLLECTION_PROCESS]);
+         current_.scopes[Scope::MC_WEAKCOLLECTION_PROCESS]);
   PrintF("weakcollection_clear=%.1f ",
-         scopes_[Scope::MC_WEAKCOLLECTION_CLEAR]);
+         current_.scopes[Scope::MC_WEAKCOLLECTION_CLEAR]);
 
-  PrintF("total_size_before=%" V8_PTR_PREFIX "d ", start_object_size_);
-  PrintF("total_size_after=%" V8_PTR_PREFIX "d ", end_object_size_);
-  PrintF("holes_size_before=%" V8_PTR_PREFIX "d ",
-         in_free_list_or_wasted_before_gc_);
-  PrintF("holes_size_after=%" V8_PTR_PREFIX "d ", CountTotalHolesSize(heap_));
+  PrintF("total_size_before=%" V8_PTR_PREFIX "d ", current_.start_object_size);
+  PrintF("total_size_after=%" V8_PTR_PREFIX "d ", current_.end_object_size);
+  PrintF("holes_size_before=%" V8_PTR_PREFIX "d ", current_.start_holes_size);
+  PrintF("holes_size_after=%" V8_PTR_PREFIX "d ", current_.end_holes_size);
 
-  PrintF("allocated=%" V8_PTR_PREFIX "d ", allocated_since_last_gc_);
+  intptr_t allocated_since_last_gc =
+      current_.start_object_size - previous_.end_object_size;
+  PrintF("allocated=%" V8_PTR_PREFIX "d ", allocated_since_last_gc);
   PrintF("promoted=%" V8_PTR_PREFIX "d ", heap_->promoted_objects_size_);
   PrintF("semi_space_copied=%" V8_PTR_PREFIX "d ",
          heap_->semi_space_copied_object_size_);
@@ -6158,30 +6209,23 @@ void GCTracer::PrintNVP() const {
   PrintF("promotion_rate=%.1f%% ", heap_->promotion_rate_);
   PrintF("semi_space_copy_rate=%.1f%% ", heap_->semi_space_copied_rate_);
 
-  if (collector_ == SCAVENGER) {
-    PrintF("stepscount=%d ", steps_count_since_last_gc_);
-    PrintF("stepstook=%.1f ", steps_took_since_last_gc_);
+  if (current_.type == Event::SCAVENGER) {
+    PrintF("stepscount=%d ", current_.incremental_marking_steps -
+           previous_.incremental_marking_steps);
+    PrintF("stepstook=%.1f ", current_.incremental_marking_duration -
+           previous_.incremental_marking_duration);
   } else {
-    PrintF("stepscount=%d ", steps_count_);
-    PrintF("stepstook=%.1f ", steps_took_);
-    PrintF("longeststep=%.1f ", longest_step_);
+    PrintF("stepscount=%d ", current_.incremental_marking_steps -
+           previous_mark_compactor_.incremental_marking_steps);
+    PrintF("stepstook=%.1f ", current_.incremental_marking_duration -
+           previous_mark_compactor_.incremental_marking_duration);
+    PrintF("longeststep=%.1f ", current_.longest_incremental_marking_step);
   }
 
   PrintF("\n");
 }
 
 
-const char* GCTracer::CollectorString() const {
-  switch (collector_) {
-    case SCAVENGER:
-      return "Scavenge";
-    case MARK_COMPACTOR:
-      return "Mark-sweep";
-  }
-  return "Unknown GC";
-}
-
-
 int KeyedLookupCache::Hash(Handle<Map> map, Handle<Name> name) {
   DisallowHeapAllocation no_gc;
   // Uses only lower 32 bits if pointers are larger.