re-land: Track history of events in GCTracer.
authorernstm@chromium.org <ernstm@chromium.org@ce2b1a6d-e550-0410-aec6-3dcde31c8c00>
Thu, 24 Jul 2014 11:16:01 +0000 (11:16 +0000)
committerernstm@chromium.org <ernstm@chromium.org@ce2b1a6d-e550-0410-aec6-3dcde31c8c00>
Thu, 24 Jul 2014 11:16:01 +0000 (11:16 +0000)
- track incremental marking stats directly on GCTracer.
- add simple ring buffer class.
- track last 10 scavenges and mark-compacts in ring buffers on GCTracer.
- various clean-ups.

This is a re-land of https://codereview.chromium.org/391413006/ with
 - int instead of size_t in ring buffer unit test.
 - git cl format

R=hpayer@chromium.org
BUG=

Review URL: https://codereview.chromium.org/411293002

git-svn-id: https://v8.googlecode.com/svn/branches/bleeding_edge@22593 ce2b1a6d-e550-0410-aec6-3dcde31c8c00

src/heap.cc
src/heap.h
src/incremental-marking.cc
src/incremental-marking.h
test/cctest/cctest.gyp
test/cctest/cctest.status
test/cctest/test-gc-tracer.cc [new file with mode: 0644]

index c41cfc7c75edce956d85a878791643322b2537d8..4fec66c21bf14fbf58612f2ccc6f38472413d33b 100644 (file)
@@ -114,8 +114,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),
@@ -842,7 +840,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();
@@ -856,7 +854,7 @@ bool Heap::CollectGarbage(GarbageCollector collector,
     }
 
     GarbageCollectionEpilogue();
-    tracer()->stop();
+    tracer()->Stop();
   }
 
   // Start incremental marking for the next cycle. The heap snapshot
@@ -5969,16 +5967,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;
@@ -5988,74 +5983,117 @@ void Heap::UpdateGCStatistics(double start_time, double end_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* 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)
+    : 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;
 
-  collector_ = collector;
-  gc_reason_ = gc_reason;
-  collector_reason_ = collector_reason;
+  previous_ = current_;
+  if (current_.type == Event::MARK_COMPACTOR)
+    previous_mark_compactor_event_ = current_;
 
-  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 (collector == SCAVENGER) {
+    current_ = Event(Event::SCAVENGER, gc_reason, collector_reason);
+  } else {
+    current_ = Event(Event::MARK_COMPACTOR, gc_reason, collector_reason);
   }
 
-  in_free_list_or_wasted_before_gc_ = CountTotalHolesSize(heap_);
+  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_);
 
-  allocated_since_last_gc_ =
-      heap_->SizeOfObjects() - heap_->alive_after_last_gc_;
+  current_.incremental_marking_steps = incremental_marking_steps_;
+  current_.incremental_marking_duration = incremental_marking_duration_;
+  current_.longest_incremental_marking_step = longest_incremental_marking_step_;
 
-  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();
+  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_);
 
-  heap_->UpdateGCStatistics(start_time_, end_time_, spent_in_mutator_,
-                            scopes_[Scope::MC_MARK]);
+  if (current_.type == Event::SCAVENGER) {
+    scavenger_events_.push_front(current_);
+  } else {
+    mark_compactor_events_.push_front(current_);
+  }
+
+  if (current_.type == Event::MARK_COMPACTOR)
+    longest_incremental_marking_step_ = 0.0;
+
+  double duration = current_.end_time - current_.start_time;
+  double spent_in_mutator = Max(current_.start_time - previous_.end_time, 0.0);
 
-  if (collector_ == SCAVENGER && FLAG_trace_gc_ignore_scavenger) return;
+  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)
@@ -6068,37 +6106,56 @@ 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);
+  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");
@@ -6108,49 +6165,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]);
-  PrintF("weakcollection_clear=%.1f ", 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("allocated=%" V8_PTR_PREFIX "d ", allocated_since_last_gc_);
+         current_.scopes[Scope::MC_WEAKCOLLECTION_PROCESS]);
+  PrintF("weakcollection_clear=%.1f ",
+         current_.scopes[Scope::MC_WEAKCOLLECTION_CLEAR]);
+
+  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);
+
+  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_);
@@ -6160,30 +6215,25 @@ 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_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.
index a2e9dbd43404eeb4dea7d71c92b2e3f88a4d8de0..5441e97e398545b2d084ff77d2112e0ed06d9450 100644 (file)
@@ -547,10 +547,81 @@ enum ArrayStorageAllocationMode {
   INITIALIZE_ARRAY_ELEMENTS_WITH_HOLE
 };
 
+// TODO(ernstm): Move into GCTracer.
+// A simple ring buffer class with maximum size known at compile time.
+// The class only implements the functionality required in GCTracer.
+template <typename T, size_t MAX_SIZE>
+class RingBuffer {
+ public:
+  class const_iterator {
+   public:
+    const_iterator() : index_(0), elements_(NULL) {}
+
+    const_iterator(size_t index, const T* elements)
+        : index_(index), elements_(elements) {}
+
+    bool operator==(const const_iterator& rhs) const {
+      return elements_ == rhs.elements_ && index_ == rhs.index_;
+    }
+
+    bool operator!=(const const_iterator& rhs) const {
+      return elements_ != rhs.elements_ || index_ != rhs.index_;
+    }
+
+    operator const T*() const { return elements_ + index_; }
+
+    const T* operator->() const { return elements_ + index_; }
+
+    const T& operator*() const { return elements_[index_]; }
+
+    const_iterator& operator++() {
+      index_ = (index_ + 1) % (MAX_SIZE + 1);
+      return *this;
+    }
+
+    const_iterator& operator--() {
+      index_ = (index_ + MAX_SIZE) % (MAX_SIZE + 1);
+      return *this;
+    }
+
+   private:
+    size_t index_;
+    const T* elements_;
+  };
+
+  RingBuffer() : begin_(0), end_(0) {}
+
+  bool empty() const { return begin_ == end_; }
+  size_t size() const {
+    return (end_ - begin_ + MAX_SIZE + 1) % (MAX_SIZE + 1);
+  }
+  const_iterator begin() const { return const_iterator(begin_, elements_); }
+  const_iterator end() const { return const_iterator(end_, elements_); }
+  const_iterator back() const { return --end(); }
+  void push_back(const T& element) {
+    elements_[end_] = element;
+    end_ = (end_ + 1) % (MAX_SIZE + 1);
+    if (end_ == begin_) begin_ = (begin_ + 1) % (MAX_SIZE + 1);
+  }
+  void push_front(const T& element) {
+    begin_ = (begin_ + MAX_SIZE) % (MAX_SIZE + 1);
+    if (begin_ == end_) end_ = (end_ + MAX_SIZE) % (MAX_SIZE + 1);
+    elements_[begin_] = element;
+  }
+
+ private:
+  T elements_[MAX_SIZE + 1];
+  size_t begin_;
+  size_t end_;
+
+  DISALLOW_COPY_AND_ASSIGN(RingBuffer);
+};
+
 
 // GCTracer collects and prints ONE line after each garbage collector
 // invocation IFF --trace_gc is used.
 
+// TODO(ernstm): Unit tests. Move to separate file.
 class GCTracer BASE_EMBEDDED {
  public:
   class Scope BASE_EMBEDDED {
@@ -585,7 +656,8 @@ class GCTracer BASE_EMBEDDED {
 
     ~Scope() {
       ASSERT(scope_ < NUMBER_OF_SCOPES);  // scope_ is unsigned.
-      tracer_->scopes_[scope_] += base::OS::TimeCurrentMillis() - start_time_;
+      tracer_->current_.scopes[scope_] +=
+          base::OS::TimeCurrentMillis() - start_time_;
     }
 
    private:
@@ -596,72 +668,119 @@ class GCTracer BASE_EMBEDDED {
     DISALLOW_COPY_AND_ASSIGN(Scope);
   };
 
+
+  class Event {
+   public:
+    enum Type { SCAVENGER = 0, MARK_COMPACTOR = 1, START = 2 };
+
+    // Default constructor leaves the event uninitialized.
+    Event() {}
+
+    Event(Type type, const char* gc_reason, const char* collector_reason);
+
+    // Returns a string describing the event type.
+    const char* TypeName(bool short_name) const;
+
+    // Type of event
+    Type type;
+
+    const char* gc_reason;
+    const char* collector_reason;
+
+    // Timestamp set in the constructor.
+    double start_time;
+
+    // Timestamp set in the destructor.
+    double end_time;
+
+    // Size of objects in heap set in constructor.
+    intptr_t start_object_size;
+
+    // Size of objects in heap set in destructor.
+    intptr_t end_object_size;
+
+    // Size of memory allocated from OS set in constructor.
+    intptr_t start_memory_size;
+
+    // Size of memory allocated from OS set in destructor.
+    intptr_t end_memory_size;
+
+    // Total amount of space either wasted or contained in one of free lists
+    // before the current GC.
+    intptr_t start_holes_size;
+
+    // Total amount of space either wasted or contained in one of free lists
+    // after the current GC.
+    intptr_t end_holes_size;
+
+    // Number of incremental marking steps since creation of tracer.
+    // (value at start of event)
+    int incremental_marking_steps;
+
+    // Cumulative duration of incremental marking steps since creation of
+    // tracer. (value at start of event)
+    double incremental_marking_duration;
+
+    // Longest incremental marking step since start of marking.
+    // (value at start of event)
+    double longest_incremental_marking_step;
+
+    // Amounts of time spent in different scopes during GC.
+    double scopes[Scope::NUMBER_OF_SCOPES];
+  };
+
+  static const int kRingBufferMaxSize = 10;
+
+  typedef RingBuffer<Event, kRingBufferMaxSize> EventBuffer;
+
   explicit GCTracer(Heap* heap);
 
   // Start collecting data.
-  void start(GarbageCollector collector, const char* gc_reason,
+  void Start(GarbageCollector collector, const char* gc_reason,
              const char* collector_reason);
 
   // Stop collecting data and print results.
-  void stop();
+  void Stop();
 
- private:
-  // Returns a string matching the collector.
-  const char* CollectorString() const;
+  // Log an incremental marking step.
+  void AddIncrementalMarkingStep(double duration);
 
+ private:
   // Print one detailed trace line in name=value format.
+  // TODO(ernstm): Move to Heap.
   void PrintNVP() const;
 
   // Print one trace line.
+  // TODO(ernstm): Move to Heap.
   void Print() const;
 
-  // Timestamp set in the constructor.
-  double start_time_;
-
-  // Timestamp set in the destructor.
-  double end_time_;
-
-  // Size of objects in heap set in constructor.
-  intptr_t start_object_size_;
-
-  // Size of objects in heap set in destructor.
-  intptr_t end_object_size_;
-
-  // Size of memory allocated from OS set in constructor.
-  intptr_t start_memory_size_;
+  // Pointer to the heap that owns this tracer.
+  Heap* heap_;
 
-  // Size of memory allocated from OS set in destructor.
-  intptr_t end_memory_size_;
+  // Current tracer event. Populated during Start/Stop cycle. Valid after Stop()
+  // has returned.
+  Event current_;
 
-  // Type of collector.
-  GarbageCollector collector_;
+  // Previous tracer event.
+  Event previous_;
 
-  // Amounts of time spent in different scopes during GC.
-  double scopes_[Scope::NUMBER_OF_SCOPES];
+  // Previous MARK_COMPACTOR event.
+  Event previous_mark_compactor_event_;
 
-  // Total amount of space either wasted or contained in one of free lists
-  // before the current GC.
-  intptr_t in_free_list_or_wasted_before_gc_;
+  // RingBuffers for SCAVENGER events.
+  EventBuffer scavenger_events_;
 
-  // Difference between space used in the heap at the beginning of the current
-  // collection and the end of the previous collection.
-  intptr_t allocated_since_last_gc_;
+  // RingBuffers for MARK_COMPACTOR events.
+  EventBuffer mark_compactor_events_;
 
-  // Amount of time spent in mutator that is time elapsed between end of the
-  // previous collection and the beginning of the current one.
-  double spent_in_mutator_;
+  // Cumulative number of incremental marking steps since creation of tracer.
+  int incremental_marking_steps_;
 
-  // Incremental marking steps counters.
-  int steps_count_;
-  double steps_took_;
-  double longest_step_;
-  int steps_count_since_last_gc_;
-  double steps_took_since_last_gc_;
+  // Cumulative duration of incremental marking steps since creation of tracer.
+  double incremental_marking_duration_;
 
-  Heap* heap_;
-
-  const char* gc_reason_;
-  const char* collector_reason_;
+  // Longest incremental marking step since start of marking.
+  double longest_incremental_marking_step_;
 
   DISALLOW_COPY_AND_ASSIGN(GCTracer);
 };
@@ -1367,8 +1486,8 @@ class Heap {
   }
 
   // Update GC statistics that are tracked on the Heap.
-  void UpdateGCStatistics(double start_time, double end_time,
-                          double spent_in_mutator, double marking_time);
+  void UpdateCumulativeGCStatistics(double duration, double spent_in_mutator,
+                                    double marking_time);
 
   // Returns maximum GC pause.
   double get_max_gc_pause() { return max_gc_pause_; }
@@ -2238,11 +2357,6 @@ class Heap {
   // Minimal interval between two subsequent collections.
   double min_in_mutator_;
 
-  // Size of objects alive after last GC.
-  intptr_t alive_after_last_gc_;
-
-  double last_gc_end_timestamp_;
-
   // Cumulative GC time spent in marking
   double marking_time_;
 
index 91a9abbf32c27bbdb72b97f819c53d92e3736919..011e160bdc4d01fac02c7ac809bfd7b767f27453 100644 (file)
@@ -22,12 +22,8 @@ IncrementalMarking::IncrementalMarking(Heap* heap)
       marking_deque_memory_(NULL),
       marking_deque_memory_committed_(false),
       steps_count_(0),
-      steps_took_(0),
-      longest_step_(0.0),
       old_generation_space_available_at_start_of_incremental_(0),
       old_generation_space_used_at_start_of_incremental_(0),
-      steps_count_since_last_gc_(0),
-      steps_took_since_last_gc_(0),
       should_hurry_(false),
       marking_speed_(0),
       allocated_(0),
@@ -658,9 +654,6 @@ void IncrementalMarking::UpdateMarkingDequeAfterScavenge() {
     }
   }
   marking_deque_.set_top(new_top);
-
-  steps_took_since_last_gc_ = 0;
-  steps_count_since_last_gc_ = 0;
 }
 
 
@@ -895,7 +888,6 @@ void IncrementalMarking::Step(intptr_t allocated_bytes,
   }
 
   steps_count_++;
-  steps_count_since_last_gc_++;
 
   bool speed_up = false;
 
@@ -964,9 +956,7 @@ void IncrementalMarking::Step(intptr_t allocated_bytes,
       FLAG_print_cumulative_gc_stat) {
     double end = base::OS::TimeCurrentMillis();
     double delta = (end - start);
-    longest_step_ = Max(longest_step_, delta);
-    steps_took_ += delta;
-    steps_took_since_last_gc_ += delta;
+    heap_->tracer()->AddIncrementalMarkingStep(delta);
     heap_->AddMarkingTime(delta);
   }
 }
@@ -974,14 +964,10 @@ void IncrementalMarking::Step(intptr_t allocated_bytes,
 
 void IncrementalMarking::ResetStepCounters() {
   steps_count_ = 0;
-  steps_took_ = 0;
-  longest_step_ = 0.0;
   old_generation_space_available_at_start_of_incremental_ =
       SpaceLeftInOldSpace();
   old_generation_space_used_at_start_of_incremental_ =
       heap_->PromotedTotalSize();
-  steps_count_since_last_gc_ = 0;
-  steps_took_since_last_gc_ = 0;
   bytes_rescanned_ = 0;
   marking_speed_ = kInitialMarkingSpeed;
   bytes_scanned_ = 0;
index bed8e185d6411ca1e464492e64bcbd65862c580f..20cfb018ae368b5a47504ebcd59a7a21dab654a1 100644 (file)
@@ -136,16 +136,6 @@ class IncrementalMarking {
 
   inline void WhiteToGreyAndPush(HeapObject* obj, MarkBit mark_bit);
 
-  inline int steps_count() { return steps_count_; }
-
-  inline double steps_took() { return steps_took_; }
-
-  inline double longest_step() { return longest_step_; }
-
-  inline int steps_count_since_last_gc() { return steps_count_since_last_gc_; }
-
-  inline double steps_took_since_last_gc() { return steps_took_since_last_gc_; }
-
   inline void SetOldSpacePageFlags(MemoryChunk* chunk) {
     SetOldSpacePageFlags(chunk, IsMarking(), IsCompacting());
   }
@@ -226,12 +216,8 @@ class IncrementalMarking {
   MarkingDeque marking_deque_;
 
   int steps_count_;
-  double steps_took_;
-  double longest_step_;
   int64_t old_generation_space_available_at_start_of_incremental_;
   int64_t old_generation_space_used_at_start_of_incremental_;
-  int steps_count_since_last_gc_;
-  double steps_took_since_last_gc_;
   int64_t bytes_rescanned_;
   bool should_hurry_;
   int marking_speed_;
index 596bd7300d4f5d896fb319d7536353501ec35579..090aed2dd1dc67b9c4d9a33788be43561085ccff 100644 (file)
@@ -78,6 +78,7 @@
         'test-fixed-dtoa.cc',
         'test-flags.cc',
         'test-func-name-inference.cc',
+        'test-gc-tracer.cc',
         'test-global-handles.cc',
         'test-global-object.cc',
         'test-hashing.cc',
index 636ce30e29d1e2e3b9423815bed48676336f6b6d..25d5711c5e6dc0cea13dd7db477bd7a6d219bfc2 100644 (file)
   'test-api/Bug*': [FAIL],
 
   ##############################################################################
+
+  # BUG(3465): SerializeToplevelIsolates crashes.
+  'test-serialize/SerializeToplevelIsolates': [SKIP],
+
   # BUG(382): Weird test. Can't guarantee that it never times out.
   'test-api/ApplyInterruption': [PASS, TIMEOUT],
 
diff --git a/test/cctest/test-gc-tracer.cc b/test/cctest/test-gc-tracer.cc
new file mode 100644 (file)
index 0000000..190644d
--- /dev/null
@@ -0,0 +1,125 @@
+// Copyright 2014 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
+//       with the distribution.
+//     * Neither the name of Google Inc. nor the names of its
+//       contributors may be used to endorse or promote products derived
+//       from this software without specific prior written permission.
+//
+// THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
+// "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
+// LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
+// A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
+// OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
+// SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
+// LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
+// DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
+// THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
+// (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
+// OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
+
+#include <stdlib.h>
+#include <utility>
+
+#include "src/v8.h"
+
+#include "test/cctest/cctest.h"
+
+using namespace v8::internal;
+
+TEST(RingBufferPartialFill) {
+  const int max_size = 6;
+  typedef RingBuffer<int, max_size>::const_iterator Iter;
+  RingBuffer<int, max_size> ring_buffer;
+  CHECK(ring_buffer.empty());
+  CHECK_EQ(static_cast<int>(ring_buffer.size()), 0);
+  CHECK(ring_buffer.begin() == ring_buffer.end());
+
+  // Fill ring_buffer partially: [0, 1, 2]
+  for (int i = 0; i < max_size / 2; i++) ring_buffer.push_back(i);
+
+  CHECK(!ring_buffer.empty());
+  CHECK(static_cast<int>(ring_buffer.size()) == max_size / 2);
+  CHECK(ring_buffer.begin() != ring_buffer.end());
+
+  // Test forward itartion
+  int i = 0;
+  for (Iter iter = ring_buffer.begin(); iter != ring_buffer.end(); ++iter) {
+    CHECK(*iter == i);
+    ++i;
+  }
+  CHECK_EQ(i, 3);  // one past last element.
+
+  // Test backward iteration
+  i = 2;
+  Iter iter = ring_buffer.back();
+  while (true) {
+    CHECK(*iter == i);
+    if (iter == ring_buffer.begin()) break;
+    --iter;
+    --i;
+  }
+  CHECK_EQ(i, 0);
+}
+
+
+TEST(RingBufferWrapAround) {
+  const int max_size = 6;
+  typedef RingBuffer<int, max_size>::const_iterator Iter;
+  RingBuffer<int, max_size> ring_buffer;
+
+  // Fill ring_buffer (wrap around): [9, 10, 11, 12, 13, 14]
+  for (int i = 0; i < 2 * max_size + 3; i++) ring_buffer.push_back(i);
+
+  CHECK(!ring_buffer.empty());
+  CHECK(static_cast<int>(ring_buffer.size()) == max_size);
+  CHECK(ring_buffer.begin() != ring_buffer.end());
+
+  // Test forward iteration
+  int i = 9;
+  for (Iter iter = ring_buffer.begin(); iter != ring_buffer.end(); ++iter) {
+    CHECK(*iter == i);
+    ++i;
+  }
+  CHECK_EQ(i, 15);  // one past last element.
+
+  // Test backward iteration
+  i = 14;
+  Iter iter = ring_buffer.back();
+  while (true) {
+    CHECK(*iter == i);
+    if (iter == ring_buffer.begin()) break;
+    --iter;
+    --i;
+  }
+  CHECK_EQ(i, 9);
+}
+
+
+TEST(RingBufferPushFront) {
+  const int max_size = 6;
+  typedef RingBuffer<int, max_size>::const_iterator Iter;
+  RingBuffer<int, max_size> ring_buffer;
+
+  // Fill ring_buffer (wrap around): [14, 13, 12, 11, 10, 9]
+  for (int i = 0; i < 2 * max_size + 3; i++) ring_buffer.push_front(i);
+
+  CHECK(!ring_buffer.empty());
+  CHECK(static_cast<int>(ring_buffer.size()) == max_size);
+  CHECK(ring_buffer.begin() != ring_buffer.end());
+
+  // Test forward iteration
+  int i = 14;
+  for (Iter iter = ring_buffer.begin(); iter != ring_buffer.end(); ++iter) {
+    CHECK(*iter == i);
+    --i;
+  }
+  CHECK_EQ(i, 8);  // one past last element.
+}