Track size of incremental marking steps in GCTracer.

src/gc-tracer.cc

 // Copyright 2014 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/gc-tracer.h"
 
 namespace v8 {
 namespace internal {
@@ skipping 14 matching lines @@
       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),
+      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;
   }
 }
 
 
 const char* GCTracer::Event::TypeName(bool short_name) const {
   switch (type) {
     case SCAVENGER:
       if (short_name) {
@@ skipping 13 matching lines @@
       } else {
         return "Start";
       }
   }
   return "Unknown Event Type";
 }
 
 
 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();
   previous_ = previous_mark_compactor_event_ = current_;
 }
 
 
 void GCTracer::Start(GarbageCollector collector, const char* gc_reason,
                      const char* collector_reason) {
   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_.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++) {
     current_.scopes[i] = 0;
   }
 }
 
 
 void GCTracer::Stop() {
   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_);
+    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;
   } else {
     mark_compactor_events_.push_front(current_);
+    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;
   }
 
-  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;
 
   double duration = current_.end_time - current_.start_time;
   double spent_in_mutator = Max(current_.start_time - previous_.end_time, 0.0);
 
   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)
       PrintNVP();
     else
       Print();
 
     heap_->PrintShortHeapStatistics();
   }
 }
 
 
-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);
 }
 
 
 void GCTracer::Print() const {
   PrintPID("%8.0f ms: ", heap_->isolate()->time_millis_since_init());
 
   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>(current_.scopes[Scope::EXTERNAL]);
   if (external_time > 0) PrintF("%d / ", external_time);
 
   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);
     }
   }
 
   if (current_.gc_reason != NULL) {
     PrintF(" [%s]", current_.gc_reason);
   }
 
   if (current_.collector_reason != NULL) {
     PrintF(" [%s]", current_.collector_reason);
   }
@@ skipping 49 matching lines @@
   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 (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("stepscount=%d ", current_.incremental_marking_steps);

[Hannes Payer (out of office), 2014/07/28 13:04:12]

Since you are here, can we make the names here uniform:
steps_count
steps_took

same in the else case

[ernstm, 2014/07/28 14:43:26]

Done.

+    PrintF("stepstook=%.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("stepscount=%d ", current_.incremental_marking_steps);
+    PrintF("stepstook=%.1f ", current_.incremental_marking_duration);
     PrintF("longeststep=%.1f ", current_.longest_incremental_marking_step);

[Hannes Payer (out of office), 2014/07/28 13:04:12]

Let's print the MarkingSpeedInBytesPerMillisecond here in the else case.
PrintF("marking_throughput=%d\n", MarkingSpeedInBytesPerMillisecond());

[ernstm, 2014/07/28 14:43:26]

Done.

   }
 
   PrintF("\n");
 }
 
 
 double GCTracer::MeanDuration(const EventBuffer& events) const {
   if (events.empty()) return 0.0;
 
   double mean = 0.0;
@@ skipping 15 matching lines @@
   while (iter != events.end()) {
     maximum = Max(iter->end_time - iter->start_time, maximum);
     ++iter;
   }
 
   return maximum;
 }
 
 
 double GCTracer::MeanIncrementalMarkingDuration() const {
-  if (mark_compactor_events_.empty()) return 0.0;
+  if (cumulative_incremental_marking_steps_ == 0) return 0.0;
 
-  EventBuffer::const_iterator last_mc = mark_compactor_events_.begin();
-  return last_mc->incremental_marking_duration /
-         last_mc->incremental_marking_steps;
+  // We haven't complete an entire round of incremental marking, yet.

[Hannes Payer (out of office), 2014/07/28 13:04:12]

completed

[ernstm, 2014/07/28 14:43:26]

Done.

+  // Use data from GCTracer instead of data from event buffers.
+  if (mark_compactor_events_.empty()) {
+    return cumulative_incremental_marking_duration_ /
+           cumulative_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 complete an entire round of incremental marking, yet.

[Hannes Payer (out of office), 2014/07/28 13:04:13]

completed

[ernstm, 2014/07/28 14:43:26]

Done.

+  // Use data from GCTracer instead of data from event buffers.
+  if (mark_compactor_events_.empty()) return longest_incremental_marking_step_;
 
-  EventBuffer::const_iterator last_mc = mark_compactor_events_.begin();
-  return last_mc->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;
+}
+
+
+double GCTracer::MarkingSpeedInBytesPerMillisecond() const {
+  if (cumulative_incremental_marking_duration_ == 0.0) return 0.0;
+
+  // We haven't complete 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_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.0;
+
+  return bytes / durations;
 }
 }
 }  // namespace v8::internal