[counters] Improve v8.execute histogram timer

- Mark uncommon timer-paths as V8_NOINLINE
- Add explicit LongTaskNestedTimedHistogramScope class
- Use explicit LongTaskRecordMode enum
- Mark a few more isolate methods as const
- Add more timer scopes:
  - Accessors::ArrayLengthSetter
  - v8::NewContext

Bug: v8:12498, chromium:1275056
Change-Id: I7896ee341c3c3a1fd5acf8f3f59347ff01dda9c0
Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/3338258Reviewed-by: Marja Hölttä <marja@chromium.org>
Auto-Submit: Camillo Bruni <cbruni@chromium.org>
Reviewed-by: Jakob Kummerow <jkummerow@chromium.org>
Commit-Queue: Jakob Kummerow <jkummerow@chromium.org>
Cr-Commit-Position: refs/heads/main@{#78372}

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(),
-                                             isolate);
+  i::LongTaskNestedTimedHistogramScope execute_timer(
+      isolate->counters()->execute());
   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(),
-                                             isolate);
+  i::LongTaskNestedTimedHistogramScope execute_timer(
+      isolate->counters()->execute());
   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(),
-                                             isolate);
+  i::LongTaskNestedTimedHistogramScope execute_timer(
+      isolate->counters()->execute());
   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(),
-                                             isolate);
+  i::LongTaskNestedTimedHistogramScope execute_timer(
+      isolate->counters()->execute());
   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(),
-                                             isolate);
+  i::LongTaskNestedTimedHistogramScope execute_timer(
+      isolate->counters()->execute());
   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(),
-                                             isolate);
+  i::LongTaskNestedTimedHistogramScope execute_timer(
+      isolate->counters()->execute());
   auto self = Utils::OpenHandle(this);
   Utils::ApiCheck(!self.is_null(), "v8::Function::Call",
                   "Function to be called is a null pointer");
@@ -6422,6 +6422,8 @@ Local<Context> NewContext(
 
   TRACE_EVENT_CALL_STATS_SCOPED(isolate, "v8", "V8.NewContext");
   LOG_API(isolate, Context, New);
+  i::LongTaskNestedTimedHistogramScope execute_timer(
+      isolate->counters()->execute());
   i::HandleScope scope(isolate);
   ExtensionConfiguration no_extensions;
   if (extensions == nullptr) extensions = &no_extensions;

src/builtins/accessors.cc

@@ -12,6 +12,7 @@
 #include "src/execution/isolate-inl.h"
 #include "src/execution/messages.h"
 #include "src/heap/factory.h"
+#include "src/logging/counters-scopes.h"
 #include "src/logging/runtime-call-stats-scope.h"
 #include "src/objects/api-callbacks.h"
 #include "src/objects/contexts.h"
@@ -166,6 +167,8 @@ void Accessors::ArrayLengthSetter(
     const v8::PropertyCallbackInfo<v8::Boolean>& info) {
   i::Isolate* isolate = reinterpret_cast<i::Isolate*>(info.GetIsolate());
   RCS_SCOPE(isolate, RuntimeCallCounterId::kArrayLengthSetter);
+  i::LongTaskNestedTimedHistogramScope timer_scope(
+      isolate->counters()->execute());
   HandleScope scope(isolate);
 
   DCHECK(Utils::OpenHandle(*name)->SameValue(

src/execution/isolate.h

@@ -1070,21 +1070,21 @@ class V8_EXPORT_PRIVATE Isolate final : private HiddenFactory {
   NATIVE_CONTEXT_FIELDS(NATIVE_CONTEXT_FIELD_ACCESSOR)
 #undef NATIVE_CONTEXT_FIELD_ACCESSOR
 
-  Bootstrapper* bootstrapper() { return bootstrapper_; }
+  Bootstrapper* bootstrapper() const { return bootstrapper_; }
   // Use for updating counters on a foreground thread.
-  Counters* counters() { return async_counters().get(); }
+  Counters* counters() const { return async_counters().get(); }
   // Use for updating counters on a background thread.
-  const std::shared_ptr<Counters>& async_counters() {
+  const std::shared_ptr<Counters>& async_counters() const {
     // Make sure InitializeCounters() has been called.
     DCHECK_NOT_NULL(async_counters_.get());
     return async_counters_;
   }
-  const std::shared_ptr<metrics::Recorder>& metrics_recorder() {
+  const std::shared_ptr<metrics::Recorder>& metrics_recorder() const {
     return metrics_recorder_;
   }
-  RuntimeProfiler* runtime_profiler() { return runtime_profiler_; }
-  CompilationCache* compilation_cache() { return compilation_cache_; }
-  Logger* logger() {
+  RuntimeProfiler* runtime_profiler() const { return runtime_profiler_; }
+  CompilationCache* compilation_cache() const { return compilation_cache_; }
+  Logger* logger() const {
     // Call InitializeLoggingAndCounters() if logging is needed before
     // the isolate is fully initialized.
     DCHECK_NOT_NULL(logger_);

src/logging/counters-scopes.h

@@ -119,9 +119,13 @@ class V8_NODISCARD LazyTimedHistogramScope : public BaseTimedHistogramScope {
 // Helper class for scoping a NestedHistogramTimer.
 class V8_NODISCARD NestedTimedHistogramScope : public BaseTimedHistogramScope {
  public:
-  explicit NestedTimedHistogramScope(NestedTimedHistogram* histogram,
-                                     Isolate* isolate = nullptr)
-      : BaseTimedHistogramScope(histogram), isolate_(isolate) {
+  enum class LongTaskRecordMode { kSkip, kRecord };
+
+  explicit NestedTimedHistogramScope(
+      NestedTimedHistogram* histogram,
+      LongTaskRecordMode long_task_record_mode = LongTaskRecordMode::kSkip)
+      : BaseTimedHistogramScope(histogram),
+        long_task_record_mode_(long_task_record_mode) {
     Start();
   }
   ~NestedTimedHistogramScope() { Stop(); }
@@ -130,19 +134,36 @@ class V8_NODISCARD NestedTimedHistogramScope : public BaseTimedHistogramScope {
   friend NestedTimedHistogram;
   friend PauseNestedTimedHistogramScope;
 
-  void StartInteral() {
+  V8_INLINE void Start() {
+    if (histogram_->Enabled()) StartInteral();
+    LogStart(isolate());
+  }
+
+  V8_NOINLINE void StartInteral() {
     previous_scope_ = timed_histogram()->Enter(this);
     base::TimeTicks now = base::TimeTicks::HighResolutionNow();
     if (previous_scope_) previous_scope_->Pause(now);
     timer_.Start(now);
   }
 
-  void StopInternal() {
+  void Pause(base::TimeTicks now) {
+    DCHECK(histogram_->Enabled());
+    timer_.Pause(now);
+  }
+
+  V8_INLINE void Stop() {
+    if (histogram_->Enabled()) StopInternal();
+    LogEnd(isolate());
+  }
+
+  V8_NOINLINE 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);
+    if (long_task_record_mode_ == LongTaskRecordMode::kRecord) {
+      RecordLongTaskTime(elapsed);
+    }
 #ifdef DEBUG
     // StopInternal() is called in the destructor and don't access timer_
     // after that.
@@ -151,39 +172,33 @@ class V8_NODISCARD NestedTimedHistogramScope : public BaseTimedHistogramScope {
     if (previous_scope_) previous_scope_->Resume(now);
   }
 
-  V8_INLINE void Start() {
-    if (histogram_->Enabled()) StartInteral();
-    LogStart(timed_histogram()->counters()->isolate());
-  }
-
-  V8_INLINE void Stop() {
-    if (histogram_->Enabled()) StopInternal();
-    LogEnd(timed_histogram()->counters()->isolate());
-  }
-
-  void Pause(base::TimeTicks now) {
-    DCHECK(histogram_->Enabled());
-    timer_.Pause(now);
-  }
-
   void Resume(base::TimeTicks now) {
     DCHECK(histogram_->Enabled());
     timer_.Resume(now);
   }
 
   void RecordLongTaskTime(base::TimeDelta elapsed) const {
-    if (histogram_ == isolate_->counters()->execute()) {
-      isolate_->GetCurrentLongTaskStats()->v8_execute_us +=
+    if (histogram_ == timed_histogram()->counters()->execute()) {
+      isolate()->GetCurrentLongTaskStats()->v8_execute_us +=
           elapsed.InMicroseconds();
     }
   }
 
-  NestedTimedHistogram* timed_histogram() {
+  Isolate* isolate() const { return timed_histogram()->counters()->isolate(); }
+
+  NestedTimedHistogram* timed_histogram() const {
     return static_cast<NestedTimedHistogram*>(histogram_);
   }
 
   NestedTimedHistogramScope* previous_scope_;
-  Isolate* isolate_;
+  LongTaskRecordMode long_task_record_mode_;
+};
+
+class V8_NODISCARD LongTaskNestedTimedHistogramScope
+    : public NestedTimedHistogramScope {
+ public:
+  explicit LongTaskNestedTimedHistogramScope(NestedTimedHistogram* histogram)
+      : NestedTimedHistogramScope(histogram, LongTaskRecordMode::kRecord) {}
 };
 
 // Temporarily pause a NestedTimedHistogram when for instance leaving V8 for
@@ -192,20 +207,32 @@ class V8_NODISCARD PauseNestedTimedHistogramScope {
  public:
   explicit PauseNestedTimedHistogramScope(NestedTimedHistogram* histogram)
       : histogram_(histogram) {
+    if (isEnabled()) Pause();
+  }
+
+  ~PauseNestedTimedHistogramScope() {
+    if (isEnabled()) Resume();
+  }
+
+ private:
+  bool isEnabled() const { return previous_scope_ && histogram_->Enabled(); }
+
+  V8_NOINLINE void Pause() {
     previous_scope_ = histogram_->Enter(nullptr);
-    if (isEnabled()) {
+    // For performance reasons we don't annotate all internal callbacks with
+    // NestedTimerScopes which might lead to double pausing and minor
+    // inaccuracies.
+    // TODO(v8:12498): Add DCHECK_NOT_NULL(previous_scope_)
+    if (previous_scope_) {
       previous_scope_->Pause(base::TimeTicks::HighResolutionNow());
     }
   }
-  ~PauseNestedTimedHistogramScope() {
+
+  V8_NOINLINE void Resume() {
     histogram_->Leave(previous_scope_);
-    if (isEnabled()) {
     previous_scope_->Resume(base::TimeTicks::HighResolutionNow());
   }
-  }
 
- private:
-  bool isEnabled() const { return previous_scope_ && histogram_->Enabled(); }
   NestedTimedHistogram* histogram_;
   NestedTimedHistogramScope* previous_scope_;
 };