[heap] Tracer: Handle incremental marking scopes

src/heap/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/heap/gc-tracer.h"
 
 #include "src/counters.h"
 #include "src/heap/heap-inl.h"
 #include "src/isolate.h"
 
@@ skipping 13 matching lines @@
 GCTracer::Scope::Scope(GCTracer* tracer, ScopeId scope)
     : tracer_(tracer), scope_(scope) {
   start_time_ = tracer_->heap_->MonotonicallyIncreasingTimeInMs();
   // TODO(cbruni): remove once we fully moved to a trace-based system.
   if (FLAG_runtime_call_stats) {
     RuntimeCallStats::Enter(tracer_->heap_->isolate(), &timer_,
                             &RuntimeCallStats::GC);
   }
 }
 
-
 GCTracer::Scope::~Scope() {
   DCHECK(scope_ < NUMBER_OF_SCOPES);  // scope_ is unsigned.
-  tracer_->current_.scopes[scope_] +=
-      tracer_->heap_->MonotonicallyIncreasingTimeInMs() - start_time_;
+  if (scope_ >= FIRST_INCREMENTAL_SCOPE && scope_ <= LAST_INCREMENTAL_SCOPE) {
+    tracer_->cumulative_incremental_scopes_[scope_] +=
+        tracer_->heap_->MonotonicallyIncreasingTimeInMs() - start_time_;
+  } else {
+    tracer_->current_.scopes[scope_] +=
+        tracer_->heap_->MonotonicallyIncreasingTimeInMs() - start_time_;
+  }
   // TODO(cbruni): remove once we fully moved to a trace-based system.
   if (FLAG_runtime_call_stats) {
     RuntimeCallStats::Leave(tracer_->heap_->isolate(), &timer_);
   }
 }
 
 const char* GCTracer::Scope::Name(ScopeId id) {
 #define CASE(scope)  \
   case Scope::scope: \
     return "V8.GC_" #scope;
@@ skipping 13 matching lines @@
       collector_reason(collector_reason),
       start_time(0.0),
       end_time(0.0),
       reduce_memory(false),
       start_object_size(0),
       end_object_size(0),
       start_memory_size(0),
       end_memory_size(0),
       start_holes_size(0),
       end_holes_size(0),
+      new_space_object_size(0),
+      survived_new_space_object_size(0),
       cumulative_incremental_marking_steps(0),
       incremental_marking_steps(0),
       cumulative_incremental_marking_bytes(0),
       incremental_marking_bytes(0),
       cumulative_incremental_marking_duration(0.0),
       incremental_marking_duration(0.0),
       cumulative_pure_incremental_marking_duration(0.0),
       pure_incremental_marking_duration(0.0),
-      longest_incremental_marking_step(0.0) {
+      longest_incremental_marking_step(0.0),
+      cumulative_incremental_marking_finalization_steps(0),
+      cumulative_incremental_marking_finalizaton_duration(0),
+      longest_incremental_marking_finalization_step(0),
+      incremental_marking_finalizaton_steps(0),
+      incremental_marking_finalization_duration(0) {
+  for (int i = Scope::FIRST_INCREMENTAL_SCOPE;
+       i <= Scope::LAST_INCREMENTAL_SCOPE; i++) {
+    cumulative_incremental_scopes[i] = 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 98 matching lines @@
 
   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_.cumulative_pure_incremental_marking_duration =
       cumulative_pure_incremental_marking_duration_;
   current_.longest_incremental_marking_step = longest_incremental_marking_step_;
+  current_.cumulative_incremental_marking_finalization_steps =
+      cumulative_incremental_marking_finalization_steps_;
+  current_.cumulative_incremental_marking_finalizaton_duration =
+      cumulative_incremental_marking_finalization_duration_;
+  current_.longest_incremental_marking_finalization_step =
+      longest_incremental_marking_finalization_step_;
 
   for (int i = 0; i < Scope::NUMBER_OF_SCOPES; i++) {
     current_.scopes[i] = 0;
   }
+
+  for (int i = Scope::FIRST_INCREMENTAL_SCOPE;
+       i <= Scope::LAST_INCREMENTAL_SCOPE; i++) {
+    current_.cumulative_incremental_scopes[i] =
+        cumulative_incremental_scopes_[i];
+  }
+
   int committed_memory = static_cast<int>(heap_->CommittedMemory() / KB);
   int used_memory = static_cast<int>(current_.start_object_size / KB);
   heap_->isolate()->counters()->aggregated_memory_heap_committed()->AddSample(
       start_time, committed_memory);
   heap_->isolate()->counters()->aggregated_memory_heap_used()->AddSample(
       start_time, used_memory);
   // TODO(cbruni): remove once we fully moved to a trace-based system.
   if (FLAG_runtime_call_stats) {
     RuntimeCallStats::Enter(heap_->isolate(), &timer_, &RuntimeCallStats::GC);
   }
@@ skipping 23 matching lines @@
   AddAllocation(current_.end_time);
 
   int committed_memory = static_cast<int>(heap_->CommittedMemory() / KB);
   int used_memory = static_cast<int>(current_.end_object_size / KB);
   heap_->isolate()->counters()->aggregated_memory_heap_committed()->AddSample(
       current_.end_time, committed_memory);
   heap_->isolate()->counters()->aggregated_memory_heap_used()->AddSample(
       current_.end_time, used_memory);
 
   double duration = current_.end_time - current_.start_time;
+
+  const Event* baseline = nullptr;
   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;
-    current_.pure_incremental_marking_duration =
-        current_.cumulative_pure_incremental_marking_duration -
-        previous_.cumulative_pure_incremental_marking_duration;
+    baseline = &previous_;
     recorded_scavenges_total_.Push(
         MakeBytesAndDuration(current_.new_space_object_size, duration));
     recorded_scavenges_survived_.Push(MakeBytesAndDuration(
         current_.survived_new_space_object_size, duration));
   } else if (current_.type == Event::INCREMENTAL_MARK_COMPACTOR) {
-    current_.incremental_marking_steps =
-        current_.cumulative_incremental_marking_steps -
-        previous_incremental_mark_compactor_event_
-            .cumulative_incremental_marking_steps;
-    current_.incremental_marking_bytes =
-        current_.cumulative_incremental_marking_bytes -
-        previous_incremental_mark_compactor_event_
-            .cumulative_incremental_marking_bytes;
-    current_.incremental_marking_duration =
-        current_.cumulative_incremental_marking_duration -
-        previous_incremental_mark_compactor_event_
-            .cumulative_incremental_marking_duration;
-    current_.pure_incremental_marking_duration =
-        current_.cumulative_pure_incremental_marking_duration -
-        previous_incremental_mark_compactor_event_
-            .cumulative_pure_incremental_marking_duration;
+    baseline = &previous_incremental_mark_compactor_event_;
     longest_incremental_marking_step_ = 0.0;
+    longest_incremental_marking_finalization_step_ = 0.0;
     recorded_incremental_marking_steps_.Push(
         MakeBytesAndDuration(current_.incremental_marking_bytes,
                              current_.pure_incremental_marking_duration));
     recorded_incremental_mark_compacts_.Push(
         MakeBytesAndDuration(current_.start_object_size, duration));
     combined_mark_compact_speed_cache_ = 0.0;
   } else {
     DCHECK(current_.incremental_marking_bytes == 0);
     DCHECK(current_.incremental_marking_duration == 0);
     DCHECK(current_.pure_incremental_marking_duration == 0);
     longest_incremental_marking_step_ = 0.0;
+    longest_incremental_marking_finalization_step_ = 0.0;
     recorded_mark_compacts_.Push(
         MakeBytesAndDuration(current_.start_object_size, duration));
     combined_mark_compact_speed_cache_ = 0.0;
   }
 
-  // TODO(ernstm): move the code below out of GCTracer.

[Michael Lippautz, 2016/08/22 12:40:06]

The code this TODO referred to is long gone.

+  if (baseline != nullptr) {
+    current_.incremental_marking_steps =
+        current_.cumulative_incremental_marking_steps -
+        baseline->cumulative_incremental_marking_steps;
+    current_.incremental_marking_bytes =
+        current_.cumulative_incremental_marking_bytes -
+        baseline->cumulative_incremental_marking_bytes;
+    current_.incremental_marking_duration =
+        current_.cumulative_incremental_marking_duration -
+        baseline->cumulative_incremental_marking_duration;
+    current_.pure_incremental_marking_duration =
+        current_.cumulative_pure_incremental_marking_duration -
+        baseline->cumulative_pure_incremental_marking_duration;
+    current_.incremental_marking_finalizaton_steps =
+        current_.cumulative_incremental_marking_finalization_steps -
+        baseline->cumulative_incremental_marking_finalization_steps;
+    current_.incremental_marking_finalization_duration =
+        current_.cumulative_incremental_marking_finalizaton_duration -
+        baseline->cumulative_incremental_marking_finalizaton_duration;
+    for (int i = Scope::FIRST_INCREMENTAL_SCOPE;
+         i <= Scope::LAST_INCREMENTAL_SCOPE; i++) {
+      current_.scopes[i] = current_.cumulative_incremental_scopes[i] -
+                           baseline->cumulative_incremental_scopes[i];
+    }
+  }
 
   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_nvp)
+  if (FLAG_trace_gc_nvp) {
     PrintNVP();
-  else
+  } else {
     Print();
+  }
 
   if (FLAG_trace_gc) {
     heap_->PrintShortHeapStatistics();
   }
 
-  longest_incremental_marking_finalization_step_ = 0.0;

[Michael Lippautz, 2016/08/22 12:40:06]

I don't see why we would refer to previous events for incremental marking
metrics but reset the finalization metrics which are part of incremental
marking.

This is now all handled the same way.

-  cumulative_incremental_marking_finalization_steps_ = 0;
-  cumulative_incremental_marking_finalization_duration_ = 0.0;
   // TODO(cbruni): remove once we fully moved to a trace-based system.
   if (FLAG_runtime_call_stats) {
     RuntimeCallStats::Leave(heap_->isolate(), &timer_);
   }
 }
 
 
 void GCTracer::SampleAllocation(double current_ms,
                                 size_t new_space_counter_bytes,
                                 size_t old_generation_counter_bytes) {
@@ skipping 239 matching lines @@
           "evacuate=%.1f "
           "evacuate.candidates=%.1f "
           "evacuate.clean_up=%.1f "
           "evacuate.copy=%.1f "
           "evacuate.update_pointers=%.1f "
           "evacuate.update_pointers.to_evacuated=%.1f "
           "evacuate.update_pointers.to_new=%.1f "
           "evacuate.update_pointers.weak=%.1f "
           "external.mc_prologue=%.1f "
           "external.mc_epilogue=%.1f "
-          "external.mc_incremental_prologue=%.1f "
-          "external.mc_incremental_epilogue=%.1f "
           "external.weak_global_handles=%.1f "
           "finish=%.1f "
           "mark=%.1f "
           "mark.finish_incremental=%.1f "
           "mark.prepare_code_flush=%.1f "
           "mark.roots=%.1f "
           "mark.weak_closure=%.1f "
           "mark.weak_closure.ephemeral=%.1f "
           "mark.weak_closure.weak_handles=%.1f "
           "mark.weak_closure.weak_roots=%.1f "
           "mark.weak_closure.harmony=%.1f "
           "sweep=%.1f "
           "sweep.code=%.1f "
           "sweep.map=%.1f "
           "sweep.old=%.1f "
-          "incremental_finalize=%.1f "
-          "steps_count=%d "
-          "steps_took=%.1f "
-          "longest_step=%.1f "
-          "finalization_steps_count=%d "
-          "finalization_steps_took=%.1f "
-          "finalization_longest_step=%.1f "
+          "incremental=%.1f "
+          "incremental.finalize=%.1f "
+          "incremental.finalize.external.prologue=%.1f "
+          "incremental.finalize.external.epilogue=%.1f "
+          "incremental.finalize.object_grouping=%.1f "
+          "incremental_finalize_longest_step=%.1f "
+          "incremental_finalize_steps_count=%d "
+          "incremental_steps_count=%d "
+          "incremental_longest_step=%.1f "
           "incremental_marking_throughput=%.f "
           "total_size_before=%" V8PRIdPTR
           " "
           "total_size_after=%" V8PRIdPTR
           " "
           "holes_size_before=%" V8PRIdPTR
           " "
           "holes_size_after=%" V8PRIdPTR
           " "
           "allocated=%" V8PRIdPTR
@@ skipping 28 matching lines @@
           current_.scopes[Scope::MC_EVACUATE],
           current_.scopes[Scope::MC_EVACUATE_CANDIDATES],
           current_.scopes[Scope::MC_EVACUATE_CLEAN_UP],
           current_.scopes[Scope::MC_EVACUATE_COPY],
           current_.scopes[Scope::MC_EVACUATE_UPDATE_POINTERS],
           current_.scopes[Scope::MC_EVACUATE_UPDATE_POINTERS_TO_EVACUATED],
           current_.scopes[Scope::MC_EVACUATE_UPDATE_POINTERS_TO_NEW],
           current_.scopes[Scope::MC_EVACUATE_UPDATE_POINTERS_WEAK],
           current_.scopes[Scope::MC_EXTERNAL_PROLOGUE],
           current_.scopes[Scope::MC_EXTERNAL_EPILOGUE],
-          current_.scopes[Scope::MC_INCREMENTAL_EXTERNAL_PROLOGUE],
-          current_.scopes[Scope::MC_INCREMENTAL_EXTERNAL_EPILOGUE],
           current_.scopes[Scope::EXTERNAL_WEAK_GLOBAL_HANDLES],
           current_.scopes[Scope::MC_FINISH], current_.scopes[Scope::MC_MARK],
           current_.scopes[Scope::MC_MARK_FINISH_INCREMENTAL],
           current_.scopes[Scope::MC_MARK_PREPARE_CODE_FLUSH],
           current_.scopes[Scope::MC_MARK_ROOTS],
           current_.scopes[Scope::MC_MARK_WEAK_CLOSURE],
           current_.scopes[Scope::MC_MARK_WEAK_CLOSURE_EPHEMERAL],
           current_.scopes[Scope::MC_MARK_WEAK_CLOSURE_WEAK_HANDLES],
           current_.scopes[Scope::MC_MARK_WEAK_CLOSURE_WEAK_ROOTS],
           current_.scopes[Scope::MC_MARK_WEAK_CLOSURE_HARMONY],
           current_.scopes[Scope::MC_SWEEP],
           current_.scopes[Scope::MC_SWEEP_CODE],
           current_.scopes[Scope::MC_SWEEP_MAP],
           current_.scopes[Scope::MC_SWEEP_OLD],
+          current_.incremental_marking_duration,
           current_.scopes[Scope::MC_INCREMENTAL_FINALIZE],
+          current_.scopes[Scope::MC_INCREMENTAL_EXTERNAL_PROLOGUE],
+          current_.scopes[Scope::MC_INCREMENTAL_EXTERNAL_EPILOGUE],
+          current_.scopes[Scope::MC_INCREMENTAL_FINALIZE_OBJECT_GROUPING],
+          current_.longest_incremental_marking_finalization_step,
+          current_.incremental_marking_finalizaton_steps,
           current_.incremental_marking_steps,
-          current_.incremental_marking_duration,
           current_.longest_incremental_marking_step,
-          cumulative_incremental_marking_finalization_steps_,
-          cumulative_incremental_marking_finalization_duration_,
-          longest_incremental_marking_finalization_step_,
           IncrementalMarkingSpeedInBytesPerMillisecond(),
           current_.start_object_size, current_.end_object_size,
           current_.start_holes_size, current_.end_holes_size,
           allocated_since_last_gc, heap_->promoted_objects_size(),
           heap_->semi_space_copied_object_size(),
           heap_->nodes_died_in_new_space_, heap_->nodes_copied_in_new_space_,
           heap_->nodes_promoted_, heap_->promotion_ratio_,
           AverageSurvivalRatio(), heap_->promotion_rate_,
           heap_->semi_space_copied_rate_,
           NewSpaceAllocationThroughputInBytesPerMillisecond(),
@@ skipping 130 matching lines @@
   return sum / recorded_survival_ratios_.Count();
 }
 
 bool GCTracer::SurvivalEventsRecorded() const {
   return recorded_survival_ratios_.Count() > 0;
 }
 
 void GCTracer::ResetSurvivalEvents() { recorded_survival_ratios_.Reset(); }
 }  // namespace internal
 }  // namespace v8