re-land: 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 96 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 706 matching lines @@
         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 5092 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(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;
+  }
+}
+
+
+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";
+}
+
+
 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) {
+  current_ = Event(Event::START, NULL, NULL);
+  current_.end_time = base::OS::TimeCurrentMillis();
+  previous_ = previous_mark_compactor_event_ = current_;
+}
+
+
+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_event_ = current_;
+
+  if (collector == SCAVENGER) {
+    current_ = Event(Event::SCAVENGER, gc_reason, collector_reason);
+  } else {
+    current_ = Event(Event::MARK_COMPACTOR, gc_reason, collector_reason);
+  }
+
+  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_);
+
+  current_.incremental_marking_steps = incremental_marking_steps_;
+  current_.incremental_marking_duration = incremental_marking_duration_;
+  current_.longest_incremental_marking_step = longest_incremental_marking_step_;
+
   for (int i = 0; i < Scope::NUMBER_OF_SCOPES; i++) {
-    scopes_[i] = 0;
+    current_.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;
+  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_);
 
-  start_time_ = base::OS::TimeCurrentMillis();
-  start_object_size_ = heap_->SizeOfObjects();
-  start_memory_size_ = heap_->isolate()->memory_allocator()->Size();
-
-  for (int i = 0; i < Scope::NUMBER_OF_SCOPES; i++) {
-    scopes_[i] = 0;
+  if (current_.type == Event::SCAVENGER) {
+    scavenger_events_.push_front(current_);
+  } else {
+    mark_compactor_events_.push_front(current_);
   }
 
-  in_free_list_or_wasted_before_gc_ = CountTotalHolesSize(heap_);
+  if (current_.type == Event::MARK_COMPACTOR)
+    longest_incremental_marking_step_ = 0.0;
 
-  allocated_since_last_gc_ =
-      heap_->SizeOfObjects() - heap_->alive_after_last_gc_;
+  double duration = current_.end_time - current_.start_time;
+  double spent_in_mutator = Max(current_.start_time - previous_.end_time, 0.0);
 
-  spent_in_mutator_ = Max(start_time_ - heap_->last_gc_end_timestamp_, 0.0);
+  heap_->UpdateCumulativeGCStatistics(duration, spent_in_mutator,
+                                      current_.scopes[Scope::MC_MARK]);
 
-  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_.type == Event::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);
+}
+
+
 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);
+  PrintF("%s %.1f (%.1f) -> %.1f (%.1f) 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_event_.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_event_.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 {
   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 ", 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]);
-  PrintF("weakcollection_clear=%.1f ", scopes_[Scope::MC_WEAKCOLLECTION_CLEAR]);
+         current_.scopes[Scope::MC_WEAKCOLLECTION_PROCESS]);
+  PrintF("weakcollection_clear=%.1f ",
+         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_.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_event_.incremental_marking_steps);
+    PrintF("stepstook=%.1f ",
+           current_.incremental_marking_duration -
+               previous_mark_compactor_event_.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.
   uintptr_t addr_hash =
       static_cast<uint32_t>(reinterpret_cast<uintptr_t>(*map)) >> kMapHashShift;
   return static_cast<uint32_t>((addr_hash ^ name->Hash()) & kCapacityMask);
 }
 
 
 int KeyedLookupCache::Lookup(Handle<Map> map, Handle<Name> name) {
@@ skipping 246 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