[heap] Add trace events for time-to-collection

Measure time from requesting GC on background thread until the main
thread starts the collection. Also add trace event for the GC on the
background thread.

Bug: v8:10315
Change-Id: I765ce0df8a1c31e4f64661ea8dc0b6a4685a3132
Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/2489681Reviewed-by: Ulan Degenbaev <ulan@chromium.org>
Commit-Queue: Dominik Inführ <dinfuehr@chromium.org>
Cr-Commit-Position: refs/heads/master@{#70707}

src/heap/collection-barrier.cc

@@ -4,7 +4,10 @@
 
 #include "src/heap/collection-barrier.h"
 
+#include "src/base/platform/time.h"
+#include "src/heap/gc-tracer.h"
 #include "src/heap/heap-inl.h"
+#include "src/heap/heap.h"
 
 namespace v8 {
 namespace internal {
@@ -17,7 +20,7 @@ void CollectionBarrier::ResumeThreadsAwaitingCollection() {
 
 void CollectionBarrier::ShutdownRequested() {
   base::MutexGuard guard(&mutex_);
-  time_to_collection_scope_.reset();
+  if (timer_.IsStarted()) timer_.Stop();
   state_.store(RequestState::kShutdown);
   cond_.NotifyAll();
 }
@@ -43,12 +46,7 @@ void CollectionBarrier::AwaitCollectionBackground() {
   {
     base::MutexGuard guard(&mutex_);
     first = FirstCollectionRequest();
-    if (first) {
-      // Initialize scope while holding the lock - prevents GC from starting
-      // before setting up this counter
-      time_to_collection_scope_.emplace(
-          heap_->isolate()->counters()->time_to_collection());
-    }
+    if (first) timer_.Start();
   }
 
   if (first) {
@@ -64,10 +62,18 @@ void CollectionBarrier::StopTimeToCollectionTimer() {
   base::MutexGuard guard(&mutex_);
   RequestState old_state = state_.exchange(RequestState::kCollectionStarted,
                                            std::memory_order_relaxed);
-  USE(old_state);
-  DCHECK(old_state == RequestState::kDefault ||
-         old_state == RequestState::kCollectionRequested);
-  time_to_collection_scope_.reset();
+  if (old_state == RequestState::kCollectionRequested) {
+    DCHECK(timer_.IsStarted());
+    base::TimeDelta delta = timer_.Elapsed();
+    TRACE_EVENT_INSTANT1(TRACE_DISABLED_BY_DEFAULT("v8.gc"),
+                         "V8.TimeToCollection", TRACE_EVENT_SCOPE_THREAD,
+                         "duration", delta.InMillisecondsF());
+    heap_->isolate()->counters()->time_to_collection()->AddTimedSample(delta);
+    timer_.Stop();
+  } else {
+    DCHECK_EQ(old_state, RequestState::kDefault);
+    DCHECK(!timer_.IsStarted());
+  }
 }
 
 void CollectionBarrier::ActivateStackGuardAndPostTask() {
@@ -81,6 +87,8 @@ void CollectionBarrier::ActivateStackGuardAndPostTask() {
 }
 
 void CollectionBarrier::BlockUntilCollected() {
+  TRACE_BACKGROUND_GC(heap_->tracer(),
+                      GCTracer::BackgroundScope::BACKGROUND_COLLECTION);
   base::MutexGuard guard(&mutex_);
 
   while (CollectionRequested()) {

src/heap/collection-barrier.h

@@ -8,6 +8,7 @@
 #include <atomic>
 
 #include "src/base/optional.h"
+#include "src/base/platform/elapsed-timer.h"
 #include "src/base/platform/mutex.h"
 #include "src/logging/counters.h"
 
@@ -21,7 +22,7 @@ class CollectionBarrier {
   Heap* heap_;
   base::Mutex mutex_;
   base::ConditionVariable cond_;
-  base::Optional<TimedHistogramScope> time_to_collection_scope_;
+  base::ElapsedTimer timer_;
 
   enum class RequestState {
     // Default state, no collection requested and tear down wasn't initated

src/init/heap-symbols.h

@@ -511,6 +511,7 @@
 #define TRACER_BACKGROUND_SCOPES(F)               \
   F(BACKGROUND_ARRAY_BUFFER_FREE)                 \
   F(BACKGROUND_ARRAY_BUFFER_SWEEP)                \
+  F(BACKGROUND_COLLECTION)                        \
   F(BACKGROUND_STORE_BUFFER)                      \
   F(BACKGROUND_UNMAPPER)                          \
   F(MC_BACKGROUND_EVACUATE_COPY)                  \

src/logging/counters-definitions.h

@@ -140,8 +140,8 @@ namespace internal {
   HT(gc_scavenger_foreground, V8.GCScavengerForeground, 10000, MILLISECOND)    \
   HT(measure_memory_delay_ms, V8.MeasureMemoryDelayMilliseconds, 100000,       \
      MILLISECOND)                                                              \
-  HT(stop_the_world, V8.StopTheWorld, 10000, MILLISECOND)                      \
-  HT(time_to_collection, V8.TimeToCollection, 10000, MILLISECOND)              \
+  HT(stop_the_world, V8.StopTheWorld, 10000, MICROSECOND)                      \
+  HT(time_to_collection, V8.TimeToCollection, 10000, MICROSECOND)              \
   /* TurboFan timers. */                                                       \
   HT(turbofan_optimize_prepare, V8.TurboFanOptimizePrepare, 1000000,           \
      MICROSECOND)                                                              \

src/logging/counters.cc

@@ -7,6 +7,7 @@
 #include <iomanip>
 
 #include "src/base/platform/platform.h"
+#include "src/base/platform/time.h"
 #include "src/builtins/builtins-definitions.h"
 #include "src/execution/isolate.h"
 #include "src/logging/counters-inl.h"
@@ -79,6 +80,15 @@ void* Histogram::CreateHistogram() const {
   return counters_->CreateHistogram(name_, min_, max_, num_buckets_);
 }
 
+void TimedHistogram::AddTimedSample(base::TimeDelta sample) {
+  if (Enabled()) {
+    int64_t sample_int = resolution_ == HistogramTimerResolution::MICROSECOND
+                             ? sample.InMicroseconds()
+                             : sample.InMilliseconds();
+    AddSample(static_cast<int>(sample_int));
+  }
+}
+
 void TimedHistogram::Start(base::ElapsedTimer* timer, Isolate* isolate) {
   if (Enabled()) timer->Start();
   if (isolate) Logger::CallEventLogger(isolate, name(), Logger::START, true);
@@ -86,11 +96,9 @@ void TimedHistogram::Start(base::ElapsedTimer* timer, Isolate* isolate) {
 
 void TimedHistogram::Stop(base::ElapsedTimer* timer, Isolate* isolate) {
   if (Enabled()) {
-    int64_t sample = resolution_ == HistogramTimerResolution::MICROSECOND
-                         ? timer->Elapsed().InMicroseconds()
-                         : timer->Elapsed().InMilliseconds();
+    base::TimeDelta delta = timer->Elapsed();
     timer->Stop();
-    AddSample(static_cast<int>(sample));
+    AddTimedSample(delta);
   }
   if (isolate != nullptr) {
     Logger::CallEventLogger(isolate, name(), Logger::END, true);

src/logging/counters.h

@@ -276,6 +276,9 @@ class TimedHistogram : public Histogram {
   // that never got to run in a given scenario. Log if isolate non-null.
   void RecordAbandon(base::ElapsedTimer* timer, Isolate* isolate);
 
+  // Add a single sample to this histogram.
+  void AddTimedSample(base::TimeDelta sample);
+
  protected:
   friend class Counters;
   HistogramTimerResolution resolution_;