From 6956482764c63776a4e8a632dc6297f98960769a Mon Sep 17 00:00:00 2001 From: Camillo Bruni Date: Tue, 14 Dec 2021 11:43:37 +0100 Subject: [PATCH] [counters] Improve v8.execute histogram timer MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - 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/+/3338258 Reviewed-by: Marja Hölttä Auto-Submit: Camillo Bruni Reviewed-by: Jakob Kummerow Commit-Queue: Jakob Kummerow Cr-Commit-Position: refs/heads/main@{#78372} --- src/api/api.cc | 26 +++++----- src/builtins/accessors.cc | 3 ++ src/execution/isolate.h | 14 +++--- src/logging/counters-scopes.h | 93 ++++++++++++++++++++++------------- 4 files changed, 84 insertions(+), 52 deletions(-) diff --git a/src/api/api.cc b/src/api/api.cc index 880e198be3..6e5bf12cfc 100644 --- a/src/api/api.cc +++ b/src/api/api.cc @@ -2088,8 +2088,8 @@ MaybeLocal Script::Run(Local context, ENTER_V8(isolate, context, Script, Run, MaybeLocal(), InternalEscapableScope); i::TimerEventScope 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::cast(Utils::OpenHandle(this)); @@ -2455,8 +2455,8 @@ MaybeLocal Module::Evaluate(Local context) { ENTER_V8(isolate, context, Module, Evaluate, MaybeLocal(), InternalEscapableScope); i::TimerEventScope 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 self = Utils::OpenHandle(this); @@ -5181,8 +5181,8 @@ MaybeLocal Object::CallAsFunction(Local context, ENTER_V8(isolate, context, Object, CallAsFunction, MaybeLocal(), InternalEscapableScope); i::TimerEventScope 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) == sizeof(i::Handle)); @@ -5201,8 +5201,8 @@ MaybeLocal Object::CallAsConstructor(Local context, int argc, ENTER_V8(isolate, context, Object, CallAsConstructor, MaybeLocal(), InternalEscapableScope); i::TimerEventScope 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) == sizeof(i::Handle)); i::Handle* args = reinterpret_cast*>(argv); @@ -5240,8 +5240,8 @@ MaybeLocal Function::NewInstanceWithSideEffectType( ENTER_V8(isolate, context, Function, NewInstance, MaybeLocal(), InternalEscapableScope); i::TimerEventScope 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) == sizeof(i::Handle)); bool should_set_has_no_side_effect = @@ -5291,8 +5291,8 @@ MaybeLocal Function::Call(Local context, ENTER_V8(isolate, context, Function, Call, MaybeLocal(), InternalEscapableScope); i::TimerEventScope 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 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; diff --git a/src/builtins/accessors.cc b/src/builtins/accessors.cc index a639591419..8fd47a9243 100644 --- a/src/builtins/accessors.cc +++ b/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& info) { i::Isolate* isolate = reinterpret_cast(info.GetIsolate()); RCS_SCOPE(isolate, RuntimeCallCounterId::kArrayLengthSetter); + i::LongTaskNestedTimedHistogramScope timer_scope( + isolate->counters()->execute()); HandleScope scope(isolate); DCHECK(Utils::OpenHandle(*name)->SameValue( diff --git a/src/execution/isolate.h b/src/execution/isolate.h index bbb8cce052..639d187702 100644 --- a/src/execution/isolate.h +++ b/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& async_counters() { + const std::shared_ptr& async_counters() const { // Make sure InitializeCounters() has been called. DCHECK_NOT_NULL(async_counters_.get()); return async_counters_; } - const std::shared_ptr& metrics_recorder() { + const std::shared_ptr& 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_); diff --git a/src/logging/counters-scopes.h b/src/logging/counters-scopes.h index a9657b00d0..f977686834 100644 --- a/src/logging/counters-scopes.h +++ b/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(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) { - previous_scope_ = histogram_->Enter(nullptr); - if (isEnabled()) { - previous_scope_->Pause(base::TimeTicks::HighResolutionNow()); - } + if (isEnabled()) Pause(); } + ~PauseNestedTimedHistogramScope() { - histogram_->Leave(previous_scope_); - if (isEnabled()) { - previous_scope_->Resume(base::TimeTicks::HighResolutionNow()); - } + if (isEnabled()) Resume(); } private: bool isEnabled() const { return previous_scope_ && histogram_->Enabled(); } + + V8_NOINLINE void Pause() { + previous_scope_ = histogram_->Enter(nullptr); + // 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()); + } + } + + V8_NOINLINE void Resume() { + histogram_->Leave(previous_scope_); + previous_scope_->Resume(base::TimeTicks::HighResolutionNow()); + } + NestedTimedHistogram* histogram_; NestedTimedHistogramScope* previous_scope_; };