From f688fe086f7f825b36988101385682a307ea6b3b Mon Sep 17 00:00:00 2001 From: Camillo Bruni Date: Mon, 9 Aug 2021 16:30:16 +0200 Subject: [PATCH] Reland "[counters] Fix reentrant timers for V8.Execute" This is a reland of fffcbaea5568bec429fc52fdbc5429402a485ea4 Additional fixes: - Relax IsStarted DCHECKs in ElapsedTimer for paused_elapsed - Add LogEventStatus enum in the API for better testing - Rename Logger::StartEnd enum values to kXXX - Add additional NestedTimedHistogramScope tests Original change's description: > [counters] Fix reentrant timers for V8.Execute > > This CL fixes a long standing issue where reentering TimedHistograms > scopes would cause spurious measurements. Only the non-nested scopes > yielded correct results. > > Due to the changed numbers, the V8.Execute histogram is renamed to > V8.ExecuteMicroSeconds. Note that this histogram is also guarded > behind the --slow-histograms flag due to the additional overhead. > > Unlike before, it does no longer include time for external callbacks > and only measures self time. The following example illustrates the > new behaviour: > > 1. Enter V8: |--+.......+--| self-time: 4 units (reported) > 2. Exit V8 (callback): |-+...+-| self-time: 2 units (ignored) > 3. Re-enter V8: |---| self-time: 3 units (reported) > > This would result in 2 histogram entries with 4 time units for the first > V8 slice and 3 units for the nested part. Note that the callback time > itself is ignored. > > This CL attempts to clean up how TimedHistograms work: > - Histogram: the base class > - TimedHistograms: used for time-related histograms that are not nested > - NestedTimeHistograms: Extends TimedHistograms and is used for nested > histograms > > This CL changes Histograms to not measure time themselves. Measurements > happen in the *HistogramScopes: > - BaseTimedHistogramScope: Base functionality > - TimedHistogramScope: For non-nested measurements > - NestedTimedHistogramScope: For nested measurements > - PauseNestedTimedHistogramScope: Ignore time during a given scope. > This is used to pause timers during callbacks. > > Additional changes: > - ExternalCallbackScope now contains a PauseNestedTimedHistogramScope > and always sets VMState > > Bug: v8:11946 > Change-Id: I45e4b7ff77b5948b605dd50539044cb26222fa21 > Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/3001345 > Reviewed-by: Omer Katz > Reviewed-by: Thibaud Michaud > Reviewed-by: Victor Gomes > Reviewed-by: Leszek Swirski > Commit-Queue: Camillo Bruni > Cr-Commit-Position: refs/heads/master@{#76111} Bug: v8:11946 Change-Id: Ic2eef7456fbc245febcf780b23418f6ab0bebdb7 Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/3080566 Commit-Queue: Camillo Bruni Reviewed-by: Leszek Swirski Reviewed-by: Victor Gomes Reviewed-by: Thibaud Michaud Reviewed-by: Omer Katz Cr-Commit-Position: refs/heads/master@{#76180} --- BUILD.bazel | 1 + BUILD.gn | 1 + include/v8.h | 4 +- src/api/api-arguments-inl.h | 3 - src/api/api.cc | 24 +- src/base/platform/elapsed-timer.h | 93 +++++-- src/builtins/builtins-console.cc | 8 +- src/codegen/compiler.cc | 31 +-- src/execution/vm-state-inl.h | 4 +- src/execution/vm-state.h | 3 + src/heap/heap.cc | 4 +- src/heap/incremental-marking.cc | 6 +- src/heap/safepoint.cc | 1 + src/logging/counters-definitions.h | 54 ++-- src/logging/counters-scopes.h | 191 +++++++++++++++ src/logging/counters.cc | 65 ++--- src/logging/counters.h | 231 ++++-------------- src/logging/log-inl.h | 13 +- src/logging/log.cc | 10 +- src/logging/log.h | 22 +- src/parsing/parser.cc | 2 - src/snapshot/code-serializer.cc | 5 +- src/wasm/function-compiler.cc | 2 +- src/wasm/module-compiler.cc | 2 +- src/wasm/module-instantiate.cc | 2 +- test/cctest/test-api.cc | 79 +++++- test/unittests/base/platform/time-unittest.cc | 109 +++++++++ 27 files changed, 634 insertions(+), 336 deletions(-) create mode 100644 src/logging/counters-scopes.h diff --git a/BUILD.bazel b/BUILD.bazel index 3e85a5be1e..c5b4a94f91 100644 --- a/BUILD.bazel +++ b/BUILD.bazel @@ -1412,6 +1412,7 @@ filegroup( "src/logging/counters-definitions.h", "src/logging/counters.cc", "src/logging/counters.h", + "src/logging/counters-scopes.h", "src/logging/local-logger.cc", "src/logging/local-logger.h", "src/logging/log-inl.h", diff --git a/BUILD.gn b/BUILD.gn index 649c3ef96e..1b5355759d 100644 --- a/BUILD.gn +++ b/BUILD.gn @@ -2835,6 +2835,7 @@ v8_header_set("v8_internal_headers") { "src/libsampler/sampler.h", "src/logging/code-events.h", "src/logging/counters-definitions.h", + "src/logging/counters-scopes.h", "src/logging/counters.h", "src/logging/local-logger.h", "src/logging/log-inl.h", diff --git a/include/v8.h b/include/v8.h index f52b0586a8..ec93111daf 100644 --- a/include/v8.h +++ b/include/v8.h @@ -7266,7 +7266,9 @@ using MessageCallback = void (*)(Local message, Local data); // --- Tracing --- -using LogEventCallback = void (*)(const char* name, int event); +enum LogEventStatus : int { kStart = 0, kEnd = 1, kStamp = 2 }; +using LogEventCallback = void (*)(const char* name, + int /* LogEventStatus */ status); /** * Create new error objects by calling the corresponding error object diff --git a/src/api/api-arguments-inl.h b/src/api/api-arguments-inl.h index f6825e5922..786f849be6 100644 --- a/src/api/api-arguments-inl.h +++ b/src/api/api-arguments-inl.h @@ -76,7 +76,6 @@ inline JSReceiver FunctionCallbackArguments::holder() { CALLBACK_INFO, RECEIVER, Debug::k##ACCESSOR_KIND)) { \ return RETURN_VALUE(); \ } \ - VMState state(ISOLATE); \ ExternalCallbackScope call_scope(ISOLATE, FUNCTION_ADDR(F)); \ PropertyCallbackInfo callback_info(values_); @@ -85,7 +84,6 @@ inline JSReceiver FunctionCallbackArguments::holder() { if (ISOLATE->debug_execution_mode() == DebugInfo::kSideEffects) { \ return RETURN_VALUE(); \ } \ - VMState state(ISOLATE); \ ExternalCallbackScope call_scope(ISOLATE, FUNCTION_ADDR(F)); \ PropertyCallbackInfo callback_info(values_); @@ -149,7 +147,6 @@ Handle FunctionCallbackArguments::Call(CallHandlerInfo handler) { Debug::kNotAccessor)) { return Handle(); } - VMState state(isolate); ExternalCallbackScope call_scope(isolate, FUNCTION_ADDR(f)); FunctionCallbackInfo info(values_, argv_, argc_); f(info); diff --git a/src/api/api.cc b/src/api/api.cc index 2d232829ab..aff797dad1 100644 --- a/src/api/api.cc +++ b/src/api/api.cc @@ -58,7 +58,7 @@ #include "src/init/v8.h" #include "src/json/json-parser.h" #include "src/json/json-stringifier.h" -#include "src/logging/counters.h" +#include "src/logging/counters-scopes.h" #include "src/logging/metrics.h" #include "src/logging/runtime-call-stats-scope.h" #include "src/logging/tracing-flags.h" @@ -1971,10 +1971,11 @@ MaybeLocal Script::Run(Local context) { TRACE_EVENT_CALL_STATS_SCOPED(isolate, "v8", "V8.Execute"); ENTER_V8(isolate, context, Script, Run, MaybeLocal(), InternalEscapableScope); - i::HistogramTimerScope execute_timer(isolate->counters()->execute(), true); + i::TimerEventScope timer_scope(isolate); + i::NestedTimedHistogramScope execute_timer( + isolate->counters()->execute_precise()); i::AggregatingHistogramTimerScope histogram_timer( isolate->counters()->compile_lazy()); - i::TimerEventScope timer_scope(isolate); auto fun = i::Handle::cast(Utils::OpenHandle(this)); // TODO(crbug.com/1193459): remove once ablation study is completed @@ -2298,9 +2299,10 @@ MaybeLocal Module::Evaluate(Local context) { TRACE_EVENT_CALL_STATS_SCOPED(isolate, "v8", "V8.Execute"); ENTER_V8(isolate, context, Module, Evaluate, MaybeLocal(), InternalEscapableScope); - i::HistogramTimerScope execute_timer(isolate->counters()->execute(), true); - i::AggregatingHistogramTimerScope timer(isolate->counters()->compile_lazy()); i::TimerEventScope timer_scope(isolate); + i::NestedTimedHistogramScope execute_timer( + isolate->counters()->execute_precise()); + i::AggregatingHistogramTimerScope timer(isolate->counters()->compile_lazy()); i::Handle self = Utils::OpenHandle(this); Utils::ApiCheck(self->status() >= i::Module::kLinked, "Module::Evaluate", @@ -4994,6 +4996,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()); auto self = Utils::OpenHandle(this); auto recv_obj = Utils::OpenHandle(*recv); STATIC_ASSERT(sizeof(v8::Local) == sizeof(i::Handle)); @@ -5012,6 +5016,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()); auto self = Utils::OpenHandle(this); STATIC_ASSERT(sizeof(v8::Local) == sizeof(i::Handle)); i::Handle* args = reinterpret_cast*>(argv); @@ -5049,6 +5055,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()); auto self = Utils::OpenHandle(this); STATIC_ASSERT(sizeof(v8::Local) == sizeof(i::Handle)); bool should_set_has_no_side_effect = @@ -5098,6 +5106,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()); auto self = Utils::OpenHandle(this); Utils::ApiCheck(!self.is_null(), "v8::Function::Call", "Function to be called is a null pointer"); @@ -8928,7 +8938,7 @@ bool Isolate::IdleNotificationDeadline(double deadline_in_seconds) { void Isolate::LowMemoryNotification() { i::Isolate* isolate = reinterpret_cast(this); { - i::HistogramTimerScope idle_notification_scope( + i::NestedTimedHistogramScope idle_notification_scope( isolate->counters()->gc_low_memory_notification()); TRACE_EVENT0("v8", "V8.GCLowMemoryNotification"); isolate->heap()->CollectAllAvailableGarbage( @@ -10274,7 +10284,6 @@ void InvokeAccessorGetterCallback( Isolate* isolate = reinterpret_cast(info.GetIsolate()); RCS_SCOPE(isolate, RuntimeCallCounterId::kAccessorGetterCallback); Address getter_address = reinterpret_cast
(getter); - VMState state(isolate); ExternalCallbackScope call_scope(isolate, getter_address); getter(property, info); } @@ -10284,7 +10293,6 @@ void InvokeFunctionCallback(const v8::FunctionCallbackInfo& info, Isolate* isolate = reinterpret_cast(info.GetIsolate()); RCS_SCOPE(isolate, RuntimeCallCounterId::kFunctionCallback); Address callback_address = reinterpret_cast
(callback); - VMState state(isolate); ExternalCallbackScope call_scope(isolate, callback_address); callback(info); } diff --git a/src/base/platform/elapsed-timer.h b/src/base/platform/elapsed-timer.h index 3406831cbe..2947c31237 100644 --- a/src/base/platform/elapsed-timer.h +++ b/src/base/platform/elapsed-timer.h @@ -13,16 +13,17 @@ namespace base { class ElapsedTimer final { public: -#ifdef DEBUG - ElapsedTimer() : started_(false) {} -#endif + ElapsedTimer() : start_ticks_() {} // Starts this timer. Once started a timer can be checked with // |Elapsed()| or |HasExpired()|, and may be restarted using |Restart()|. // This method must not be called on an already started timer. - void Start() { + void Start() { Start(Now()); } + + void Start(TimeTicks now) { + DCHECK(!now.IsNull()); DCHECK(!IsStarted()); - start_ticks_ = Now(); + set_start_ticks(now); #ifdef DEBUG started_ = true; #endif @@ -33,7 +34,7 @@ class ElapsedTimer final { // started before. void Stop() { DCHECK(IsStarted()); - start_ticks_ = TimeTicks(); + set_start_ticks(TimeTicks()); #ifdef DEBUG started_ = false; #endif @@ -42,31 +43,65 @@ class ElapsedTimer final { // Returns |true| if this timer was started previously. bool IsStarted() const { - DCHECK(started_ || start_ticks_.IsNull()); - DCHECK(!started_ || !start_ticks_.IsNull()); + DCHECK(!paused_); + DCHECK_NE(started_, start_ticks_.IsNull()); return !start_ticks_.IsNull(); } +#if DEBUG + bool IsPaused() const { return paused_; } +#endif + // Restarts the timer and returns the time elapsed since the previous start. // This method is equivalent to obtaining the elapsed time with |Elapsed()| // and then starting the timer again, but does so in one single operation, // avoiding the need to obtain the clock value twice. It may only be called // on a previously started timer. - TimeDelta Restart() { + TimeDelta Restart() { return Restart(Now()); } + + TimeDelta Restart(TimeTicks now) { + DCHECK(!now.IsNull()); DCHECK(IsStarted()); - TimeTicks ticks = Now(); - TimeDelta elapsed = ticks - start_ticks_; + TimeDelta elapsed = now - start_ticks_; DCHECK_GE(elapsed.InMicroseconds(), 0); - start_ticks_ = ticks; + set_start_ticks(now); DCHECK(IsStarted()); return elapsed; } + void Pause() { Pause(Now()); } + + void Pause(TimeTicks now) { + TimeDelta elapsed = Elapsed(now); + DCHECK(IsStarted()); +#ifdef DEBUG + paused_ = true; +#endif + set_paused_elapsed(elapsed); + } + + void Resume() { Resume(Now()); } + + void Resume(TimeTicks now) { + DCHECK(!now.IsNull()); + DCHECK(started_); + DCHECK(paused_); + TimeDelta elapsed = paused_elapsed(); +#ifdef DEBUG + paused_ = false; +#endif + set_start_ticks(now - elapsed); + DCHECK(IsStarted()); + } + // Returns the time elapsed since the previous start. This method may only // be called on a previously started timer. - TimeDelta Elapsed() const { + TimeDelta Elapsed() const { return Elapsed(Now()); } + + TimeDelta Elapsed(TimeTicks now) const { + DCHECK(!now.IsNull()); DCHECK(IsStarted()); - TimeDelta elapsed = Now() - start_ticks_; + TimeDelta elapsed = now - start_ticks(); DCHECK_GE(elapsed.InMicroseconds(), 0); return elapsed; } @@ -86,9 +121,35 @@ class ElapsedTimer final { return now; } - TimeTicks start_ticks_; + TimeDelta paused_elapsed() { + // Only used started_ since paused_elapsed_ can be 0. + DCHECK(paused_); + DCHECK(started_); + return paused_elapsed_; + } + + void set_paused_elapsed(TimeDelta delta) { + DCHECK(paused_); + DCHECK(started_); + paused_elapsed_ = delta; + } + + TimeTicks start_ticks() const { + DCHECK(!paused_); + return start_ticks_; + } + void set_start_ticks(TimeTicks start_ticks) { + DCHECK(!paused_); + start_ticks_ = start_ticks; + } + + union { + TimeTicks start_ticks_; + TimeDelta paused_elapsed_; + }; #ifdef DEBUG - bool started_; + bool started_ = false; + bool paused_ = false; #endif }; diff --git a/src/builtins/builtins-console.cc b/src/builtins/builtins-console.cc index 9af8af210d..a1359cd422 100644 --- a/src/builtins/builtins-console.cc +++ b/src/builtins/builtins-console.cc @@ -62,7 +62,7 @@ void ConsoleCall( } void LogTimerEvent(Isolate* isolate, BuiltinArguments args, - Logger::StartEnd se) { + v8::LogEventStatus se) { if (!isolate->logger()->is_logging()) return; HandleScope scope(isolate); std::unique_ptr name; @@ -86,21 +86,21 @@ CONSOLE_METHOD_LIST(CONSOLE_BUILTIN_IMPLEMENTATION) #undef CONSOLE_BUILTIN_IMPLEMENTATION BUILTIN(ConsoleTime) { - LogTimerEvent(isolate, args, Logger::START); + LogTimerEvent(isolate, args, v8::LogEventStatus::kStart); ConsoleCall(isolate, args, &debug::ConsoleDelegate::Time); RETURN_FAILURE_IF_SCHEDULED_EXCEPTION(isolate); return ReadOnlyRoots(isolate).undefined_value(); } BUILTIN(ConsoleTimeEnd) { - LogTimerEvent(isolate, args, Logger::END); + LogTimerEvent(isolate, args, v8::LogEventStatus::kEnd); ConsoleCall(isolate, args, &debug::ConsoleDelegate::TimeEnd); RETURN_FAILURE_IF_SCHEDULED_EXCEPTION(isolate); return ReadOnlyRoots(isolate).undefined_value(); } BUILTIN(ConsoleTimeStamp) { - LogTimerEvent(isolate, args, Logger::STAMP); + LogTimerEvent(isolate, args, v8::LogEventStatus::kStamp); ConsoleCall(isolate, args, &debug::ConsoleDelegate::TimeStamp); RETURN_FAILURE_IF_SCHEDULED_EXCEPTION(isolate); return ReadOnlyRoots(isolate).undefined_value(); diff --git a/src/codegen/compiler.cc b/src/codegen/compiler.cc index b2ddcdab4c..6d0f116246 100644 --- a/src/codegen/compiler.cc +++ b/src/codegen/compiler.cc @@ -44,7 +44,7 @@ #include "src/heap/parked-scope.h" #include "src/init/bootstrapper.h" #include "src/interpreter/interpreter.h" -#include "src/logging/counters.h" +#include "src/logging/counters-scopes.h" #include "src/logging/log-inl.h" #include "src/logging/runtime-call-stats-scope.h" #include "src/objects/feedback-cell-inl.h" @@ -1354,10 +1354,10 @@ MaybeHandle CompileToplevel( // Measure how long it takes to do the compilation; only take the // rest of the function into account to avoid overlap with the // parsing statistics. - HistogramTimer* rate = parse_info->flags().is_eval() - ? isolate->counters()->compile_eval() - : isolate->counters()->compile(); - HistogramTimerScope timer(rate); + NestedTimedHistogram* rate = parse_info->flags().is_eval() + ? isolate->counters()->compile_eval() + : isolate->counters()->compile(); + NestedTimedHistogramScope timer(rate); TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("v8.compile"), parse_info->flags().is_eval() ? "V8.CompileEval" : "V8.Compile"); @@ -1757,7 +1757,8 @@ bool Compiler::CollectSourcePositions(Isolate* isolate, RCS_SCOPE(isolate, RuntimeCallCounterId::kCompileCollectSourcePositions); TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("v8.compile"), "V8.CollectSourcePositions"); - HistogramTimerScope timer(isolate->counters()->collect_source_positions()); + NestedTimedHistogramScope timer( + isolate->counters()->collect_source_positions()); // Set up parse info. UnoptimizedCompileFlags flags = @@ -2279,14 +2280,14 @@ MaybeHandle Compiler::GetFunctionFromEval( // (via v8::Isolate::SetAllowCodeGenerationFromStringsCallback) bool CodeGenerationFromStringsAllowed(Isolate* isolate, Handle context, Handle source) { + RCS_SCOPE(isolate, RuntimeCallCounterId::kCodeGenerationFromStringsCallbacks); DCHECK(context->allow_code_gen_from_strings().IsFalse(isolate)); DCHECK(isolate->allow_code_gen_callback()); - - // Callback set. Let it decide if code generation is allowed. - VMState state(isolate); - RCS_SCOPE(isolate, RuntimeCallCounterId::kCodeGenerationFromStringsCallbacks); AllowCodeGenerationFromStringsCallback callback = isolate->allow_code_gen_callback(); + ExternalCallbackScope external_callback(isolate, + reinterpret_cast
(callback)); + // Callback set. Let it decide if code generation is allowed. return callback(v8::Utils::ToLocal(context), v8::Utils::ToLocal(source)); } @@ -2470,8 +2471,7 @@ struct ScriptCompileTimerScope { explicit ScriptCompileTimerScope( Isolate* isolate, ScriptCompiler::NoCacheReason no_cache_reason) : isolate_(isolate), - all_scripts_histogram_scope_(isolate->counters()->compile_script(), - true), + all_scripts_histogram_scope_(isolate->counters()->compile_script()), no_cache_reason_(no_cache_reason), hit_isolate_cache_(false), producing_code_cache_(false), @@ -2510,7 +2510,7 @@ struct ScriptCompileTimerScope { LazyTimedHistogramScope histogram_scope_; // TODO(leszeks): This timer is the sum of the other times, consider removing // it to save space. - HistogramTimerScope all_scripts_histogram_scope_; + NestedTimedHistogramScope all_scripts_histogram_scope_; ScriptCompiler::NoCacheReason no_cache_reason_; bool hit_isolate_cache_; bool producing_code_cache_; @@ -2877,7 +2877,8 @@ MaybeHandle Compiler::GetSharedFunctionInfoForScript( } else if (can_consume_code_cache) { compile_timer.set_consuming_code_cache(); // Then check cached code provided by embedder. - HistogramTimerScope timer(isolate->counters()->compile_deserialize()); + NestedTimedHistogramScope timer( + isolate->counters()->compile_deserialize()); RCS_SCOPE(isolate, RuntimeCallCounterId::kCompileDeserialize); TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("v8.compile"), "V8.CompileDeserialize"); @@ -2965,7 +2966,7 @@ MaybeHandle Compiler::GetWrappedFunction( if (can_consume_code_cache) { compile_timer.set_consuming_code_cache(); // Then check cached code provided by embedder. - HistogramTimerScope timer(isolate->counters()->compile_deserialize()); + NestedTimedHistogramScope timer(isolate->counters()->compile_deserialize()); RCS_SCOPE(isolate, RuntimeCallCounterId::kCompileDeserialize); TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("v8.compile"), "V8.CompileDeserialize"); diff --git a/src/execution/vm-state-inl.h b/src/execution/vm-state-inl.h index 1781917764..91fcbf30c7 100644 --- a/src/execution/vm-state-inl.h +++ b/src/execution/vm-state-inl.h @@ -54,7 +54,9 @@ VMState::~VMState() { ExternalCallbackScope::ExternalCallbackScope(Isolate* isolate, Address callback) : isolate_(isolate), callback_(callback), - previous_scope_(isolate->external_callback_scope()) { + previous_scope_(isolate->external_callback_scope()), + vm_state_(isolate), + pause_timed_histogram_scope_(isolate->counters()->execute_precise()) { #ifdef USE_SIMULATOR scope_address_ = Simulator::current(isolate)->get_sp(); #endif diff --git a/src/execution/vm-state.h b/src/execution/vm-state.h index f342c0b0d0..9621bee421 100644 --- a/src/execution/vm-state.h +++ b/src/execution/vm-state.h @@ -7,6 +7,7 @@ #include "include/v8.h" #include "src/common/globals.h" +#include "src/logging/counters-scopes.h" namespace v8 { namespace internal { @@ -46,6 +47,8 @@ class V8_NODISCARD ExternalCallbackScope { Isolate* isolate_; Address callback_; ExternalCallbackScope* previous_scope_; + VMState vm_state_; + PauseNestedTimedHistogramScope pause_timed_histogram_scope_; #ifdef USE_SIMULATOR Address scope_address_; #endif diff --git a/src/heap/heap.cc b/src/heap/heap.cc index 3ae0f4a3c5..5e014ef60f 100644 --- a/src/heap/heap.cc +++ b/src/heap/heap.cc @@ -3767,7 +3767,7 @@ void Heap::FinalizeIncrementalMarkingIncrementally( DevToolsTraceEventScope devtools_trace_event_scope( this, "MajorGC", "incremental finalization step"); - HistogramTimerScope incremental_marking_scope( + NestedTimedHistogramScope incremental_marking_scope( isolate()->counters()->gc_incremental_marking_finalize()); TRACE_EVENT1("v8", "V8.GCIncrementalMarkingFinalize", "epoch", epoch_full()); TRACE_GC_EPOCH(tracer(), GCTracer::Scope::MC_INCREMENTAL_FINALIZE, @@ -4001,7 +4001,7 @@ bool Heap::IdleNotification(double deadline_in_seconds) { double deadline_in_ms = deadline_in_seconds * static_cast(base::Time::kMillisecondsPerSecond); - HistogramTimerScope idle_notification_scope( + NestedTimedHistogramScope idle_notification_scope( isolate_->counters()->gc_idle_notification()); TRACE_EVENT0("v8", "V8.GCIdleNotification"); double start_ms = MonotonicallyIncreasingTimeInMs(); diff --git a/src/heap/incremental-marking.cc b/src/heap/incremental-marking.cc index f12781b8b5..8c40eac601 100644 --- a/src/heap/incremental-marking.cc +++ b/src/heap/incremental-marking.cc @@ -194,7 +194,7 @@ void IncrementalMarking::Start(GarbageCollectionReason gc_reason) { counters->incremental_marking_reason()->AddSample( static_cast(gc_reason)); - HistogramTimerScope incremental_marking_scope( + NestedTimedHistogramScope incremental_marking_scope( counters->gc_incremental_marking_start()); TRACE_EVENT1("v8", "V8.GCIncrementalMarkingStart", "epoch", heap_->epoch_full()); @@ -784,7 +784,7 @@ StepResult CombineStepResults(StepResult a, StepResult b) { StepResult IncrementalMarking::AdvanceWithDeadline( double deadline_in_ms, CompletionAction completion_action, StepOrigin step_origin) { - HistogramTimerScope incremental_marking_scope( + NestedTimedHistogramScope incremental_marking_scope( heap_->isolate()->counters()->gc_incremental_marking()); TRACE_EVENT1("v8", "V8.GCIncrementalMarking", "epoch", heap_->epoch_full()); TRACE_GC_EPOCH(heap_->tracer(), GCTracer::Scope::MC_INCREMENTAL, @@ -889,7 +889,7 @@ void IncrementalMarking::AdvanceOnAllocation() { state_ != MARKING || heap_->always_allocate()) { return; } - HistogramTimerScope incremental_marking_scope( + NestedTimedHistogramScope incremental_marking_scope( heap_->isolate()->counters()->gc_incremental_marking()); TRACE_EVENT0("v8", "V8.GCIncrementalMarking"); TRACE_GC_EPOCH(heap_->tracer(), GCTracer::Scope::MC_INCREMENTAL, diff --git a/src/heap/safepoint.cc b/src/heap/safepoint.cc index 5bcfb58045..e67c9743f8 100644 --- a/src/heap/safepoint.cc +++ b/src/heap/safepoint.cc @@ -14,6 +14,7 @@ #include "src/heap/heap-inl.h" #include "src/heap/heap.h" #include "src/heap/local-heap.h" +#include "src/logging/counters-scopes.h" namespace v8 { namespace internal { diff --git a/src/logging/counters-definitions.h b/src/logging/counters-definitions.h index 540f18e5c0..d6d42b06b0 100644 --- a/src/logging/counters-definitions.h +++ b/src/logging/counters-definitions.h @@ -102,35 +102,35 @@ namespace internal { /* The maximum of 100M backtracks takes roughly 2 seconds on my machine. */ \ HR(regexp_backtracks, V8.RegExpBacktracks, 1, 100000000, 50) -#define HISTOGRAM_TIMER_LIST(HT) \ - /* Timer histograms, not thread safe: HT(name, caption, max, unit) */ \ - /* Garbage collection timers. */ \ - HT(gc_idle_notification, V8.GCIdleNotification, 10000, MILLISECOND) \ - HT(gc_incremental_marking, V8.GCIncrementalMarking, 10000, MILLISECOND) \ - HT(gc_incremental_marking_start, V8.GCIncrementalMarkingStart, 10000, \ - MILLISECOND) \ - HT(gc_incremental_marking_finalize, V8.GCIncrementalMarkingFinalize, 10000, \ - MILLISECOND) \ - HT(gc_low_memory_notification, V8.GCLowMemoryNotification, 10000, \ - MILLISECOND) \ - /* Compilation times. */ \ - HT(collect_source_positions, V8.CollectSourcePositions, 1000000, \ - MICROSECOND) \ - HT(compile, V8.CompileMicroSeconds, 1000000, MICROSECOND) \ - HT(compile_eval, V8.CompileEvalMicroSeconds, 1000000, MICROSECOND) \ - /* Serialization as part of compilation (code caching) */ \ - HT(compile_serialize, V8.CompileSerializeMicroSeconds, 100000, MICROSECOND) \ - HT(compile_deserialize, V8.CompileDeserializeMicroSeconds, 1000000, \ - MICROSECOND) \ - /* Total compilation time incl. caching/parsing */ \ - HT(compile_script, V8.CompileScriptMicroSeconds, 1000000, MICROSECOND) \ - /* Time for lazily compiling Wasm functions. */ \ - HT(wasm_lazy_compile_time, V8.WasmLazyCompileTimeMicroSeconds, 100000000, \ +#define NESTED_TIMED_HISTOGRAM_LIST(HT) \ + /* Timer histograms, not thread safe: HT(name, caption, max, unit) */ \ + /* Garbage collection timers. */ \ + HT(gc_idle_notification, V8.GCIdleNotification, 10000, MILLISECOND) \ + HT(gc_incremental_marking, V8.GCIncrementalMarking, 10000, MILLISECOND) \ + HT(gc_incremental_marking_start, V8.GCIncrementalMarkingStart, 10000, \ + MILLISECOND) \ + HT(gc_incremental_marking_finalize, V8.GCIncrementalMarkingFinalize, 10000, \ + MILLISECOND) \ + HT(gc_low_memory_notification, V8.GCLowMemoryNotification, 10000, \ + MILLISECOND) \ + /* Compilation times. */ \ + HT(collect_source_positions, V8.CollectSourcePositions, 1000000, \ + MICROSECOND) \ + HT(compile, V8.CompileMicroSeconds, 1000000, MICROSECOND) \ + HT(compile_eval, V8.CompileEvalMicroSeconds, 1000000, MICROSECOND) \ + /* Serialization as part of compilation (code caching) */ \ + HT(compile_serialize, V8.CompileSerializeMicroSeconds, 100000, MICROSECOND) \ + HT(compile_deserialize, V8.CompileDeserializeMicroSeconds, 1000000, \ + MICROSECOND) \ + /* Total compilation time incl. caching/parsing */ \ + HT(compile_script, V8.CompileScriptMicroSeconds, 1000000, MICROSECOND) \ + /* Time for lazily compiling Wasm functions. */ \ + HT(wasm_lazy_compile_time, V8.WasmLazyCompileTimeMicroSeconds, 100000000, \ MICROSECOND) -#define HISTOGRAM_TIMER_LIST_SLOW(HT) \ - /* Total JavaScript execution time (including callbacks and runtime calls */ \ - HT(execute, V8.Execute, 1000000, MICROSECOND) +#define NESTED_TIMED_HISTOGRAM_LIST_SLOW(HT) \ + /* Total V8 time (including JS and runtime calls, exluding callbacks) */ \ + HT(execute_precise, 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 new file mode 100644 index 0000000000..4f5c74b5ea --- /dev/null +++ b/src/logging/counters-scopes.h @@ -0,0 +1,191 @@ +// Copyright 2021 the V8 project authors. All rights reserved. +// Use of this source code is governed by a BSD-style license that can be +// found in the LICENSE file. + +#ifndef V8_LOGGING_COUNTERS_SCOPES_H_ +#define V8_LOGGING_COUNTERS_SCOPES_H_ + +#include "src/execution/isolate.h" +#include "src/logging/counters.h" +#include "src/logging/log.h" + +namespace v8 { +namespace internal { + +class BaseTimedHistogramScope { + protected: + explicit BaseTimedHistogramScope(TimedHistogram* histogram) + : histogram_(histogram) {} + + void Start() { + if (!histogram_->Enabled()) return; + DCHECK(histogram_->ToggleRunningState(true)); + timer_.Start(); + } + + void Stop() { + if (!histogram_->Enabled()) return; + DCHECK(histogram_->ToggleRunningState(false)); + histogram_->AddTimedSample(timer_.Elapsed()); + timer_.Stop(); + } + + void LogStart(Isolate* isolate) { + Logger::CallEventLogger(isolate, histogram_->name(), + v8::LogEventStatus::kStart, true); + } + + void LogEnd(Isolate* isolate) { + Logger::CallEventLogger(isolate, histogram_->name(), + v8::LogEventStatus::kEnd, true); + } + + base::ElapsedTimer timer_; + TimedHistogram* histogram_; +}; + +// Helper class for scoping a TimedHistogram. +class V8_NODISCARD TimedHistogramScope : public BaseTimedHistogramScope { + public: + explicit TimedHistogramScope(TimedHistogram* histogram, + Isolate* isolate = nullptr) + : BaseTimedHistogramScope(histogram), isolate_(isolate) { + Start(); + if (isolate_) LogStart(isolate_); + } + + ~TimedHistogramScope() { + Stop(); + if (isolate_) LogEnd(isolate_); + } + + private: + Isolate* const isolate_; + + DISALLOW_IMPLICIT_CONSTRUCTORS(TimedHistogramScope); +}; + +enum class OptionalTimedHistogramScopeMode { TAKE_TIME, DONT_TAKE_TIME }; + +// Helper class for scoping a TimedHistogram. +// It will not take time for mode = DONT_TAKE_TIME. +class V8_NODISCARD OptionalTimedHistogramScope + : public BaseTimedHistogramScope { + public: + OptionalTimedHistogramScope(TimedHistogram* histogram, Isolate* isolate, + OptionalTimedHistogramScopeMode mode) + : BaseTimedHistogramScope(histogram), isolate_(isolate), mode_(mode) { + if (mode != OptionalTimedHistogramScopeMode::TAKE_TIME) return; + Start(); + LogStart(isolate_); + } + + ~OptionalTimedHistogramScope() { + if (mode_ != OptionalTimedHistogramScopeMode::TAKE_TIME) return; + Stop(); + LogEnd(isolate_); + } + + private: + Isolate* const isolate_; + const OptionalTimedHistogramScopeMode mode_; + DISALLOW_IMPLICIT_CONSTRUCTORS(OptionalTimedHistogramScope); +}; + +// Helper class for scoping a TimedHistogram, where the histogram is selected at +// stop time rather than start time. +class V8_NODISCARD LazyTimedHistogramScope : public BaseTimedHistogramScope { + public: + LazyTimedHistogramScope() : BaseTimedHistogramScope(nullptr) { + timer_.Start(); + } + ~LazyTimedHistogramScope() { + // We should set the histogram before this scope exits. + Stop(); + } + + void set_histogram(TimedHistogram* histogram) { + DCHECK_IMPLIES(histogram->Enabled(), histogram->ToggleRunningState(true)); + histogram_ = histogram; + } +}; + +// Helper class for scoping a NestedHistogramTimer. +class V8_NODISCARD NestedTimedHistogramScope : public BaseTimedHistogramScope { + public: + explicit NestedTimedHistogramScope(NestedTimedHistogram* histogram) + : BaseTimedHistogramScope(histogram) { + Start(); + } + ~NestedTimedHistogramScope() { Stop(); } + + private: + friend NestedTimedHistogram; + friend PauseNestedTimedHistogramScope; + + void Start() { + 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); + } + 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); + } + 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); + } + + NestedTimedHistogram* timed_histogram() { + return static_cast(histogram_); + } + + NestedTimedHistogramScope* previous_scope_; +}; + +// Temporarily pause a NestedTimedHistogram when for instance leaving V8 for +// external callbacks. +class V8_NODISCARD PauseNestedTimedHistogramScope { + public: + explicit PauseNestedTimedHistogramScope(NestedTimedHistogram* histogram) + : histogram_(histogram) { + previous_scope_ = histogram_->Enter(nullptr); + if (isEnabled()) { + previous_scope_->Pause(base::TimeTicks::HighResolutionNow()); + } + } + ~PauseNestedTimedHistogramScope() { + 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_; +}; + +} // namespace internal +} // namespace v8 + +#endif // V8_LOGGING_COUNTERS_SCOPES_H_ diff --git a/src/logging/counters.cc b/src/logging/counters.cc index f17155da0f..a333327e93 100644 --- a/src/logging/counters.cc +++ b/src/logging/counters.cc @@ -77,46 +77,48 @@ void* Histogram::CreateHistogram() const { return counters_->CreateHistogram(name_, min_, max_, num_buckets_); } +void TimedHistogram::Stop(base::ElapsedTimer* timer) { + DCHECK(Enabled()); + AddTimedSample(timer->Elapsed()); + timer->Stop(); +} + void TimedHistogram::AddTimedSample(base::TimeDelta sample) { if (Enabled()) { - int64_t sample_int = resolution_ == HistogramTimerResolution::MICROSECOND + int64_t sample_int = resolution_ == TimedHistogramResolution::MICROSECOND ? sample.InMicroseconds() : sample.InMilliseconds(); AddSample(static_cast(sample_int)); } } -void TimedHistogram::Start(base::ElapsedTimer* timer, Isolate* isolate) { - if (Enabled()) timer->Start(); - if (isolate) Logger::CallEventLogger(isolate, name(), Logger::START, true); -} - -void TimedHistogram::Stop(base::ElapsedTimer* timer, Isolate* isolate) { - if (Enabled()) { - base::TimeDelta delta = timer->Elapsed(); - timer->Stop(); - AddTimedSample(delta); - } - if (isolate != nullptr) { - Logger::CallEventLogger(isolate, name(), Logger::END, true); - } -} - void TimedHistogram::RecordAbandon(base::ElapsedTimer* timer, Isolate* isolate) { if (Enabled()) { DCHECK(timer->IsStarted()); timer->Stop(); - int64_t sample = resolution_ == HistogramTimerResolution::MICROSECOND + int64_t sample = resolution_ == TimedHistogramResolution::MICROSECOND ? base::TimeDelta::Max().InMicroseconds() : base::TimeDelta::Max().InMilliseconds(); AddSample(static_cast(sample)); } if (isolate != nullptr) { - Logger::CallEventLogger(isolate, name(), Logger::END, true); + Logger::CallEventLogger(isolate, name(), v8::LogEventStatus::kEnd, true); } } +#ifdef DEBUG +bool TimedHistogram::ToggleRunningState(bool expect_to_run) const { + static thread_local base::LazyInstance< + std::unordered_map>::type active_timer = + LAZY_INSTANCE_INITIALIZER; + bool is_running = (*active_timer.Pointer())[this]; + DCHECK_NE(is_running, expect_to_run); + (*active_timer.Pointer())[this] = !is_running; + return true; +} +#endif + Counters::Counters(Isolate* isolate) : #define SC(name, caption) name##_(this, "c:" #caption), @@ -149,29 +151,30 @@ Counters::Counters(Isolate* isolate) const int DefaultTimedHistogramNumBuckets = 50; static const struct { - HistogramTimer Counters::*member; + NestedTimedHistogram Counters::*member; const char* caption; int max; - HistogramTimerResolution res; - } kHistogramTimers[] = { + TimedHistogramResolution res; + } kNestedTimedHistograms[] = { #define HT(name, caption, max, res) \ - {&Counters::name##_, #caption, max, HistogramTimerResolution::res}, - HISTOGRAM_TIMER_LIST(HT) HISTOGRAM_TIMER_LIST_SLOW(HT) + {&Counters::name##_, #caption, max, TimedHistogramResolution::res}, + NESTED_TIMED_HISTOGRAM_LIST(HT) NESTED_TIMED_HISTOGRAM_LIST_SLOW(HT) #undef HT }; - for (const auto& timer : kHistogramTimers) { - this->*timer.member = HistogramTimer(timer.caption, 0, timer.max, timer.res, - DefaultTimedHistogramNumBuckets, this); + for (const auto& timer : kNestedTimedHistograms) { + this->*timer.member = + NestedTimedHistogram(timer.caption, 0, timer.max, timer.res, + DefaultTimedHistogramNumBuckets, this); } static const struct { TimedHistogram Counters::*member; const char* caption; int max; - HistogramTimerResolution res; + TimedHistogramResolution res; } kTimedHistograms[] = { #define HT(name, caption, max, res) \ - {&Counters::name##_, #caption, max, HistogramTimerResolution::res}, + {&Counters::name##_, #caption, max, TimedHistogramResolution::res}, TIMED_HISTOGRAM_LIST(HT) #undef HT }; @@ -297,11 +300,11 @@ void Counters::ResetCreateHistogramFunction(CreateHistogramCallback f) { #undef HR #define HT(name, caption, max, res) name##_.Reset(); - HISTOGRAM_TIMER_LIST(HT) + NESTED_TIMED_HISTOGRAM_LIST(HT) #undef HT #define HT(name, caption, max, res) name##_.Reset(FLAG_slow_histograms); - HISTOGRAM_TIMER_LIST_SLOW(HT) + NESTED_TIMED_HISTOGRAM_LIST_SLOW(HT) #undef HT #define HT(name, caption, max, res) name##_.Reset(); diff --git a/src/logging/counters.h b/src/logging/counters.h index 745aebf47c..3a2527f49c 100644 --- a/src/logging/counters.h +++ b/src/logging/counters.h @@ -214,7 +214,7 @@ class Histogram { // Returns true if this histogram is enabled. bool Enabled() { return histogram_ != nullptr; } - const char* name() { return name_; } + const char* name() const { return name_; } int min() const { return min_; } int max() const { return max_; } @@ -259,204 +259,74 @@ class Histogram { Counters* counters_; }; -enum class HistogramTimerResolution { MILLISECOND, MICROSECOND }; +enum class TimedHistogramResolution { MILLISECOND, MICROSECOND }; // A thread safe histogram timer. It also allows distributions of // nested timed results. class TimedHistogram : public Histogram { public: - // Start the timer. Log if isolate non-null. - V8_EXPORT_PRIVATE void Start(base::ElapsedTimer* timer, Isolate* isolate); - - // Stop the timer and record the results. Log if isolate non-null. - V8_EXPORT_PRIVATE void Stop(base::ElapsedTimer* timer, Isolate* isolate); - // Records a TimeDelta::Max() result. Useful to record percentage of tasks // 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); + V8_EXPORT_PRIVATE void AddTimedSample(base::TimeDelta sample); + +#ifdef DEBUG + // Ensures that we don't have nested timers for TimedHistogram per thread, use + // NestedTimedHistogram which correctly pause and resume timers. + // This method assumes that each timer is alternating between stopped and + // started on a single thread. Multiple timers can be active on different + // threads. + bool ToggleRunningState(bool expected_is_running) const; +#endif // DEBUG protected: + void Stop(base::ElapsedTimer* timer); + void LogStart(Isolate* isolate); + void LogEnd(Isolate* isolate); + friend class Counters; - HistogramTimerResolution resolution_; + TimedHistogramResolution resolution_; TimedHistogram() = default; TimedHistogram(const char* name, int min, int max, - HistogramTimerResolution resolution, int num_buckets, + TimedHistogramResolution resolution, int num_buckets, Counters* counters) : Histogram(name, min, max, num_buckets, counters), resolution_(resolution) {} - void AddTimeSample(); }; -// Helper class for scoping a TimedHistogram. -class V8_NODISCARD TimedHistogramScope { - public: - explicit TimedHistogramScope(TimedHistogram* histogram, - Isolate* isolate = nullptr) - : histogram_(histogram), isolate_(isolate) { - histogram_->Start(&timer_, isolate); - } +class NestedTimedHistogramScope; +class PauseNestedTimedHistogramScope; - ~TimedHistogramScope() { histogram_->Stop(&timer_, isolate_); } - - private: - base::ElapsedTimer timer_; - TimedHistogram* histogram_; - Isolate* isolate_; - - DISALLOW_IMPLICIT_CONSTRUCTORS(TimedHistogramScope); -}; - -enum class OptionalTimedHistogramScopeMode { TAKE_TIME, DONT_TAKE_TIME }; - -// Helper class for scoping a TimedHistogram. -// It will not take time for mode = DONT_TAKE_TIME. -class V8_NODISCARD OptionalTimedHistogramScope { - public: - OptionalTimedHistogramScope(TimedHistogram* histogram, Isolate* isolate, - OptionalTimedHistogramScopeMode mode) - : histogram_(histogram), isolate_(isolate), mode_(mode) { - if (mode == OptionalTimedHistogramScopeMode::TAKE_TIME) { - histogram_->Start(&timer_, isolate); - } - } - - ~OptionalTimedHistogramScope() { - if (mode_ == OptionalTimedHistogramScopeMode::TAKE_TIME) { - histogram_->Stop(&timer_, isolate_); - } - } - - private: - base::ElapsedTimer timer_; - TimedHistogram* const histogram_; - Isolate* const isolate_; - const OptionalTimedHistogramScopeMode mode_; - DISALLOW_IMPLICIT_CONSTRUCTORS(OptionalTimedHistogramScope); -}; - -// Helper class for recording a TimedHistogram asynchronously with manual -// controls (it will not generate a report if destroyed without explicitly -// triggering a report). |async_counters| should be a shared_ptr to -// |histogram->counters()|, making it is safe to report to an -// AsyncTimedHistogram after the associated isolate has been destroyed. -// AsyncTimedHistogram can be moved/copied to avoid computing Now() multiple -// times when the times of multiple tasks are identical; each copy will generate -// its own report. -class AsyncTimedHistogram { - public: - explicit AsyncTimedHistogram(TimedHistogram* histogram, - std::shared_ptr async_counters) - : histogram_(histogram), async_counters_(std::move(async_counters)) { - histogram_->AssertReportsToCounters(async_counters_.get()); - histogram_->Start(&timer_, nullptr); - } - - // Records the time elapsed to |histogram_| and stops |timer_|. - void RecordDone() { histogram_->Stop(&timer_, nullptr); } - - // Records TimeDelta::Max() to |histogram_| and stops |timer_|. - void RecordAbandon() { histogram_->RecordAbandon(&timer_, nullptr); } - - private: - base::ElapsedTimer timer_; - TimedHistogram* histogram_; - std::shared_ptr async_counters_; -}; - -// Helper class for scoping a TimedHistogram, where the histogram is selected at -// stop time rather than start time. -// TODO(leszeks): This is heavily reliant on TimedHistogram::Start() doing -// nothing but starting the timer, and TimedHistogram::Stop() logging the sample -// correctly even if Start() was not called. This happens to be true iff Stop() -// is passed a null isolate, but that's an implementation detail of -// TimedHistogram, and we shouldn't rely on it. -class V8_NODISCARD LazyTimedHistogramScope { - public: - LazyTimedHistogramScope() : histogram_(nullptr) { timer_.Start(); } - ~LazyTimedHistogramScope() { - // We should set the histogram before this scope exits. - DCHECK_NOT_NULL(histogram_); - histogram_->Stop(&timer_, nullptr); - } - - void set_histogram(TimedHistogram* histogram) { histogram_ = histogram; } - - private: - base::ElapsedTimer timer_; - TimedHistogram* histogram_; -}; - -// A HistogramTimer allows distributions of non-nested timed results -// to be created. WARNING: This class is not thread safe and can only -// be run on the foreground thread. -class HistogramTimer : public TimedHistogram { +// A NestedTimedHistogram allows distributions of nested timed results. +class NestedTimedHistogram : public TimedHistogram { public: // Note: public for testing purposes only. - HistogramTimer(const char* name, int min, int max, - HistogramTimerResolution resolution, int num_buckets, - Counters* counters) + NestedTimedHistogram(const char* name, int min, int max, + TimedHistogramResolution resolution, int num_buckets, + Counters* counters) : TimedHistogram(name, min, max, resolution, num_buckets, counters) {} - inline void Start(); - inline void Stop(); - - // Returns true if the timer is running. - bool Running() { return Enabled() && timer_.IsStarted(); } - - // TODO(bmeurer): Remove this when HistogramTimerScope is fixed. -#ifdef DEBUG - base::ElapsedTimer* timer() { return &timer_; } -#endif - private: friend class Counters; + friend class NestedTimedHistogramScope; + friend class PauseNestedTimedHistogramScope; - base::ElapsedTimer timer_; - - HistogramTimer() = default; -}; - -// Helper class for scoping a HistogramTimer. -// TODO(bmeurer): The ifdeffery is an ugly hack around the fact that the -// Parser is currently reentrant (when it throws an error, we call back -// into JavaScript and all bets are off), but ElapsedTimer is not -// reentry-safe. Fix this properly and remove |allow_nesting|. -class V8_NODISCARD HistogramTimerScope { - public: - explicit HistogramTimerScope(HistogramTimer* timer, - bool allow_nesting = false) -#ifdef DEBUG - : timer_(timer), skipped_timer_start_(false) { - if (timer_->timer()->IsStarted() && allow_nesting) { - skipped_timer_start_ = true; - } else { - timer_->Start(); - } - } -#else - : timer_(timer) { - timer_->Start(); - } -#endif - ~HistogramTimerScope() { -#ifdef DEBUG - if (!skipped_timer_start_) { - timer_->Stop(); - } -#else - timer_->Stop(); -#endif + inline NestedTimedHistogramScope* Enter(NestedTimedHistogramScope* next) { + NestedTimedHistogramScope* previous = current_; + current_ = next; + return previous; } - private: - HistogramTimer* timer_; -#ifdef DEBUG - bool skipped_timer_start_; -#endif + inline void Leave(NestedTimedHistogramScope* previous) { + current_ = previous; + } + + NestedTimedHistogramScope* current_ = nullptr; + + NestedTimedHistogram() = default; }; // A histogram timer that can aggregate events within a larger scope. @@ -674,9 +544,9 @@ class Counters : public std::enable_shared_from_this { #undef HR #define HT(name, caption, max, res) \ - HistogramTimer* name() { return &name##_; } - HISTOGRAM_TIMER_LIST(HT) - HISTOGRAM_TIMER_LIST_SLOW(HT) + NestedTimedHistogram* name() { return &name##_; } + NESTED_TIMED_HISTOGRAM_LIST(HT) + NESTED_TIMED_HISTOGRAM_LIST_SLOW(HT) #undef HT #define HT(name, caption, max, res) \ @@ -714,8 +584,8 @@ class Counters : public std::enable_shared_from_this { // clang-format off enum Id { #define RATE_ID(name, caption, max, res) k_##name, - HISTOGRAM_TIMER_LIST(RATE_ID) - HISTOGRAM_TIMER_LIST_SLOW(RATE_ID) + NESTED_TIMED_HISTOGRAM_LIST(RATE_ID) + NESTED_TIMED_HISTOGRAM_LIST_SLOW(RATE_ID) TIMED_HISTOGRAM_LIST(RATE_ID) #undef RATE_ID #define AGGREGATABLE_ID(name, caption) k_##name, @@ -766,7 +636,7 @@ class Counters : public std::enable_shared_from_this { friend class StatsTable; friend class StatsCounterBase; friend class Histogram; - friend class HistogramTimer; + friend class NestedTimedHistogramScope; int* FindLocation(const char* name) { return stats_table_.FindLocation(name); @@ -786,9 +656,9 @@ class Counters : public std::enable_shared_from_this { HISTOGRAM_RANGE_LIST(HR) #undef HR -#define HT(name, caption, max, res) HistogramTimer name##_; - HISTOGRAM_TIMER_LIST(HT) - HISTOGRAM_TIMER_LIST_SLOW(HT) +#define HT(name, caption, max, res) NestedTimedHistogram name##_; + NESTED_TIMED_HISTOGRAM_LIST(HT) + NESTED_TIMED_HISTOGRAM_LIST_SLOW(HT) #undef HT #define HT(name, caption, max, res) TimedHistogram name##_; @@ -845,13 +715,6 @@ class Counters : public std::enable_shared_from_this { DISALLOW_IMPLICIT_CONSTRUCTORS(Counters); }; -void HistogramTimer::Start() { - TimedHistogram::Start(&timer_, counters()->isolate()); -} - -void HistogramTimer::Stop() { - TimedHistogram::Stop(&timer_, counters()->isolate()); -} } // namespace internal } // namespace v8 diff --git a/src/logging/log-inl.h b/src/logging/log-inl.h index 83677f5f64..0929854dcb 100644 --- a/src/logging/log-inl.h +++ b/src/logging/log-inl.h @@ -28,19 +28,8 @@ CodeEventListener::LogEventsAndTags Logger::ToNativeByScript( } } -void Logger::CallEventLogger(Isolate* isolate, const char* name, StartEnd se, - bool expose_to_api) { - if (isolate->event_logger()) { - if (isolate->event_logger() == DefaultEventLoggerSentinel) { - LOG(isolate, TimerEvent(se, name)); - } else if (expose_to_api) { - isolate->event_logger()(name, se); - } - } -} - template -void TimerEventScope::LogTimerEvent(Logger::StartEnd se) { +void TimerEventScope::LogTimerEvent(v8::LogEventStatus se) { Logger::CallEventLogger(isolate_, TimerEvent::name(), se, TimerEvent::expose_to_api()); } diff --git a/src/logging/log.cc b/src/logging/log.cc index 7b6540e60f..4f6aa856d7 100644 --- a/src/logging/log.cc +++ b/src/logging/log.cc @@ -1110,16 +1110,16 @@ void Logger::CurrentTimeEvent() { msg.WriteToLogFile(); } -void Logger::TimerEvent(Logger::StartEnd se, const char* name) { +void Logger::TimerEvent(v8::LogEventStatus se, const char* name) { MSG_BUILDER(); switch (se) { - case START: + case kStart: msg << "timer-event-start"; break; - case END: + case kEnd: msg << "timer-event-end"; break; - case STAMP: + case kStamp: msg << "timer-event"; } msg << kNext << name << kNext << Time(); @@ -1152,7 +1152,7 @@ bool Logger::is_logging() { // Instantiate template methods. #define V(TimerName, expose) \ template void TimerEventScope::LogTimerEvent( \ - Logger::StartEnd se); + v8::LogEventStatus se); TIMER_EVENTS_LIST(V) #undef V diff --git a/src/logging/log.h b/src/logging/log.h index 83e36ffbce..612c2a2df7 100644 --- a/src/logging/log.h +++ b/src/logging/log.h @@ -12,6 +12,7 @@ #include "include/v8-profiler.h" #include "src/base/platform/elapsed-timer.h" +#include "src/execution/isolate.h" #include "src/logging/code-events.h" #include "src/objects/objects.h" @@ -103,8 +104,6 @@ enum class LogSeparator; class Logger : public CodeEventListener { public: - enum StartEnd { START = 0, END = 1, STAMP = 2 }; - enum class ScriptEventType { kReserveId, kCreate, @@ -263,7 +262,7 @@ class Logger : public CodeEventListener { void CurrentTimeEvent(); - V8_EXPORT_PRIVATE void TimerEvent(StartEnd se, const char* name); + V8_EXPORT_PRIVATE void TimerEvent(v8::LogEventStatus se, const char* name); void BasicBlockCounterEvent(const char* name, int block_id, uint32_t count); @@ -274,8 +273,15 @@ class Logger : public CodeEventListener { static void DefaultEventLoggerSentinel(const char* name, int event) {} - V8_INLINE static void CallEventLogger(Isolate* isolate, const char* name, - StartEnd se, bool expose_to_api); + static void CallEventLogger(Isolate* isolate, const char* name, + v8::LogEventStatus se, bool expose_to_api) { + if (!isolate->event_logger()) return; + if (isolate->event_logger() == DefaultEventLoggerSentinel) { + LOG(isolate, TimerEvent(se, name)); + } else if (expose_to_api) { + isolate->event_logger()(name, static_cast(se)); + } + } V8_EXPORT_PRIVATE bool is_logging(); @@ -399,13 +405,13 @@ template class V8_NODISCARD TimerEventScope { public: explicit TimerEventScope(Isolate* isolate) : isolate_(isolate) { - LogTimerEvent(Logger::START); + LogTimerEvent(v8::LogEventStatus::kStart); } - ~TimerEventScope() { LogTimerEvent(Logger::END); } + ~TimerEventScope() { LogTimerEvent(v8::LogEventStatus::kEnd); } private: - void LogTimerEvent(Logger::StartEnd se); + void LogTimerEvent(v8::LogEventStatus se); Isolate* isolate_; }; diff --git a/src/parsing/parser.cc b/src/parsing/parser.cc index fc07370a07..a541734bdd 100644 --- a/src/parsing/parser.cc +++ b/src/parsing/parser.cc @@ -516,8 +516,6 @@ void MaybeProcessSourceRanges(ParseInfo* parse_info, Expression* root, void Parser::ParseProgram(Isolate* isolate, Handle