[api] Add LongTaskStats::v8_execute_us

The execute_us is now tied to the --slow-histograms flag.
This currently enabled on a small population as a persistent finch study
which should give us enough coverage for now.

Drive-by-fixes:
- Rename counter: execute_precise() to execute()
- Avoid Leave/Enter overhead in NestedTimedHistogramScope if the
  histogram is not enabled
- Only stop timers in debug mode for NestedTimedHistogramScope

Bug: chromium:1275056
Change-Id: Id6a492bdd68edb5194cb191c7083829a9f90283f
Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/3320431
Reviewed-by: Michael Lippautz <mlippautz@chromium.org>
Reviewed-by: Igor Sheludko <ishell@chromium.org>
Commit-Queue: Camillo Bruni <cbruni@chromium.org>
Cr-Commit-Position: refs/heads/main@{#78318}

include/v8-metrics.h

@@ -230,6 +230,8 @@ struct V8_EXPORT LongTaskStats {
   int64_t gc_full_atomic_wall_clock_duration_us = 0;
   int64_t gc_full_incremental_wall_clock_duration_us = 0;
   int64_t gc_young_wall_clock_duration_us = 0;
+  // Only collected with --slow-histograms
+  int64_t v8_execute_us = 0;
 };
 
 }  // namespace metrics

src/api/api.cc

@@ -2088,8 +2088,8 @@ MaybeLocal<Value> Script::Run(Local<Context> context,
   ENTER_V8(isolate, context, Script, Run, MaybeLocal<Value>(),
            InternalEscapableScope);
   i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
-  i::NestedTimedHistogramScope execute_timer(
-      isolate->counters()->execute_precise());
+  i::NestedTimedHistogramScope execute_timer(isolate->counters()->execute(),
+                                             isolate);
   i::AggregatingHistogramTimerScope histogram_timer(
       isolate->counters()->compile_lazy());
   auto fun = i::Handle<i::JSFunction>::cast(Utils::OpenHandle(this));
@@ -2455,8 +2455,8 @@ MaybeLocal<Value> Module::Evaluate(Local<Context> context) {
   ENTER_V8(isolate, context, Module, Evaluate, MaybeLocal<Value>(),
            InternalEscapableScope);
   i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
-  i::NestedTimedHistogramScope execute_timer(
-      isolate->counters()->execute_precise());
+  i::NestedTimedHistogramScope execute_timer(isolate->counters()->execute(),
+                                             isolate);
   i::AggregatingHistogramTimerScope timer(isolate->counters()->compile_lazy());
 
   i::Handle<i::Module> self = Utils::OpenHandle(this);
@@ -5181,8 +5181,8 @@ MaybeLocal<Value> Object::CallAsFunction(Local<Context> context,
   ENTER_V8(isolate, context, Object, CallAsFunction, MaybeLocal<Value>(),
            InternalEscapableScope);
   i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
-  i::NestedTimedHistogramScope execute_timer(
-      isolate->counters()->execute_precise());
+  i::NestedTimedHistogramScope execute_timer(isolate->counters()->execute(),
+                                             isolate);
   auto self = Utils::OpenHandle(this);
   auto recv_obj = Utils::OpenHandle(*recv);
   STATIC_ASSERT(sizeof(v8::Local<v8::Value>) == sizeof(i::Handle<i::Object>));
@@ -5201,8 +5201,8 @@ MaybeLocal<Value> Object::CallAsConstructor(Local<Context> context, int argc,
   ENTER_V8(isolate, context, Object, CallAsConstructor, MaybeLocal<Value>(),
            InternalEscapableScope);
   i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
-  i::NestedTimedHistogramScope execute_timer(
-      isolate->counters()->execute_precise());
+  i::NestedTimedHistogramScope execute_timer(isolate->counters()->execute(),
+                                             isolate);
   auto self = Utils::OpenHandle(this);
   STATIC_ASSERT(sizeof(v8::Local<v8::Value>) == sizeof(i::Handle<i::Object>));
   i::Handle<i::Object>* args = reinterpret_cast<i::Handle<i::Object>*>(argv);
@@ -5240,8 +5240,8 @@ MaybeLocal<Object> Function::NewInstanceWithSideEffectType(
   ENTER_V8(isolate, context, Function, NewInstance, MaybeLocal<Object>(),
            InternalEscapableScope);
   i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
-  i::NestedTimedHistogramScope execute_timer(
-      isolate->counters()->execute_precise());
+  i::NestedTimedHistogramScope execute_timer(isolate->counters()->execute(),
+                                             isolate);
   auto self = Utils::OpenHandle(this);
   STATIC_ASSERT(sizeof(v8::Local<v8::Value>) == sizeof(i::Handle<i::Object>));
   bool should_set_has_no_side_effect =
@@ -5291,8 +5291,8 @@ MaybeLocal<v8::Value> Function::Call(Local<Context> context,
   ENTER_V8(isolate, context, Function, Call, MaybeLocal<Value>(),
            InternalEscapableScope);
   i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
-  i::NestedTimedHistogramScope execute_timer(
-      isolate->counters()->execute_precise());
+  i::NestedTimedHistogramScope execute_timer(isolate->counters()->execute(),
+                                             isolate);
   auto self = Utils::OpenHandle(this);
   Utils::ApiCheck(!self.is_null(), "v8::Function::Call",
                   "Function to be called is a null pointer");

src/execution/vm-state-inl.h

@@ -56,7 +56,7 @@ ExternalCallbackScope::ExternalCallbackScope(Isolate* isolate, Address callback)
       callback_(callback),
       previous_scope_(isolate->external_callback_scope()),
       vm_state_(isolate),
-      pause_timed_histogram_scope_(isolate->counters()->execute_precise()) {
+      pause_timed_histogram_scope_(isolate->counters()->execute()) {
 #ifdef USE_SIMULATOR
   scope_address_ = Simulator::current(isolate)->get_sp();
 #endif

src/logging/counters-definitions.h

@@ -142,7 +142,7 @@ namespace internal {
 
 #define NESTED_TIMED_HISTOGRAM_LIST_SLOW(HT)                               \
   /* Total V8 time (including JS and runtime calls, exluding callbacks) */ \
-  HT(execute_precise, V8.ExecuteMicroSeconds, 1000000, MICROSECOND)
+  HT(execute, V8.ExecuteMicroSeconds, 1000000, MICROSECOND)
 
 #define TIMED_HISTOGRAM_LIST(HT)                                               \
   /* Timer histograms, thread safe: HT(name, caption, max, unit) */            \

src/logging/counters-scopes.h

@@ -17,25 +17,31 @@ class BaseTimedHistogramScope {
   explicit BaseTimedHistogramScope(TimedHistogram* histogram)
       : histogram_(histogram) {}
 
-  void Start() {
-    if (!histogram_->Enabled()) return;
+  void StartInternal() {
     DCHECK(histogram_->ToggleRunningState(true));
     timer_.Start();
   }
 
-  void Stop() {
-    if (!histogram_->Enabled()) return;
+  void StopInternal() {
     DCHECK(histogram_->ToggleRunningState(false));
     histogram_->AddTimedSample(timer_.Elapsed());
     timer_.Stop();
   }
 
-  void LogStart(Isolate* isolate) {
+  V8_INLINE void Start() {
+    if (histogram_->Enabled()) StartInternal();
+  }
+
+  V8_INLINE void Stop() {
+    if (histogram_->Enabled()) StopInternal();
+  }
+
+  V8_INLINE void LogStart(Isolate* isolate) {
     Logger::CallEventLogger(isolate, histogram_->name(),
                             v8::LogEventStatus::kStart, true);
   }
 
-  void LogEnd(Isolate* isolate) {
+  V8_INLINE void LogEnd(Isolate* isolate) {
     Logger::CallEventLogger(isolate, histogram_->name(),
                             v8::LogEventStatus::kEnd, true);
   }
@@ -113,8 +119,9 @@ class V8_NODISCARD LazyTimedHistogramScope : public BaseTimedHistogramScope {
 // Helper class for scoping a NestedHistogramTimer.
 class V8_NODISCARD NestedTimedHistogramScope : public BaseTimedHistogramScope {
  public:
-  explicit NestedTimedHistogramScope(NestedTimedHistogram* histogram)
-      : BaseTimedHistogramScope(histogram) {
+  explicit NestedTimedHistogramScope(NestedTimedHistogram* histogram,
+                                     Isolate* isolate = nullptr)
+      : BaseTimedHistogramScope(histogram), isolate_(isolate) {
     Start();
   }
   ~NestedTimedHistogramScope() { Stop(); }
@@ -123,24 +130,34 @@ class V8_NODISCARD NestedTimedHistogramScope : public BaseTimedHistogramScope {
   friend NestedTimedHistogram;
   friend PauseNestedTimedHistogramScope;
 
-  void Start() {
+  void StartInteral() {
     previous_scope_ = timed_histogram()->Enter(this);
-    if (histogram_->Enabled()) {
-      base::TimeTicks now = base::TimeTicks::HighResolutionNow();
-      if (previous_scope_) previous_scope_->Pause(now);
-      timer_.Start(now);
-    }
+    base::TimeTicks now = base::TimeTicks::HighResolutionNow();
+    if (previous_scope_) previous_scope_->Pause(now);
+    timer_.Start(now);
+  }
+
+  void StopInternal() {
+    timed_histogram()->Leave(previous_scope_);
+    base::TimeTicks now = base::TimeTicks::HighResolutionNow();
+    base::TimeDelta elapsed = timer_.Elapsed(now);
+    histogram_->AddTimedSample(elapsed);
+    if (isolate_) RecordLongTaskTime(elapsed);
+#ifdef DEBUG
+    // StopInternal() is called in the destructor and don't access timer_
+    // after that.
+    timer_.Stop();
+#endif
+    if (previous_scope_) previous_scope_->Resume(now);
+  }
+
+  V8_INLINE void Start() {
+    if (histogram_->Enabled()) StartInteral();
     LogStart(timed_histogram()->counters()->isolate());
   }
 
-  void Stop() {
-    timed_histogram()->Leave(previous_scope_);
-    if (histogram_->Enabled()) {
-      base::TimeTicks now = base::TimeTicks::HighResolutionNow();
-      histogram_->AddTimedSample(timer_.Elapsed(now));
-      timer_.Stop();
-      if (previous_scope_) previous_scope_->Resume(now);
-    }
+  V8_INLINE void Stop() {
+    if (histogram_->Enabled()) StopInternal();
     LogEnd(timed_histogram()->counters()->isolate());
   }
 
@@ -154,11 +171,19 @@ class V8_NODISCARD NestedTimedHistogramScope : public BaseTimedHistogramScope {
     timer_.Resume(now);
   }
 
+  void RecordLongTaskTime(base::TimeDelta elapsed) const {
+    if (histogram_ == isolate_->counters()->execute()) {
+      isolate_->GetCurrentLongTaskStats()->v8_execute_us +=
+          elapsed.InMicroseconds();
+    }
+  }
+
   NestedTimedHistogram* timed_histogram() {
     return static_cast<NestedTimedHistogram*>(histogram_);
   }
 
   NestedTimedHistogramScope* previous_scope_;
+  Isolate* isolate_;
 };
 
 // Temporarily pause a NestedTimedHistogram when for instance leaving V8 for

src/logging/log.h

@@ -277,9 +277,10 @@ class Logger : public CodeEventListener {
 
   static void DefaultEventLoggerSentinel(const char* name, int event) {}
 
-  static void CallEventLogger(Isolate* isolate, const char* name,
-                              v8::LogEventStatus se, bool expose_to_api) {
-    if (!isolate->event_logger()) return;
+  V8_INLINE static void CallEventLoggerInternal(Isolate* isolate,
+                                                const char* name,
+                                                v8::LogEventStatus se,
+                                                bool expose_to_api) {
     if (isolate->event_logger() == DefaultEventLoggerSentinel) {
       LOG(isolate, TimerEvent(se, name));
     } else if (expose_to_api) {
@@ -287,6 +288,13 @@ class Logger : public CodeEventListener {
     }
   }
 
+  V8_INLINE static void CallEventLogger(Isolate* isolate, const char* name,
+                                        v8::LogEventStatus se,
+                                        bool expose_to_api) {
+    if (!isolate->event_logger()) return;
+    CallEventLoggerInternal(isolate, name, se, expose_to_api);
+  }
+
   V8_EXPORT_PRIVATE bool is_logging();
 
   bool is_listening_to_code_events() override {