Track size of incremental marking steps in GCTracer.

- Track size of bytes marked incrementally
- Add method to compute marking speed in bytes/millisecond
- Distinguish between cumulative and differential marking stats.
- Fix methods that compute incremental marking stats.

R=hpayer@chromium.org
BUG=

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

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

src/gc-tracer.cc

@@ -32,8 +32,13 @@ GCTracer::Event::Event(Type type, const char* gc_reason,
       end_memory_size(0),
       start_holes_size(0),
       end_holes_size(0),
+      cumulative_incremental_marking_steps(0),
       incremental_marking_steps(0),
-      incremental_marking_duration(0.0) {
+      cumulative_incremental_marking_bytes(0),
+      incremental_marking_bytes(0),
+      cumulative_incremental_marking_duration(0.0),
+      incremental_marking_duration(0.0),
+      longest_incremental_marking_step(0.0) {
   for (int i = 0; i < Scope::NUMBER_OF_SCOPES; i++) {
     scopes[i] = 0;
   }
@@ -67,8 +72,9 @@ const char* GCTracer::Event::TypeName(bool short_name) const {
 
 GCTracer::GCTracer(Heap* heap)
     : heap_(heap),
-      incremental_marking_steps_(0),
-      incremental_marking_duration_(0.0),
+      cumulative_incremental_marking_steps_(0),
+      cumulative_incremental_marking_bytes_(0),
+      cumulative_incremental_marking_duration_(0.0),
       longest_incremental_marking_step_(0.0) {
   current_ = Event(Event::START, NULL, NULL);
   current_.end_time = base::OS::TimeCurrentMillis();
@@ -93,8 +99,12 @@ void GCTracer::Start(GarbageCollector collector, const char* gc_reason,
   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_.cumulative_incremental_marking_steps =
+      cumulative_incremental_marking_steps_;
+  current_.cumulative_incremental_marking_bytes =
+      cumulative_incremental_marking_bytes_;
+  current_.cumulative_incremental_marking_duration =
+      cumulative_incremental_marking_duration_;
   current_.longest_incremental_marking_step = longest_incremental_marking_step_;
 
   for (int i = 0; i < Scope::NUMBER_OF_SCOPES; i++) {
@@ -110,14 +120,30 @@ void GCTracer::Stop() {
   current_.end_holes_size = CountTotalHolesSize(heap_);
 
   if (current_.type == Event::SCAVENGER) {
+    current_.incremental_marking_steps =
+        current_.cumulative_incremental_marking_steps -
+        previous_.cumulative_incremental_marking_steps;
+    current_.incremental_marking_bytes =
+        current_.cumulative_incremental_marking_bytes -
+        previous_.cumulative_incremental_marking_bytes;
+    current_.incremental_marking_duration =
+        current_.cumulative_incremental_marking_duration -
+        previous_.cumulative_incremental_marking_duration;
     scavenger_events_.push_front(current_);
   } else {
+    current_.incremental_marking_steps =
+        current_.cumulative_incremental_marking_steps -
+        previous_mark_compactor_event_.cumulative_incremental_marking_steps;
+    current_.incremental_marking_bytes =
+        current_.cumulative_incremental_marking_bytes -
+        previous_mark_compactor_event_.cumulative_incremental_marking_bytes;
+    current_.incremental_marking_duration =
+        current_.cumulative_incremental_marking_duration -
+        previous_mark_compactor_event_.cumulative_incremental_marking_duration;
+    longest_incremental_marking_step_ = 0.0;
     mark_compactor_events_.push_front(current_);
   }
 
-  if (current_.type == Event::MARK_COMPACTOR)
-    longest_incremental_marking_step_ = 0.0;
-
   // TODO(ernstm): move the code below out of GCTracer.
 
   if (!FLAG_trace_gc && !FLAG_print_cumulative_gc_stat) return;
@@ -142,9 +168,10 @@ void GCTracer::Stop() {
 }
 
 
-void GCTracer::AddIncrementalMarkingStep(double duration) {
-  incremental_marking_steps_++;
-  incremental_marking_duration_ += duration;
+void GCTracer::AddIncrementalMarkingStep(double duration, intptr_t bytes) {
+  cumulative_incremental_marking_steps_++;
+  cumulative_incremental_marking_bytes_ += bytes;
+  cumulative_incremental_marking_duration_ += duration;
   longest_incremental_marking_step_ =
       Max(longest_incremental_marking_step_, duration);
 }
@@ -165,24 +192,19 @@ void GCTracer::Print() const {
   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) {
+    if (current_.incremental_marking_steps > 0) {
       PrintF(" (+ %.1f ms in %d steps since last GC)",
-             current_.incremental_marking_duration -
-                 previous_.incremental_marking_duration,
-             steps);
+             current_.incremental_marking_duration,
+             current_.incremental_marking_steps);
     }
   } else {
-    int steps = current_.incremental_marking_steps -
-                previous_mark_compactor_event_.incremental_marking_steps;
-    if (steps > 0) {
+    if (current_.incremental_marking_steps > 0) {
       PrintF(
           " (+ %.1f ms in %d steps since start of marking, "
           "biggest step %.1f ms)",
-          current_.incremental_marking_duration -
-              previous_mark_compactor_event_.incremental_marking_duration,
-          steps, current_.longest_incremental_marking_step);
+          current_.incremental_marking_duration,
+          current_.incremental_marking_steps,
+          current_.longest_incremental_marking_step);
     }
   }
 
@@ -252,18 +274,13 @@ void GCTracer::PrintNVP() const {
   PrintF("semi_space_copy_rate=%.1f%% ", heap_->semi_space_copied_rate_);
 
   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);
+    PrintF("steps_count=%d ", current_.incremental_marking_steps);
+    PrintF("steps_took=%.1f ", current_.incremental_marking_duration);
   } else {
-    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("steps_count=%d ", current_.incremental_marking_steps);
+    PrintF("steps_took=%.1f ", current_.incremental_marking_duration);
+    PrintF("longest_step=%.1f ", current_.longest_incremental_marking_step);
+    PrintF("marking_throughput=%d\n", MarkingSpeedInBytesPerMillisecond());
   }
 
   PrintF("\n");
@@ -299,19 +316,66 @@ double GCTracer::MaxDuration(const EventBuffer& events) const {
 
 
 double GCTracer::MeanIncrementalMarkingDuration() const {
-  if (mark_compactor_events_.empty()) return 0.0;
+  if (cumulative_incremental_marking_steps_ == 0) return 0.0;
+
+  // We haven't completed an entire round of incremental marking, yet.
+  // Use data from GCTracer instead of data from event buffers.
+  if (mark_compactor_events_.empty()) {
+    return cumulative_incremental_marking_duration_ /
+           cumulative_incremental_marking_steps_;
+  }
 
-  EventBuffer::const_iterator last_mc = mark_compactor_events_.begin();
-  return last_mc->incremental_marking_duration /
-         last_mc->incremental_marking_steps;
+  int steps = 0;
+  double durations = 0.0;
+  EventBuffer::const_iterator iter = mark_compactor_events_.begin();
+  while (iter != mark_compactor_events_.end()) {
+    steps += iter->incremental_marking_steps;
+    durations += iter->incremental_marking_duration;
+    ++iter;
+  }
+
+  if (steps == 0) return 0.0;
+
+  return durations / steps;
 }
 
 
 double GCTracer::MaxIncrementalMarkingDuration() const {
-  if (mark_compactor_events_.empty()) return 0.0;
+  // We haven't completed an entire round of incremental marking, yet.
+  // Use data from GCTracer instead of data from event buffers.
+  if (mark_compactor_events_.empty()) return longest_incremental_marking_step_;
+
+  double max_duration = 0.0;
+  EventBuffer::const_iterator iter = mark_compactor_events_.begin();
+  while (iter != mark_compactor_events_.end())
+    max_duration = Max(iter->longest_incremental_marking_step, max_duration);
+
+  return max_duration;
+}
+
+
+intptr_t GCTracer::MarkingSpeedInBytesPerMillisecond() const {
+  if (cumulative_incremental_marking_duration_ == 0.0) return 0;
+
+  // We haven't completed an entire round of incremental marking, yet.
+  // Use data from GCTracer instead of data from event buffers.
+  if (mark_compactor_events_.empty()) {
+    return static_cast<intptr_t>(cumulative_incremental_marking_bytes_ /
+                                 cumulative_incremental_marking_duration_);
+  }
+
+  intptr_t bytes = 0;
+  double durations = 0.0;
+  EventBuffer::const_iterator iter = mark_compactor_events_.begin();
+  while (iter != mark_compactor_events_.end()) {
+    bytes += iter->incremental_marking_bytes;
+    durations += iter->incremental_marking_duration;
+    ++iter;
+  }
+
+  if (durations == 0.0) return 0;
 
-  EventBuffer::const_iterator last_mc = mark_compactor_events_.begin();
-  return last_mc->longest_incremental_marking_step;
+  return static_cast<intptr_t>(bytes / durations);
 }
 }
 }  // namespace v8::internal

src/gc-tracer.h

@@ -172,10 +172,28 @@ class GCTracer BASE_EMBEDDED {
 
     // Number of incremental marking steps since creation of tracer.
     // (value at start of event)
+    int cumulative_incremental_marking_steps;
+
+    // Incremental marking steps since
+    // - last event for SCAVENGER events
+    // - last MARK_COMPACTOR event for MARK_COMPACTOR events
     int incremental_marking_steps;
 
+    // Bytes marked since creation of tracer (value at start of event).
+    intptr_t cumulative_incremental_marking_bytes;
+
+    // Bytes marked since
+    // - last event for SCAVENGER events
+    // - last MARK_COMPACTOR event for MARK_COMPACTOR events
+    intptr_t incremental_marking_bytes;
+
     // Cumulative duration of incremental marking steps since creation of
     // tracer. (value at start of event)
+    double cumulative_incremental_marking_duration;
+
+    // Duration of incremental marking steps since
+    // - last event for SCAVENGER events
+    // - last MARK_COMPACTOR event for MARK_COMPACTOR events
     double incremental_marking_duration;
 
     // Longest incremental marking step since start of marking.
@@ -200,7 +218,7 @@ class GCTracer BASE_EMBEDDED {
   void Stop();
 
   // Log an incremental marking step.
-  void AddIncrementalMarkingStep(double duration);
+  void AddIncrementalMarkingStep(double duration, intptr_t bytes);
 
   // Compute the mean duration of the last scavenger events. Returns 0 if no
   // events have been recorded.
@@ -232,6 +250,10 @@ class GCTracer BASE_EMBEDDED {
   // Returns 0 if no incremental marking round has been completed.
   double MaxIncrementalMarkingDuration() const;
 
+  // Compute the average incremental marking speed in bytes/second. Returns 0 if
+  // no events have been recorded.
+  intptr_t MarkingSpeedInBytesPerMillisecond() const;
+
  private:
   // Print one detailed trace line in name=value format.
   // TODO(ernstm): Move to Heap.
@@ -267,10 +289,14 @@ class GCTracer BASE_EMBEDDED {
   EventBuffer mark_compactor_events_;
 
   // Cumulative number of incremental marking steps since creation of tracer.
-  int incremental_marking_steps_;
+  int cumulative_incremental_marking_steps_;
+
+  // Cumulative size of incremental marking steps (in bytes) since creation of
+  // tracer.
+  intptr_t cumulative_incremental_marking_bytes_;
 
   // Cumulative duration of incremental marking steps since creation of tracer.
-  double incremental_marking_duration_;
+  double cumulative_incremental_marking_duration_;
 
   // Longest incremental marking step since start of marking.
   double longest_incremental_marking_step_;

src/incremental-marking.cc

@@ -955,9 +955,9 @@ void IncrementalMarking::Step(intptr_t allocated_bytes,
     }
 
     double end = base::OS::TimeCurrentMillis();
-    double delta = (end - start);
-    heap_->tracer()->AddIncrementalMarkingStep(delta);
-    heap_->AddMarkingTime(delta);
+    double duration = (end - start);
+    heap_->tracer()->AddIncrementalMarkingStep(duration, allocated_bytes);
+    heap_->AddMarkingTime(duration);
   }
 }