Add Blink GC, and global renderer GC sums

Adds the following UMA metricss:
- BlinkGC.TimeForGCCycle: Time spent in Blink GC for a complete cycle. This
  includes marking, the atomic pause, and sweeping.
- BlinkGC.TimeForNestedInV8: Time spent in Blink GC events that are nested
  in V8 GC events.

Bug: 843903
Change-Id: Ide371e4d599b6c0f19593d9d6c77ed88a86704c5
Reviewed-on: https://chromium-review.googlesource.com/c/1283369
Commit-Queue: Michael Lippautz <mlippautz@chromium.org>
Reviewed-by: Kentaro Hara <haraken@chromium.org>
Reviewed-by: Mark Pearson <mpearson@chromium.org>
Cr-Commit-Position: refs/heads/master@{#601060}

third_party/blink/renderer/bindings/core/v8/v8_gc_controller.cc

@@ -147,12 +147,21 @@ void VisitWeakHandlesForMinorGC(v8::Isolate* isolate) {
   isolate->VisitWeakHandles(&visitor);
 }
 
+bool IsNestedInV8GC(ThreadState* thread_state, v8::GCType type) {
+  return thread_state && (type == v8::kGCTypeMarkSweepCompact ||
+                          type == v8::kGCTypeIncrementalMarking);
+}
+
 }  // namespace
 
 void V8GCController::GcPrologue(v8::Isolate* isolate,
                                 v8::GCType type,
                                 v8::GCCallbackFlags flags) {
   RUNTIME_CALL_TIMER_SCOPE(isolate, RuntimeCallStats::CounterId::kGcPrologue);
+  ThreadHeapStatsCollector::BlinkGCInV8Scope nested_scope(
+      IsNestedInV8GC(ThreadState::Current(), type)
+          ? ThreadState::Current()->Heap().stats_collector()
+          : nullptr);
   ScriptForbiddenScope::Enter();
 
   // Attribute garbage collection to the all frames instead of a specific
@@ -264,6 +273,10 @@ void V8GCController::GcEpilogue(v8::Isolate* isolate,
                                 v8::GCType type,
                                 v8::GCCallbackFlags flags) {
   RUNTIME_CALL_TIMER_SCOPE(isolate, RuntimeCallStats::CounterId::kGcEpilogue);
+  ThreadHeapStatsCollector::BlinkGCInV8Scope nested_scope(
+      IsNestedInV8GC(ThreadState::Current(), type)
+          ? ThreadState::Current()->Heap().stats_collector()
+          : nullptr);
   UpdateCollectedPhantomHandles(isolate);
   switch (type) {
     case v8::kGCTypeScavenge:

third_party/blink/renderer/platform/heap/heap_stats_collector.cc

@@ -79,11 +79,13 @@ void ThreadHeapStatsCollector::NotifySweepingCompleted() {
           ? static_cast<double>(current().marked_bytes) /
                 current_.object_size_in_bytes_before_sweeping
           : 0.0;
+  current_.gc_nested_in_v8_ = gc_nested_in_v8_;
   previous_ = std::move(current_);
   // Reset the current state.
   static_assert(!std::is_polymorphic<Event>::value,
                 "Event should not be polymorphic");
   memset(&current_, 0, sizeof(current_));
+  gc_nested_in_v8_ = TimeDelta();
 }
 
 void ThreadHeapStatsCollector::UpdateReason(BlinkGC::GCReason reason) {

third_party/blink/renderer/platform/heap/heap_stats_collector.h

@@ -112,11 +112,11 @@ class PLATFORM_EXPORT ThreadHeapStatsCollector {
     template <typename... Args>
     inline InternalScope(ThreadHeapStatsCollector* tracer, Id id, Args... args)
         : tracer_(tracer), start_time_(WTF::CurrentTimeTicks()), id_(id) {
-      StartTrace(args...);
+      StartTrace(id, args...);
     }
 
     inline ~InternalScope() {
-      TRACE_EVENT_END0(TraceCategory(), ToString(id_));
+      StopTrace(id_);
       tracer_->IncreaseScopeTime(id_, WTF::CurrentTimeTicks() - start_time_);
     }
 
@@ -132,18 +132,26 @@ class PLATFORM_EXPORT ThreadHeapStatsCollector {
       }
     }
 
-    void StartTrace() { TRACE_EVENT_BEGIN0(TraceCategory(), ToString(id_)); }
+    void StartTrace(Id id) {
+      TRACE_EVENT_BEGIN0(TraceCategory(), ToString(id));
+    }
 
     template <typename Value1>
-    void StartTrace(const char* k1, Value1 v1) {
-      TRACE_EVENT_BEGIN1(TraceCategory(), ToString(id_), k1, v1);
+    void StartTrace(Id id, const char* k1, Value1 v1) {
+      TRACE_EVENT_BEGIN1(TraceCategory(), ToString(id), k1, v1);
     }
 
     template <typename Value1, typename Value2>
-    void StartTrace(const char* k1, Value1 v1, const char* k2, Value2 v2) {
-      TRACE_EVENT_BEGIN2(TraceCategory(), ToString(id_), k1, v1, k2, v2);
+    void StartTrace(Id id,
+                    const char* k1,
+                    Value1 v1,
+                    const char* k2,
+                    Value2 v2) {
+      TRACE_EVENT_BEGIN2(TraceCategory(), ToString(id), k1, v1, k2, v2);
     }
 
+    void StopTrace(Id id) { TRACE_EVENT_END0(TraceCategory(), ToString(id)); }
+
     ThreadHeapStatsCollector* const tracer_;
     const TimeTicks start_time_;
     const Id id_;
@@ -153,6 +161,25 @@ class PLATFORM_EXPORT ThreadHeapStatsCollector {
   using EnabledScope = InternalScope<kEnabled>;
   using DevToolsScope = InternalScope<kDevTools>;
 
+  class PLATFORM_EXPORT BlinkGCInV8Scope {
+    DISALLOW_NEW();
+    DISALLOW_COPY_AND_ASSIGN(BlinkGCInV8Scope);
+
+   public:
+    template <typename... Args>
+    BlinkGCInV8Scope(ThreadHeapStatsCollector* tracer)
+        : tracer_(tracer), start_time_(WTF::CurrentTimeTicks()) {}
+
+    ~BlinkGCInV8Scope() {
+      if (tracer_)
+        tracer_->gc_nested_in_v8_ += WTF::CurrentTimeTicks() - start_time_;
+    }
+
+   private:
+    ThreadHeapStatsCollector* const tracer_;
+    const TimeTicks start_time_;
+  };
+
   // POD to hold interesting data accumulated during a garbage collection cycle.
   // The event is always fully polulated when looking at previous events but
   // is only be partially populated when looking at the current event. See
@@ -173,6 +200,7 @@ class PLATFORM_EXPORT ThreadHeapStatsCollector {
     size_t partition_alloc_bytes_before_sweeping = 0;
     double live_object_rate = 0;
     size_t wrapper_count_before_sweeping = 0;
+    TimeDelta gc_nested_in_v8_;
   };
 
   // Indicates a new garbage collection cycle.
@@ -250,6 +278,10 @@ class PLATFORM_EXPORT ThreadHeapStatsCollector {
 
   bool is_started_ = false;
 
+  // TimeDelta for RawScope. These don't need to be nested within a garbage
+  // collection cycle to make them easier to use.
+  TimeDelta gc_nested_in_v8_;
+
   FRIEND_TEST_ALL_PREFIXES(ThreadHeapStatsCollectorTest, InitialEmpty);
   FRIEND_TEST_ALL_PREFIXES(ThreadHeapStatsCollectorTest, IncreaseScopeTime);
   FRIEND_TEST_ALL_PREFIXES(ThreadHeapStatsCollectorTest, StopResetsCurrent);

third_party/blink/renderer/platform/heap/thread_state.cc

@@ -1142,6 +1142,19 @@ void UpdateTraceCounters(const ThreadHeapStatsCollector& stats_collector) {
 void UpdateHistograms(const ThreadHeapStatsCollector::Event& event) {
   UMA_HISTOGRAM_ENUMERATION("BlinkGC.GCReason", event.reason);
 
+  // Blink GC cycle time.
+  const WTF::TimeDelta cycle_duration =
+      event.scope_data
+          [ThreadHeapStatsCollector::kIncrementalMarkingStartMarking] +
+      event.scope_data[ThreadHeapStatsCollector::kIncrementalMarkingStep] +
+      event.scope_data[ThreadHeapStatsCollector::kAtomicPhase] +
+      event.scope_data[ThreadHeapStatsCollector::kCompleteSweep] +
+      event.scope_data[ThreadHeapStatsCollector::kLazySweepInIdle] +
+      event.scope_data[ThreadHeapStatsCollector::kLazySweepOnAllocation];
+  UMA_HISTOGRAM_TIMES("BlinkGC.TimeForGCCycle", cycle_duration);
+
+  UMA_HISTOGRAM_TIMES("BlinkGC.TimeForNestedInV8", event.gc_nested_in_v8_);
+
   // TODO(mlippautz): Update name of this histogram.
   UMA_HISTOGRAM_TIMES(
       "BlinkGC.CollectGarbage",

third_party/blink/renderer/platform/heap/unified_heap_controller.cc

@@ -7,6 +7,8 @@
 #include "third_party/blink/renderer/platform/bindings/active_script_wrappable_base.h"
 #include "third_party/blink/renderer/platform/bindings/script_wrappable.h"
 #include "third_party/blink/renderer/platform/bindings/wrapper_type_info.h"
+#include "third_party/blink/renderer/platform/heap/heap.h"
+#include "third_party/blink/renderer/platform/heap/heap_stats_collector.h"
 #include "third_party/blink/renderer/platform/heap/marking_visitor.h"
 #include "third_party/blink/renderer/platform/heap/thread_state.h"
 
@@ -28,11 +30,14 @@ UnifiedHeapController::UnifiedHeapController(ThreadState* thread_state)
 
 void UnifiedHeapController::TracePrologue() {
   VLOG(2) << "UnifiedHeapController::TracePrologue";
+  ThreadHeapStatsCollector::BlinkGCInV8Scope nested_scope(
+      thread_state_->Heap().stats_collector());
 
   // Be conservative here as a new garbage collection gets started right away.
   thread_state_->FinishIncrementalMarkingIfRunning(
       BlinkGC::kHeapPointersOnStack, BlinkGC::kIncrementalMarking,
       BlinkGC::kLazySweeping, thread_state_->current_gc_data_.reason);
+
   // Reset any previously scheduled garbage collections.
   thread_state_->SetGCState(ThreadState::kNoGCScheduled);
   // Start incremental marking with unified tracing.
@@ -43,6 +48,11 @@ void UnifiedHeapController::TracePrologue() {
 
 void UnifiedHeapController::EnterFinalPause(EmbedderStackState stack_state) {
   VLOG(2) << "UnifiedHeapController::EnterFinalPause";
+  ThreadHeapStatsCollector::BlinkGCInV8Scope nested_scope(
+      thread_state_->Heap().stats_collector());
+  ThreadHeapStatsCollector::Scope stats_scope(
+      thread_state_->Heap().stats_collector(),
+      ThreadHeapStatsCollector::kAtomicPhase);
 
   // ActiveScriptWrappable may not have persistents keeping them alive but rely
   // on explicit tracing to be kept alive.
@@ -61,11 +71,19 @@ void UnifiedHeapController::EnterFinalPause(EmbedderStackState stack_state) {
 void UnifiedHeapController::TraceEpilogue() {
   VLOG(2) << "UnifiedHeapController::TraceEpilogue";
 
-  thread_state_->AtomicPauseMarkEpilogue(BlinkGC::kIncrementalMarking);
-  thread_state_->LeaveAtomicPause();
-  thread_state_->LeaveGCForbiddenScope();
-  thread_state_->AtomicPauseSweepAndCompact(BlinkGC::kIncrementalMarking,
-                                            BlinkGC::kLazySweeping);
+  {
+    ThreadHeapStatsCollector::BlinkGCInV8Scope nested_scope(
+        thread_state_->Heap().stats_collector());
+    ThreadHeapStatsCollector::Scope stats_scope(
+        thread_state_->Heap().stats_collector(),
+        ThreadHeapStatsCollector::kAtomicPhase);
+    thread_state_->AtomicPauseMarkEpilogue(BlinkGC::kIncrementalMarking);
+    thread_state_->LeaveAtomicPause();
+    thread_state_->LeaveGCForbiddenScope();
+    thread_state_->AtomicPauseSweepAndCompact(BlinkGC::kIncrementalMarking,
+                                              BlinkGC::kLazySweeping);
+  }
+
   if (!thread_state_->IsSweepingInProgress()) {
     // Sweeping was finished during the atomic pause. Update statistics needs to
     // run outside of the top-most stats scope.
@@ -77,7 +95,6 @@ void UnifiedHeapController::RegisterV8References(
     const std::vector<std::pair<void*, void*>>&
         internal_fields_of_potential_wrappers) {
   VLOG(2) << "UnifiedHeapController::RegisterV8References";
-
   DCHECK(thread_state()->IsMarkingInProgress());
 
   const bool was_in_atomic_pause = thread_state()->in_atomic_pause();
@@ -102,7 +119,7 @@ bool UnifiedHeapController::AdvanceTracing(double deadline_in_ms) {
 
   if (!thread_state_->in_atomic_pause()) {
     // V8 calls into embedder tracing from its own marking to ensure
-    // progress.Oilpan will additionally schedule marking steps.
+    // progress. Oilpan will additionally schedule marking steps.
     ThreadState::AtomicPauseScope atomic_pause_scope(thread_state_);
     TimeTicks deadline =
         TimeTicks() + TimeDelta::FromMillisecondsD(deadline_in_ms);

tools/metrics/histograms/histograms.xml

@@ -10230,6 +10230,14 @@ uploading your change for review.
   </summary>
 </histogram>
 
+<histogram name="BlinkGC.TimeForGCCycle" units="ms">
+  <owner>oilpan-reviews@chromium.org</owner>
+  <summary>
+    Sum of all durations of individual phases within one Blink garbage
+    collection. Reported once per garbage collection at the end.
+  </summary>
+</histogram>
+
 <histogram name="BlinkGC.TimeForGlobalWeakProcessing" units="ms">
   <owner>haraken@chromium.org</owner>
   <summary>
@@ -10251,6 +10259,14 @@ uploading your change for review.
   </summary>
 </histogram>
 
+<histogram name="BlinkGC.TimeForNestedInV8" units="ms">
+  <owner>oilpan-reviews@chromium.org</owner>
+  <summary>
+    Duration of the time of Blink garbage collection spent nested in a V8
+    garbage collection. Reported once per garbage collection at the end.
+  </summary>
+</histogram>
+
 <histogram name="BlinkGC.TimeForStoppingThreads" units="ms">
   <obsolete>
     As of 02/2017, the code to stop Blink threads was removed.