[heap] Track average mutator utilization in GC tracer.

The mutator utilizaton is computed for each mark-compact GC cycle as
mutator_time / total_time, where
- total_time is the time from the end of the previous GC to the end of
  the current GC
- mutator_time = total_time - incremental_steps_duration - gc_time.

Bug: chromium:824214
Change-Id: Ie1814f22f0816a3c9c579107f4950f6fc8c8a72d
Reviewed-on: https://chromium-review.googlesource.com/978215
Commit-Queue: Ulan Degenbaev <ulan@chromium.org>
Reviewed-by: Hannes Payer <hpayer@chromium.org>
Cr-Commit-Position: refs/heads/master@{#52221}

src/heap/gc-tracer.cc

@@ -152,7 +152,11 @@ GCTracer::GCTracer(Heap* heap)
       new_space_allocation_in_bytes_since_gc_(0),
       old_generation_allocation_in_bytes_since_gc_(0),
       combined_mark_compact_speed_cache_(0.0),
-      start_counter_(0) {
+      start_counter_(0),
+      average_mutator_duration_(0),
+      average_mark_compact_duration_(0),
+      current_mark_compact_mutator_utilization_(1.0),
+      previous_mark_compact_end_time_(0) {
   // All accesses to incremental_marking_scope assume that incremental marking
   // scopes come first.
   STATIC_ASSERT(0 == Scope::FIRST_INCREMENTAL_SCOPE);
@@ -188,6 +192,10 @@ void GCTracer::ResetForTesting() {
   recorded_context_disposal_times_.Reset();
   recorded_survival_ratios_.Reset();
   start_counter_ = 0;
+  average_mutator_duration_ = 0;
+  average_mark_compact_duration_ = 0;
+  current_mark_compact_mutator_utilization_ = 1.0;
+  previous_mark_compact_end_time_ = 0;
   base::LockGuard<base::Mutex> guard(&background_counter_mutex_);
   for (int i = 0; i < BackgroundScope::NUMBER_OF_SCOPES; i++) {
     background_counter_[i].total_duration_ms = 0;
@@ -322,6 +330,9 @@ void GCTracer::Stop(GarbageCollector collector) {
         current_.incremental_marking_scopes[i] = incremental_marking_scopes_[i];
         current_.scopes[i] = incremental_marking_scopes_[i].duration;
       }
+
+      RecordMutatorUtilization(
+          current_.end_time, duration + current_.incremental_marking_duration);
       RecordIncrementalMarkingSpeed(current_.incremental_marking_bytes,
                                     current_.incremental_marking_duration);
       recorded_incremental_mark_compacts_.Push(
@@ -333,6 +344,8 @@ void GCTracer::Stop(GarbageCollector collector) {
     case Event::MARK_COMPACTOR:
       DCHECK_EQ(0u, current_.incremental_marking_bytes);
       DCHECK_EQ(0, current_.incremental_marking_duration);
+      RecordMutatorUtilization(
+          current_.end_time, duration + current_.incremental_marking_duration);
       recorded_mark_compacts_.Push(
           MakeBytesAndDuration(current_.start_object_size, duration));
       ResetIncrementalMarkingCounters();
@@ -469,7 +482,7 @@ void GCTracer::Print() const {
       "[%d:%p] "
       "%8.0f ms: "
       "%s %.1f (%.1f) -> %.1f (%.1f) MB, "
-      "%.1f / %.1f ms %s %s %s\n",
+      "%.1f / %.1f ms %s (average mu = %.3f, current mu = %.3f) %s %s\n",
       base::OS::GetCurrentProcessId(),
       reinterpret_cast<void*>(heap_->isolate()),
       heap_->isolate()->time_millis_since_init(), current_.TypeName(false),
@@ -478,6 +491,8 @@ void GCTracer::Print() const {
       static_cast<double>(current_.end_object_size) / MB,
       static_cast<double>(current_.end_memory_size) / MB, duration,
       TotalExternalTime(), incremental_buffer,
+      AverageMarkCompactMutatorUtilization(),
+      CurrentMarkCompactMutatorUtilization(),
       Heap::GarbageCollectionReasonToString(current_.gc_reason),
       current_.collector_reason != nullptr ? current_.collector_reason : "");
 }
@@ -871,6 +886,43 @@ void GCTracer::RecordIncrementalMarkingSpeed(size_t bytes, double duration) {
   }
 }
 
+void GCTracer::RecordMutatorUtilization(double mark_compact_end_time,
+                                        double mark_compact_duration) {
+  if (previous_mark_compact_end_time_ == 0) {
+    // The first event only contributes to previous_mark_compact_end_time_,
+    // because we cannot compute the mutator duration.
+    previous_mark_compact_end_time_ = mark_compact_end_time;
+  } else {
+    double total_duration =
+        mark_compact_end_time - previous_mark_compact_end_time_;
+    double mutator_duration = total_duration - mark_compact_duration;
+    if (average_mark_compact_duration_ == 0 && average_mutator_duration_ == 0) {
+      // This is the first event with mutator and mark-compact durations.
+      average_mark_compact_duration_ = mark_compact_duration;
+      average_mutator_duration_ = mutator_duration;
+    } else {
+      average_mark_compact_duration_ =
+          (average_mark_compact_duration_ + mark_compact_duration) / 2;
+      average_mutator_duration_ =
+          (average_mutator_duration_ + mutator_duration) / 2;
+    }
+    current_mark_compact_mutator_utilization_ =
+        total_duration ? mutator_duration / total_duration : 0;
+    previous_mark_compact_end_time_ = mark_compact_end_time;
+  }
+}
+
+double GCTracer::AverageMarkCompactMutatorUtilization() const {
+  double average_total_duration =
+      average_mark_compact_duration_ + average_mutator_duration_;
+  if (average_total_duration == 0) return 1.0;
+  return average_mutator_duration_ / average_total_duration;
+}
+
+double GCTracer::CurrentMarkCompactMutatorUtilization() const {
+  return current_mark_compact_mutator_utilization_;
+}
+
 double GCTracer::IncrementalMarkingSpeedInBytesPerMillisecond() const {
   const int kConservativeSpeedInBytesPerMillisecond = 128 * KB;
   if (recorded_incremental_marking_speed_ != 0) {

src/heap/gc-tracer.h

@@ -300,6 +300,11 @@ class V8_EXPORT_PRIVATE GCTracer {
 
   void NotifyIncrementalMarkingStart();
 
+  // Returns average mutator utilization with respect to mark-compact
+  // garbage collections. This ignores scavenger.
+  double AverageMarkCompactMutatorUtilization() const;
+  double CurrentMarkCompactMutatorUtilization() const;
+
   V8_INLINE void AddScopeSample(Scope::ScopeId scope, double duration) {
     DCHECK(scope < Scope::NUMBER_OF_SCOPES);
     if (scope >= Scope::FIRST_INCREMENTAL_SCOPE &&
@@ -328,6 +333,7 @@ class V8_EXPORT_PRIVATE GCTracer {
   FRIEND_TEST(GCTracerTest, IncrementalMarkingDetails);
   FRIEND_TEST(GCTracerTest, IncrementalScope);
   FRIEND_TEST(GCTracerTest, IncrementalMarkingSpeed);
+  FRIEND_TEST(GCTracerTest, MutatorUtilization);
 
   struct BackgroundCounter {
     double total_duration_ms;
@@ -344,6 +350,8 @@ class V8_EXPORT_PRIVATE GCTracer {
   void ResetForTesting();
   void ResetIncrementalMarkingCounters();
   void RecordIncrementalMarkingSpeed(size_t bytes, double duration);
+  void RecordMutatorUtilization(double mark_compactor_end_time,
+                                double mark_compactor_duration);
 
   // Print one detailed trace line in name=value format.
   // TODO(ernstm): Move to Heap.
@@ -415,6 +423,12 @@ class V8_EXPORT_PRIVATE GCTracer {
   // Counts how many tracers were started without stopping.
   int start_counter_;
 
+  // Used for computing average mutator utilization.
+  double average_mutator_duration_;
+  double average_mark_compact_duration_;
+  double current_mark_compact_mutator_utilization_;
+  double previous_mark_compact_end_time_;
+
   base::RingBuffer<BytesAndDuration> recorded_minor_gcs_total_;
   base::RingBuffer<BytesAndDuration> recorded_minor_gcs_survived_;
   base::RingBuffer<BytesAndDuration> recorded_compactions_;

test/unittests/heap/gc-tracer-unittest.cc

@@ -295,6 +295,42 @@ TEST_F(GCTracerTest, IncrementalMarkingSpeed) {
                        tracer->IncrementalMarkingSpeedInBytesPerMillisecond()));
 }
 
+TEST_F(GCTracerTest, MutatorUtilization) {
+  GCTracer* tracer = i_isolate()->heap()->tracer();
+  tracer->ResetForTesting();
+
+  // Mark-compact #1 ended at 200ms and took 100ms.
+  tracer->RecordMutatorUtilization(200, 100);
+  // Avarage mark-compact time = 0ms.
+  // Avarage mutator time = 0ms.
+  EXPECT_DOUBLE_EQ(1.0, tracer->CurrentMarkCompactMutatorUtilization());
+  EXPECT_DOUBLE_EQ(1.0, tracer->AverageMarkCompactMutatorUtilization());
+
+  // Mark-compact #2 ended at 400ms and took 100ms.
+  tracer->RecordMutatorUtilization(400, 100);
+  // The first mark-compactor is ignored.
+  // Avarage mark-compact time = 100ms.
+  // Avarage mutator time = 100ms.
+  EXPECT_DOUBLE_EQ(0.5, tracer->CurrentMarkCompactMutatorUtilization());
+  EXPECT_DOUBLE_EQ(0.5, tracer->AverageMarkCompactMutatorUtilization());
+
+  // Mark-compact #3 ended at 600ms and took 200ms.
+  tracer->RecordMutatorUtilization(600, 200);
+  // Avarage mark-compact time = 100ms * 0.5 + 200ms * 0.5.
+  // Avarage mutator time = 100ms * 0.5 + 0ms * 0.5.
+  EXPECT_DOUBLE_EQ(0.0, tracer->CurrentMarkCompactMutatorUtilization());
+  EXPECT_DOUBLE_EQ(50.0 / 200.0,
+                   tracer->AverageMarkCompactMutatorUtilization());
+
+  // Mark-compact #4 ended at 800ms and took 0ms.
+  tracer->RecordMutatorUtilization(800, 0);
+  // Avarage mark-compact time = 150ms * 0.5 + 0ms * 0.5.
+  // Avarage mutator time = 50ms * 0.5 + 200ms * 0.5.
+  EXPECT_DOUBLE_EQ(1.0, tracer->CurrentMarkCompactMutatorUtilization());
+  EXPECT_DOUBLE_EQ(125.0 / 200.0,
+                   tracer->AverageMarkCompactMutatorUtilization());
+}
+
 TEST_F(GCTracerTest, BackgroundScavengerScope) {
   GCTracer* tracer = i_isolate()->heap()->tracer();
   tracer->ResetForTesting();