Track history of events in GCTracer.

src/heap.cc

 // Copyright 2012 the V8 project authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "src/v8.h"
 
 #include "src/accessors.h"
 #include "src/api.h"
 #include "src/base/once.h"
 #include "src/base/utils/random-number-generator.h"
@@ skipping 95 matching lines @@
       semi_space_copied_object_size_(0),
       semi_space_copied_rate_(0),
       nodes_died_in_new_space_(0),
       nodes_copied_in_new_space_(0),
       nodes_promoted_(0),
       maximum_size_scavenges_(0),
       max_gc_pause_(0.0),
       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),
       store_buffer_(this),
       marking_(this),
       incremental_marking_(this),
       number_idle_notifications_(0),
       last_idle_notification_gc_count_(0),
       last_idle_notification_gc_count_init_(false),
       mark_sweeps_since_idle_round_started_(0),
@@ skipping 705 matching lines @@
       if (FLAG_trace_incremental_marking) {
         PrintF("[IncrementalMarking] Delaying MarkSweep.\n");
       }
       collector = SCAVENGER;
       collector_reason = "incremental marking delaying mark-sweep";
     }
   }
 
   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();
 
     {
       HistogramTimerScope histogram_timer_scope(
           (collector == SCAVENGER) ? isolate_->counters()->gc_scavenger()
                                    : isolate_->counters()->gc_compactor());
       next_gc_likely_to_collect_more =
           PerformGarbageCollection(collector, gc_callback_flags);
     }
 
     GarbageCollectionEpilogue();
-    tracer()->stop();
+    tracer()->Stop();
   }
 
   // Start incremental marking for the next cycle. The heap snapshot
   // generator needs incremental marking to stay off after it aborted.
   if (!mark_compact_collector()->abort_incremental_marking() &&
       incremental_marking()->IsStopped() &&
       incremental_marking()->WorthActivating() &&
       NextGCIsLikelyToBeFull()) {
     incremental_marking()->Start();
   }
@@ skipping 5083 matching lines @@
   OldSpaces spaces(heap);
   for (OldSpace* space = spaces.next();
        space != NULL;
        space = spaces.next()) {
     holes_size += space->Waste() + space->Available();
   }
   return holes_size;
 }
 
 
-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;
   }
 
   marking_time_ += marking_time;
 }
 
+GCTracer::Event::Event()
+    : collector(MARK_COMPACTOR),
+      gc_reason(NULL),
+      collector_reason(NULL),
+      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;
+  }
+}
+
+GCTracer::Event::Event(GarbageCollector collector,
+                       const char* gc_reason,
+                       const char* collector_reason)
+    : collector(collector),
+      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;
+  }
+}
+
 
 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) {
+    : heap_(heap),
+      incremental_marking_steps_(0),
+      incremental_marking_duration_(0.0),
+      longest_incremental_marking_step_(0.0) {
+  double time = base::OS::TimeCurrentMillis();
+
+  Event mark_compactor_dummy_event(MARK_COMPACTOR, NULL, NULL);

[Hannes Payer (out of office), 2014/07/22 09:10:17]

Hmm, I am not sure if the dummy elements may be problematic. What about
calculating the average gc time of the events in a buffer. The dummy element
would have an impact on that.

[ernstm, 2014/07/22 14:09:28]

Good point. I've added a type to the Event that will allow us to filter out the
dummy events (now called ANCHOR). Not having them will complicate a lot of the
code, because we need stats at GCTracer construction time to compute deltas for
the first real GC event.

+  mark_compactor_dummy_event.end_time = time;
+  event_buffers_[MARK_COMPACTOR].push_back(mark_compactor_dummy_event);
+
+  Event scavenger_dummy_event(SCAVENGER, NULL, NULL);
+  scavenger_dummy_event.end_time = time;
+  event_buffers_[SCAVENGER].push_back(scavenger_dummy_event);
+}
+
+
+void GCTracer::Start(GarbageCollector collector,
+                     const char* gc_reason,
+                     const char* collector_reason) {
+  if (!FLAG_trace_gc && !FLAG_print_cumulative_gc_stat) return;
+
+  pending_ = Event(collector, gc_reason, collector_reason);
+
+  pending_.start_time = base::OS::TimeCurrentMillis();
+  pending_.start_object_size = heap_->SizeOfObjects();
+  pending_.start_memory_size = heap_->isolate()->memory_allocator()->Size();
+  pending_.start_holes_size = CountTotalHolesSize(heap_);
+
+  pending_.incremental_marking_steps = incremental_marking_steps_;
+  pending_.incremental_marking_duration = incremental_marking_duration_;
+  pending_.longest_incremental_marking_step = longest_incremental_marking_step_;
+
   for (int i = 0; i < Scope::NUMBER_OF_SCOPES; i++) {
-    scopes_[i] = 0;
+    pending_.scopes[i] = 0;
   }
 }
 
 
-void GCTracer::start(GarbageCollector collector,
-                      const char* gc_reason,
-                      const char* collector_reason) {
+void GCTracer::Stop() {
   if (!FLAG_trace_gc && !FLAG_print_cumulative_gc_stat) return;
 
-  collector_ = collector;
-  gc_reason_ = gc_reason;
-  collector_reason_ = collector_reason;
+  pending_.end_time = base::OS::TimeCurrentMillis();
+  pending_.end_object_size = heap_->SizeOfObjects();
+  pending_.end_memory_size = heap_->isolate()->memory_allocator()->Size();
+  pending_.end_holes_size = CountTotalHolesSize(heap_);
 
-  start_time_ = base::OS::TimeCurrentMillis();
-  start_object_size_ = heap_->SizeOfObjects();
-  start_memory_size_ = heap_->isolate()->memory_allocator()->Size();
+  event_buffers_[pending_.collector].push_back(pending_);
 
-  for (int i = 0; i < Scope::NUMBER_OF_SCOPES; i++) {
-    scopes_[i] = 0;
-  }
+  if (pending_.collector == MARK_COMPACTOR)
+    longest_incremental_marking_step_ = 0.0;
 
-  in_free_list_or_wasted_before_gc_ = CountTotalHolesSize(heap_);
+  double duration = pending_.end_time - pending_.start_time;
+  double spent_in_mutator =
+      Max(pending_.start_time - Previous()->end_time, 0.0);
 
-  allocated_since_last_gc_ =
-      heap_->SizeOfObjects() - heap_->alive_after_last_gc_;
+  heap_->UpdateCumulativeGCStatistics(duration,
+                                      spent_in_mutator,
+                                      Current()->scopes[Scope::MC_MARK]);
 
-  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();
-}
-
-
-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();
-
-  heap_->UpdateGCStatistics(start_time_,
-                            end_time_,
-                            spent_in_mutator_,
-                            scopes_[Scope::MC_MARK]);
-
-  if (collector_ == SCAVENGER && FLAG_trace_gc_ignore_scavenger) return;
+  if (Current()->collector == SCAVENGER && FLAG_trace_gc_ignore_scavenger)
+    return;
 
   if (FLAG_trace_gc) {
     if (FLAG_trace_gc_nvp)
       PrintNVP();
     else
       Print();
 
     heap_->PrintShortHeapStatistics();
   }
 }
 
 
+void GCTracer::AddIncrementalMarkingStep(double duration) {
+  incremental_marking_steps_++;
+  incremental_marking_duration_ += duration;
+  longest_incremental_marking_step_ =
+      Max(longest_incremental_marking_step_, duration);
+}
+
+
+GCTracer::EventBuffer::const_iterator GCTracer::Current() const {
+  if (event_buffers_[SCAVENGER].back()->end_time >=
+      event_buffers_[MARK_COMPACTOR].back()->end_time)
+    return event_buffers_[SCAVENGER].back();
+  else
+    return event_buffers_[MARK_COMPACTOR].back();
+}
+
+
+GCTracer::EventBuffer::const_iterator GCTracer::Previous() const {
+  EventBuffer::const_iterator current = this->Current();
+  EventBuffer::const_iterator previous = current;
+  --previous;
+  GarbageCollector other_buffer =
+      (current->collector == SCAVENGER) ? MARK_COMPACTOR : SCAVENGER;
+  if (!previous ||
+      event_buffers_[other_buffer].back()->end_time > previous->end_time)
+    previous = event_buffers_[other_buffer].back();
+
+  return previous;
+}
+
+
 void GCTracer::Print() const {
+  EventBuffer::const_iterator current = Current();
+  EventBuffer::const_iterator previous = Previous();
+
   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);
+         CollectorString(current->collector, 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->collector == 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 {
+    EventBuffer::const_iterator previous_mark_compactor = current;
+    --previous_mark_compactor;
+    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");
 }
 
 
 void GCTracer::PrintNVP() const {
+  EventBuffer::const_iterator current = Current();
+  EventBuffer::const_iterator previous = Previous();
+
   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(" ");
+  double duration = current->end_time - current->start_time;
+  double spent_in_mutator = current->start_time - previous->end_time;
 
-  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]);
+  PrintF("pause=%.1f ", duration);
+  PrintF("mutator=%.1f ", spent_in_mutator);
+  PrintF("gc=%s ", CollectorString(current->collector, 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_);
   PrintF("nodes_died_in_new=%d ", heap_->nodes_died_in_new_space_);
   PrintF("nodes_copied_in_new=%d ", heap_->nodes_copied_in_new_space_);
   PrintF("nodes_promoted=%d ", heap_->nodes_promoted_);
   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->collector == 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_);
+    EventBuffer::const_iterator previous_mark_compactor = current;
+    --previous_mark_compactor;
+    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_) {
+const char* GCTracer::CollectorString(GarbageCollector collector,
+                                      bool short_name) const {
+  switch (collector) {
     case SCAVENGER:
-      return "Scavenge";
+      if (short_name)
+        return "s";
+      else
+        return "Scavenge";
     case MARK_COMPACTOR:
-      return "Mark-sweep";
+      if (short_name)
+        return "ms";
+      else
+        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.
   uintptr_t addr_hash =
       static_cast<uint32_t>(reinterpret_cast<uintptr_t>(*map)) >> kMapHashShift;
@@ skipping 251 matching lines @@
       static_cast<int>(object_sizes_last_time_[index]));
   CODE_AGE_LIST_COMPLETE(ADJUST_LAST_TIME_OBJECT_COUNT)
 #undef ADJUST_LAST_TIME_OBJECT_COUNT
 
   MemCopy(object_counts_last_time_, object_counts_, sizeof(object_counts_));
   MemCopy(object_sizes_last_time_, object_sizes_, sizeof(object_sizes_));
   ClearObjectStats();
 }
 
 } }  // namespace v8::internal