diff --git a/include/v8-metrics.h b/include/v8-metrics.h index 62738442f7..82e521ef06 100644 --- a/include/v8-metrics.h +++ b/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 diff --git a/src/api/api.cc b/src/api/api.cc index 7e9c504f8e..12af2e71e7 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_precise()); + i::NestedTimedHistogramScope execute_timer(isolate->counters()->execute(), + isolate); 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_precise()); + i::NestedTimedHistogramScope execute_timer(isolate->counters()->execute(), + isolate); 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_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) == 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_precise()); + i::NestedTimedHistogramScope execute_timer(isolate->counters()->execute(), + isolate); 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_precise()); + i::NestedTimedHistogramScope execute_timer(isolate->counters()->execute(), + isolate); 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_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"); diff --git a/src/execution/vm-state-inl.h b/src/execution/vm-state-inl.h index 91fcbf30c7..d4de5abf8c 100644 --- a/src/execution/vm-state-inl.h +++ b/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 diff --git a/src/logging/counters-definitions.h b/src/logging/counters-definitions.h index d3cdccd91a..e07b32745e 100644 --- a/src/logging/counters-definitions.h +++ b/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) */ \ diff --git a/src/logging/counters-scopes.h b/src/logging/counters-scopes.h index 4f5c74b5ea..a9657b00d0 100644 --- a/src/logging/counters-scopes.h +++ b/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(histogram_); } NestedTimedHistogramScope* previous_scope_; + Isolate* isolate_; }; // Temporarily pause a NestedTimedHistogram when for instance leaving V8 for diff --git a/src/logging/log.h b/src/logging/log.h index 34f5bfc9ec..d9c3628fb9 100644 --- a/src/logging/log.h +++ b/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 {