[heap] Tracer: Handle incremental marking scopes

Before this patch all tracing scopes in incremental marking would be reset
during a gc tracer start/stop cycle. This patch handles scopes the same way it
does other incremental marking metrics.

Also:
- Align finalization metric with regular marking metric.
- Smaller cleanups

BUG=chromium:639818
R=jochen@chromium.org

Review-Url: https://codereview.chromium.org/2264033002
Cr-Commit-Position: refs/heads/master@{#38822}

src/heap/gc-tracer.h

@@ -9,6 +9,7 @@
 #include "src/base/platform/platform.h"
 #include "src/counters.h"
 #include "src/globals.h"
+#include "testing/gtest/include/gtest/gtest_prod.h"
 
 namespace v8 {
 namespace internal {
@@ -59,7 +60,16 @@ inline BytesAndDuration MakeBytesAndDuration(uint64_t bytes, double duration) {
 
 enum ScavengeSpeedMode { kForAllObjects, kForSurvivedObjects };
 
+#define INCREMENTAL_SCOPES(F)                \
+  F(MC_INCREMENTAL_WRAPPER_PROLOGUE)         \
+  F(MC_INCREMENTAL_WRAPPER_TRACING)          \
+  F(MC_INCREMENTAL_FINALIZE)                 \
+  F(MC_INCREMENTAL_FINALIZE_OBJECT_GROUPING) \
+  F(MC_INCREMENTAL_EXTERNAL_EPILOGUE)        \
+  F(MC_INCREMENTAL_EXTERNAL_PROLOGUE)
+
 #define TRACER_SCOPES(F)                      \
+  INCREMENTAL_SCOPES(F)                       \
   F(EXTERNAL_WEAK_GLOBAL_HANDLES)             \
   F(MC_CLEAR)                                 \
   F(MC_CLEAR_CODE_FLUSH)                      \
@@ -83,9 +93,6 @@ enum ScavengeSpeedMode { kForAllObjects, kForSurvivedObjects };
   F(MC_EXTERNAL_EPILOGUE)                     \
   F(MC_EXTERNAL_PROLOGUE)                     \
   F(MC_FINISH)                                \
-  F(MC_INCREMENTAL_FINALIZE)                       \
-  F(MC_INCREMENTAL_EXTERNAL_EPILOGUE)              \
-  F(MC_INCREMENTAL_EXTERNAL_PROLOGUE)              \
   F(MC_MARK)                                  \
   F(MC_MARK_FINISH_INCREMENTAL)               \
   F(MC_MARK_PREPARE_CODE_FLUSH)               \
@@ -95,6 +102,10 @@ enum ScavengeSpeedMode { kForAllObjects, kForSurvivedObjects };
   F(MC_MARK_WEAK_CLOSURE_WEAK_HANDLES)        \
   F(MC_MARK_WEAK_CLOSURE_WEAK_ROOTS)          \
   F(MC_MARK_WEAK_CLOSURE_HARMONY)             \
+  F(MC_MARK_WRAPPER_EPILOGUE)                 \
+  F(MC_MARK_WRAPPER_PROLOGUE)                 \
+  F(MC_MARK_WRAPPER_TRACING)                  \
+  F(MC_MARK_OBJECT_GROUPING)                  \
   F(MC_SWEEP)                                 \
   F(MC_SWEEP_CODE)                            \
   F(MC_SWEEP_MAP)                             \
@@ -126,7 +137,12 @@ class GCTracer {
 #define DEFINE_SCOPE(scope) scope,
       TRACER_SCOPES(DEFINE_SCOPE)
 #undef DEFINE_SCOPE
-          NUMBER_OF_SCOPES
+          NUMBER_OF_SCOPES,
+
+      FIRST_INCREMENTAL_SCOPE = MC_INCREMENTAL_WRAPPER_PROLOGUE,
+      LAST_INCREMENTAL_SCOPE = MC_INCREMENTAL_EXTERNAL_PROLOGUE,
+      NUMBER_OF_INCREMENTAL_SCOPES =
+          LAST_INCREMENTAL_SCOPE - FIRST_INCREMENTAL_SCOPE + 1
     };
 
     Scope(GCTracer* tracer, ScopeId scope);
@@ -197,7 +213,7 @@ class GCTracer {
 
     // Size of new space objects in constructor.
     intptr_t new_space_object_size;
-    // Size of survived new space objects in desctructor.
+    // Size of survived new space objects in destructor.
     intptr_t survived_new_space_object_size;
 
     // Number of incremental marking steps since creation of tracer.
@@ -239,10 +255,35 @@ class GCTracer {
     // events
     double pure_incremental_marking_duration;
 
-    // Longest incremental marking step since start of marking.
-    // (value at start of event)
+    // Longest incremental marking step since start of marking (start of event).
     double longest_incremental_marking_step;
 
+    // Number of incremental marking finalization steps since creation of
+    // tracer.
+    int cumulative_incremental_marking_finalization_steps;
+
+    // Cumulative pure duration of incremental marking steps since creation of
+    // tracer. (value at start of event)
+    double cumulative_incremental_marking_finalizaton_duration;
+
+    // Longest incremental marking finalization step since start of marking
+    // (start of event).
+    double longest_incremental_marking_finalization_step;
+
+    // Incremental marking finalization steps since
+    // - last event for SCAVENGER events
+    // - last INCREMENTAL_MARK_COMPACTOR event for INCREMENTAL_MARK_COMPACTOR
+    // events
+    int incremental_marking_finalizaton_steps;
+
+    // Duration of incremental marking finalization steps since
+    // - last event for SCAVENGER events
+    // - last INCREMENTAL_MARK_COMPACTOR event for INCREMENTAL_MARK_COMPACTOR
+    // events
+    double incremental_marking_finalization_duration;
+
+    double cumulative_incremental_scopes[Scope::NUMBER_OF_INCREMENTAL_SCOPES];
+
     // Amounts of time spent in different scopes during GC.
     double scopes[Scope::NUMBER_OF_SCOPES];
   };
@@ -365,6 +406,17 @@ class GCTracer {
   // Discard all recorded survival events.
   void ResetSurvivalEvents();
 
+  void AddScopeSample(Scope::ScopeId scope, double duration);
+
+ private:
+  FRIEND_TEST(GCTracer, AverageSpeed);
+  FRIEND_TEST(GCTracerTest, AllocationThroughput);
+  FRIEND_TEST(GCTracerTest, NewSpaceAllocationThroughput);
+  FRIEND_TEST(GCTracerTest, NewSpaceAllocationThroughputWithProvidedTime);
+  FRIEND_TEST(GCTracerTest, OldGenerationAllocationThroughputWithProvidedTime);
+  FRIEND_TEST(GCTracerTest, RegularScope);
+  FRIEND_TEST(GCTracerTest, IncrementalScope);
+
   // Returns the average speed of the events in the buffer.
   // If the buffer is empty, the result is 0.
   // Otherwise, the result is between 1 byte/ms and 1 GB/ms.
@@ -374,7 +426,6 @@ class GCTracer {
 
   void ResetForTesting();
 
- private:
   // Print one detailed trace line in name=value format.
   // TODO(ernstm): Move to Heap.
   void PrintNVP() const;
@@ -455,6 +506,10 @@ class GCTracer {
   // This timer is precise when run with --print-cumulative-gc-stat
   double cumulative_marking_duration_;
 
+  // Cumulative duration of incremental marking scopes since the creation of
+  // the tracer.
+  double cumulative_incremental_scopes_[Scope::NUMBER_OF_INCREMENTAL_SCOPES];
+
   // Total sweeping time on the main thread.
   // This timer is precise when run with --print-cumulative-gc-stat
   // TODO(hpayer): Account for sweeping time on sweeper threads. Add a

src/heap/incremental-marking.cc

@@ -557,6 +557,8 @@ void IncrementalMarking::StartMarking() {
   state_ = MARKING;
 
   if (heap_->UsingEmbedderHeapTracer()) {
+    TRACE_GC(heap()->tracer(),
+             GCTracer::Scope::MC_INCREMENTAL_WRAPPER_PROLOGUE);
     heap_->mark_compact_collector()->embedder_heap_tracer()->TracePrologue();
   }
 
@@ -622,6 +624,9 @@ void IncrementalMarking::MarkRoots() {
 
 
 void IncrementalMarking::MarkObjectGroups() {
+  TRACE_GC(heap_->tracer(),
+           GCTracer::Scope::MC_INCREMENTAL_FINALIZE_OBJECT_GROUPING);
+
   DCHECK(!heap_->UsingEmbedderHeapTracer());
   DCHECK(!finalize_marking_completed_);
   DCHECK(IsMarking());
@@ -1203,6 +1208,8 @@ intptr_t IncrementalMarking::Step(intptr_t allocated_bytes,
       bytes_processed = ProcessMarkingDeque(bytes_to_process);
       if (FLAG_incremental_marking_wrappers &&
           heap_->UsingEmbedderHeapTracer()) {
+        TRACE_GC(heap()->tracer(),
+                 GCTracer::Scope::MC_INCREMENTAL_WRAPPER_TRACING);
         // This currently marks through all registered wrappers and does not
         // respect bytes_to_process.
         // TODO(hpayer): Integrate incremental marking of wrappers into

src/heap/mark-compact.cc

@@ -814,6 +814,7 @@ void MarkCompactCollector::Prepare() {
 
   if (!was_marked_incrementally_) {
     if (heap_->UsingEmbedderHeapTracer()) {
+      TRACE_GC(heap()->tracer(), GCTracer::Scope::MC_MARK_WRAPPER_PROLOGUE);
       heap_->mark_compact_collector()->embedder_heap_tracer()->TracePrologue();
     }
   }
@@ -2081,12 +2082,14 @@ void MarkCompactCollector::ProcessEphemeralMarking(
   bool work_to_do = true;
   while (work_to_do) {
     if (UsingEmbedderHeapTracer()) {
+      TRACE_GC(heap()->tracer(), GCTracer::Scope::MC_MARK_WRAPPER_TRACING);
       RegisterWrappersWithEmbedderHeapTracer();
       embedder_heap_tracer()->AdvanceTracing(
           0, EmbedderHeapTracer::AdvanceTracingActions(
                  EmbedderHeapTracer::ForceCompletionAction::FORCE_COMPLETION));
     }
     if (!only_process_harmony_weak_collections) {
+      TRACE_GC(heap()->tracer(), GCTracer::Scope::MC_MARK_OBJECT_GROUPING);
       isolate()->global_handles()->IterateObjectGroups(
           visitor, &IsUnmarkedHeapObjectWithHeap);
       MarkImplicitRefGroups(&MarkCompactMarkingVisitor::MarkObject);
@@ -2365,6 +2368,7 @@ void MarkCompactCollector::MarkLiveObjects() {
       TRACE_GC(heap()->tracer(), GCTracer::Scope::MC_MARK_WEAK_CLOSURE_HARMONY);
       ProcessEphemeralMarking(&root_visitor, true);
       if (UsingEmbedderHeapTracer()) {
+        TRACE_GC(heap()->tracer(), GCTracer::Scope::MC_MARK_WRAPPER_EPILOGUE);
         embedder_heap_tracer()->TraceEpilogue();
       }
     }

test/cctest/heap/test-heap.cc

@@ -6206,54 +6206,6 @@ TEST(OldSpaceAllocationCounter) {
 }
 
 
-TEST(NewSpaceAllocationThroughput) {
-  CcTest::InitializeVM();
-  v8::HandleScope scope(CcTest::isolate());
-  Isolate* isolate = CcTest::i_isolate();
-  Heap* heap = isolate->heap();
-  GCTracer* tracer = heap->tracer();
-  tracer->ResetForTesting();
-  int time1 = 100;
-  size_t counter1 = 1000;
-  tracer->SampleAllocation(time1, counter1, 0);
-  int time2 = 200;
-  size_t counter2 = 2000;
-  tracer->SampleAllocation(time2, counter2, 0);
-  size_t throughput =
-      tracer->NewSpaceAllocationThroughputInBytesPerMillisecond();
-  CHECK_EQ((counter2 - counter1) / (time2 - time1), throughput);
-  int time3 = 1000;
-  size_t counter3 = 30000;
-  tracer->SampleAllocation(time3, counter3, 0);
-  throughput = tracer->NewSpaceAllocationThroughputInBytesPerMillisecond();
-  CHECK_EQ((counter3 - counter1) / (time3 - time1), throughput);
-}
-
-
-TEST(NewSpaceAllocationThroughput2) {
-  CcTest::InitializeVM();
-  v8::HandleScope scope(CcTest::isolate());
-  Isolate* isolate = CcTest::i_isolate();
-  Heap* heap = isolate->heap();
-  GCTracer* tracer = heap->tracer();
-  tracer->ResetForTesting();
-  int time1 = 100;
-  size_t counter1 = 1000;
-  tracer->SampleAllocation(time1, counter1, 0);
-  int time2 = 200;
-  size_t counter2 = 2000;
-  tracer->SampleAllocation(time2, counter2, 0);
-  size_t throughput =
-      tracer->NewSpaceAllocationThroughputInBytesPerMillisecond(100);
-  CHECK_EQ((counter2 - counter1) / (time2 - time1), throughput);
-  int time3 = 1000;
-  size_t counter3 = 30000;
-  tracer->SampleAllocation(time3, counter3, 0);
-  throughput = tracer->NewSpaceAllocationThroughputInBytesPerMillisecond(100);
-  CHECK_EQ((counter3 - counter1) / (time3 - time1), throughput);
-}
-
-
 static void CheckLeak(const v8::FunctionCallbackInfo<v8::Value>& args) {
   Isolate* isolate = CcTest::i_isolate();
   Object* message =
@@ -6366,55 +6318,6 @@ TEST(RemoveCodeFromSharedFunctionInfoButNotFromClosure) {
       "check(g1, g2);");
 }
 
-TEST(OldGenerationAllocationThroughput) {
-  CcTest::InitializeVM();
-  v8::HandleScope scope(CcTest::isolate());
-  Isolate* isolate = CcTest::i_isolate();
-  Heap* heap = isolate->heap();
-  GCTracer* tracer = heap->tracer();
-  tracer->ResetForTesting();
-  int time1 = 100;
-  size_t counter1 = 1000;
-  tracer->SampleAllocation(time1, 0, counter1);
-  int time2 = 200;
-  size_t counter2 = 2000;
-  tracer->SampleAllocation(time2, 0, counter2);
-  size_t throughput = static_cast<size_t>(
-      tracer->OldGenerationAllocationThroughputInBytesPerMillisecond(100));
-  CHECK_EQ((counter2 - counter1) / (time2 - time1), throughput);
-  int time3 = 1000;
-  size_t counter3 = 30000;
-  tracer->SampleAllocation(time3, 0, counter3);
-  throughput = static_cast<size_t>(
-      tracer->OldGenerationAllocationThroughputInBytesPerMillisecond(100));
-  CHECK_EQ((counter3 - counter1) / (time3 - time1), throughput);
-}
-
-
-TEST(AllocationThroughput) {
-  CcTest::InitializeVM();
-  v8::HandleScope scope(CcTest::isolate());
-  Isolate* isolate = CcTest::i_isolate();
-  Heap* heap = isolate->heap();
-  GCTracer* tracer = heap->tracer();
-  tracer->ResetForTesting();
-  int time1 = 100;
-  size_t counter1 = 1000;
-  tracer->SampleAllocation(time1, counter1, counter1);
-  int time2 = 200;
-  size_t counter2 = 2000;
-  tracer->SampleAllocation(time2, counter2, counter2);
-  size_t throughput = static_cast<size_t>(
-      tracer->AllocationThroughputInBytesPerMillisecond(100));
-  CHECK_EQ(2 * (counter2 - counter1) / (time2 - time1), throughput);
-  int time3 = 1000;
-  size_t counter3 = 30000;
-  tracer->SampleAllocation(time3, counter3, counter3);
-  throughput = tracer->AllocationThroughputInBytesPerMillisecond(100);
-  CHECK_EQ(2 * (counter3 - counter1) / (time3 - time1), throughput);
-}
-
-
 TEST(ContextMeasure) {
   CcTest::InitializeVM();
   v8::HandleScope scope(CcTest::isolate());

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

@@ -5,12 +5,17 @@
 #include <cmath>
 #include <limits>
 
+#include "src/globals.h"
 #include "src/heap/gc-tracer.h"
+#include "src/isolate.h"
+#include "test/unittests/test-utils.h"
 #include "testing/gtest/include/gtest/gtest.h"
 
 namespace v8 {
 namespace internal {
 
+typedef TestWithContext GCTracerTest;
+
 TEST(GCTracer, AverageSpeed) {
   RingBuffer<BytesAndDuration> buffer;
   EXPECT_EQ(100 / 2,
@@ -45,5 +50,141 @@ TEST(GCTracer, AverageSpeed) {
       GCTracer::AverageSpeed(buffer, MakeBytesAndDuration(0, 0), buffer.kSize));
 }
 
+namespace {
+
+void SampleAndAddAllocaton(v8::internal::GCTracer* tracer, double time_ms,
+                           size_t new_space_counter_bytes,
+                           size_t old_generation_counter_bytes) {
+  tracer->SampleAllocation(time_ms, new_space_counter_bytes,
+                           old_generation_counter_bytes);
+  tracer->AddAllocation(time_ms);
+}
+
+}  // namespace
+
+TEST_F(GCTracerTest, AllocationThroughput) {
+  GCTracer* tracer = i_isolate()->heap()->tracer();
+  tracer->ResetForTesting();
+
+  int time1 = 100;
+  size_t counter1 = 1000;
+  // First sample creates baseline but is not part of the recorded samples.
+  tracer->SampleAllocation(time1, counter1, counter1);
+  SampleAndAddAllocaton(tracer, time1, counter1, counter1);
+  int time2 = 200;
+  size_t counter2 = 2000;
+  SampleAndAddAllocaton(tracer, time2, counter2, counter2);
+  // Will only consider the current sample.
+  size_t throughput = static_cast<size_t>(
+      tracer->AllocationThroughputInBytesPerMillisecond(100));
+  EXPECT_EQ(2 * (counter2 - counter1) / (time2 - time1), throughput);
+  int time3 = 1000;
+  size_t counter3 = 30000;
+  SampleAndAddAllocaton(tracer, time3, counter3, counter3);
+  // Considers last 2 samples.
+  throughput = tracer->AllocationThroughputInBytesPerMillisecond(801);
+  EXPECT_EQ(2 * (counter3 - counter1) / (time3 - time1), throughput);
+}
+
+TEST_F(GCTracerTest, NewSpaceAllocationThroughput) {
+  GCTracer* tracer = i_isolate()->heap()->tracer();
+  tracer->ResetForTesting();
+
+  int time1 = 100;
+  size_t counter1 = 1000;
+  SampleAndAddAllocaton(tracer, time1, counter1, 0);
+  int time2 = 200;
+  size_t counter2 = 2000;
+  SampleAndAddAllocaton(tracer, time2, counter2, 0);
+  size_t throughput =
+      tracer->NewSpaceAllocationThroughputInBytesPerMillisecond();
+  EXPECT_EQ((counter2 - counter1) / (time2 - time1), throughput);
+  int time3 = 1000;
+  size_t counter3 = 30000;
+  SampleAndAddAllocaton(tracer, time3, counter3, 0);
+  throughput = tracer->NewSpaceAllocationThroughputInBytesPerMillisecond();
+  EXPECT_EQ((counter3 - counter1) / (time3 - time1), throughput);
+}
+
+TEST_F(GCTracerTest, NewSpaceAllocationThroughputWithProvidedTime) {
+  GCTracer* tracer = i_isolate()->heap()->tracer();
+  tracer->ResetForTesting();
+
+  int time1 = 100;
+  size_t counter1 = 1000;
+  // First sample creates baseline but is not part of the recorded samples.
+  SampleAndAddAllocaton(tracer, time1, counter1, 0);
+  int time2 = 200;
+  size_t counter2 = 2000;
+  SampleAndAddAllocaton(tracer, time2, counter2, 0);
+  // Will only consider the current sample.
+  size_t throughput =
+      tracer->NewSpaceAllocationThroughputInBytesPerMillisecond(100);
+  EXPECT_EQ((counter2 - counter1) / (time2 - time1), throughput);
+  int time3 = 1000;
+  size_t counter3 = 30000;
+  SampleAndAddAllocaton(tracer, time3, counter3, 0);
+  // Considers last 2 samples.
+  throughput = tracer->NewSpaceAllocationThroughputInBytesPerMillisecond(801);
+  EXPECT_EQ((counter3 - counter1) / (time3 - time1), throughput);
+}
+
+TEST_F(GCTracerTest, OldGenerationAllocationThroughputWithProvidedTime) {
+  GCTracer* tracer = i_isolate()->heap()->tracer();
+  tracer->ResetForTesting();
+
+  int time1 = 100;
+  size_t counter1 = 1000;
+  // First sample creates baseline but is not part of the recorded samples.
+  SampleAndAddAllocaton(tracer, time1, 0, counter1);
+  int time2 = 200;
+  size_t counter2 = 2000;
+  SampleAndAddAllocaton(tracer, time2, 0, counter2);
+  // Will only consider the current sample.
+  size_t throughput = static_cast<size_t>(
+      tracer->OldGenerationAllocationThroughputInBytesPerMillisecond(100));
+  EXPECT_EQ((counter2 - counter1) / (time2 - time1), throughput);
+  int time3 = 1000;
+  size_t counter3 = 30000;
+  SampleAndAddAllocaton(tracer, time3, 0, counter3);
+  // Considers last 2 samples.
+  throughput = static_cast<size_t>(
+      tracer->OldGenerationAllocationThroughputInBytesPerMillisecond(801));
+  EXPECT_EQ((counter3 - counter1) / (time3 - time1), throughput);
+}
+
+TEST_F(GCTracerTest, RegularScope) {
+  GCTracer* tracer = i_isolate()->heap()->tracer();
+
+  {
+    // Sample not added because it's not within a started tracer.
+    tracer->AddScopeSample(GCTracer::Scope::MC_MARK, 100);
+  }
+  tracer->Start(MARK_COMPACTOR, "gc unittest", "collector unittest");
+  { tracer->AddScopeSample(GCTracer::Scope::MC_MARK, 100); }
+  tracer->Stop(MARK_COMPACTOR);
+  EXPECT_EQ(
+      static_cast<size_t>(tracer->current_.scopes[GCTracer::Scope::MC_MARK]),
+      100u);
+}
+
+TEST_F(GCTracerTest, IncrementalScope) {
+  GCTracer* tracer = i_isolate()->heap()->tracer();
+
+  {
+    // Sample is added because its ScopeId is listed as incremental sample.
+    tracer->AddScopeSample(GCTracer::Scope::MC_INCREMENTAL_FINALIZE, 100);
+  }
+  tracer->Start(MARK_COMPACTOR, "gc unittest", "collector unittest");
+  // Switch to incremental MC to enable writing back incremental scopes.
+  tracer->current_.type = GCTracer::Event::INCREMENTAL_MARK_COMPACTOR;
+  { tracer->AddScopeSample(GCTracer::Scope::MC_INCREMENTAL_FINALIZE, 100); }
+  tracer->Stop(MARK_COMPACTOR);
+  EXPECT_EQ(
+      static_cast<size_t>(
+          tracer->current_.scopes[GCTracer::Scope::MC_INCREMENTAL_FINALIZE]),
+      200u);
+}
+
 }  // namespace internal
 }  // namespace v8