Commit a12c6fa2 authored by Leszek Swirski's avatar Leszek Swirski Committed by V8 LUCI CQ

Revert "[counters] Fix reentrant timers for V8.Execute"

This reverts commit fffcbaea.

Reason for revert: Breaks in Chromium (e.g. https://ci.chromium.org/p/v8/builders/ci/Linux%20V8%20FYI%20Release%20%28NVIDIA%29)

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<EXTERNAL>
>
> Bug: v8:11946
> Change-Id: I45e4b7ff77b5948b605dd50539044cb26222fa21
> Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/3001345
> Reviewed-by: Omer Katz <omerkatz@chromium.org>
> Reviewed-by: Thibaud Michaud <thibaudm@chromium.org>
> Reviewed-by: Victor Gomes <victorgomes@chromium.org>
> Reviewed-by: Leszek Swirski <leszeks@chromium.org>
> Commit-Queue: Camillo Bruni <cbruni@chromium.org>
> Cr-Commit-Position: refs/heads/master@{#76111}

Bug: v8:11946
Change-Id: I954de1afbabf101fb5d4f52eca0d3b80a723385b
Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/3077153
Bot-Commit: Rubber Stamper <rubber-stamper@appspot.gserviceaccount.com>
Commit-Queue: Leszek Swirski <leszeks@chromium.org>
Owners-Override: Leszek Swirski <leszeks@chromium.org>
Cr-Commit-Position: refs/heads/master@{#76138}
parent 7810ce04
...@@ -1411,7 +1411,6 @@ filegroup( ...@@ -1411,7 +1411,6 @@ filegroup(
"src/logging/counters-definitions.h", "src/logging/counters-definitions.h",
"src/logging/counters.cc", "src/logging/counters.cc",
"src/logging/counters.h", "src/logging/counters.h",
"src/logging/counters-scopes.h",
"src/logging/local-logger.cc", "src/logging/local-logger.cc",
"src/logging/local-logger.h", "src/logging/local-logger.h",
"src/logging/log-inl.h", "src/logging/log-inl.h",
......
...@@ -2835,7 +2835,6 @@ v8_header_set("v8_internal_headers") { ...@@ -2835,7 +2835,6 @@ v8_header_set("v8_internal_headers") {
"src/libsampler/sampler.h", "src/libsampler/sampler.h",
"src/logging/code-events.h", "src/logging/code-events.h",
"src/logging/counters-definitions.h", "src/logging/counters-definitions.h",
"src/logging/counters-scopes.h",
"src/logging/counters.h", "src/logging/counters.h",
"src/logging/local-logger.h", "src/logging/local-logger.h",
"src/logging/log-inl.h", "src/logging/log-inl.h",
......
...@@ -76,6 +76,7 @@ inline JSReceiver FunctionCallbackArguments::holder() { ...@@ -76,6 +76,7 @@ inline JSReceiver FunctionCallbackArguments::holder() {
CALLBACK_INFO, RECEIVER, Debug::k##ACCESSOR_KIND)) { \ CALLBACK_INFO, RECEIVER, Debug::k##ACCESSOR_KIND)) { \
return RETURN_VALUE(); \ return RETURN_VALUE(); \
} \ } \
VMState<EXTERNAL> state(ISOLATE); \
ExternalCallbackScope call_scope(ISOLATE, FUNCTION_ADDR(F)); \ ExternalCallbackScope call_scope(ISOLATE, FUNCTION_ADDR(F)); \
PropertyCallbackInfo<API_RETURN_TYPE> callback_info(values_); PropertyCallbackInfo<API_RETURN_TYPE> callback_info(values_);
...@@ -84,6 +85,7 @@ inline JSReceiver FunctionCallbackArguments::holder() { ...@@ -84,6 +85,7 @@ inline JSReceiver FunctionCallbackArguments::holder() {
if (ISOLATE->debug_execution_mode() == DebugInfo::kSideEffects) { \ if (ISOLATE->debug_execution_mode() == DebugInfo::kSideEffects) { \
return RETURN_VALUE(); \ return RETURN_VALUE(); \
} \ } \
VMState<EXTERNAL> state(ISOLATE); \
ExternalCallbackScope call_scope(ISOLATE, FUNCTION_ADDR(F)); \ ExternalCallbackScope call_scope(ISOLATE, FUNCTION_ADDR(F)); \
PropertyCallbackInfo<API_RETURN_TYPE> callback_info(values_); PropertyCallbackInfo<API_RETURN_TYPE> callback_info(values_);
...@@ -147,6 +149,7 @@ Handle<Object> FunctionCallbackArguments::Call(CallHandlerInfo handler) { ...@@ -147,6 +149,7 @@ Handle<Object> FunctionCallbackArguments::Call(CallHandlerInfo handler) {
Debug::kNotAccessor)) { Debug::kNotAccessor)) {
return Handle<Object>(); return Handle<Object>();
} }
VMState<EXTERNAL> state(isolate);
ExternalCallbackScope call_scope(isolate, FUNCTION_ADDR(f)); ExternalCallbackScope call_scope(isolate, FUNCTION_ADDR(f));
FunctionCallbackInfo<v8::Value> info(values_, argv_, argc_); FunctionCallbackInfo<v8::Value> info(values_, argv_, argc_);
f(info); f(info);
......
...@@ -58,7 +58,7 @@ ...@@ -58,7 +58,7 @@
#include "src/init/v8.h" #include "src/init/v8.h"
#include "src/json/json-parser.h" #include "src/json/json-parser.h"
#include "src/json/json-stringifier.h" #include "src/json/json-stringifier.h"
#include "src/logging/counters-scopes.h" #include "src/logging/counters.h"
#include "src/logging/metrics.h" #include "src/logging/metrics.h"
#include "src/logging/runtime-call-stats-scope.h" #include "src/logging/runtime-call-stats-scope.h"
#include "src/logging/tracing-flags.h" #include "src/logging/tracing-flags.h"
...@@ -1967,11 +1967,10 @@ MaybeLocal<Value> Script::Run(Local<Context> context) { ...@@ -1967,11 +1967,10 @@ MaybeLocal<Value> Script::Run(Local<Context> context) {
TRACE_EVENT_CALL_STATS_SCOPED(isolate, "v8", "V8.Execute"); TRACE_EVENT_CALL_STATS_SCOPED(isolate, "v8", "V8.Execute");
ENTER_V8(isolate, context, Script, Run, MaybeLocal<Value>(), ENTER_V8(isolate, context, Script, Run, MaybeLocal<Value>(),
InternalEscapableScope); InternalEscapableScope);
i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate); i::HistogramTimerScope execute_timer(isolate->counters()->execute(), true);
i::NestedTimedHistogramScope execute_timer(
isolate->counters()->execute_precise());
i::AggregatingHistogramTimerScope histogram_timer( i::AggregatingHistogramTimerScope histogram_timer(
isolate->counters()->compile_lazy()); isolate->counters()->compile_lazy());
i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
auto fun = i::Handle<i::JSFunction>::cast(Utils::OpenHandle(this)); auto fun = i::Handle<i::JSFunction>::cast(Utils::OpenHandle(this));
// TODO(crbug.com/1193459): remove once ablation study is completed // TODO(crbug.com/1193459): remove once ablation study is completed
...@@ -2294,10 +2293,9 @@ MaybeLocal<Value> Module::Evaluate(Local<Context> context) { ...@@ -2294,10 +2293,9 @@ MaybeLocal<Value> Module::Evaluate(Local<Context> context) {
TRACE_EVENT_CALL_STATS_SCOPED(isolate, "v8", "V8.Execute"); TRACE_EVENT_CALL_STATS_SCOPED(isolate, "v8", "V8.Execute");
ENTER_V8(isolate, context, Module, Evaluate, MaybeLocal<Value>(), ENTER_V8(isolate, context, Module, Evaluate, MaybeLocal<Value>(),
InternalEscapableScope); InternalEscapableScope);
i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate); i::HistogramTimerScope execute_timer(isolate->counters()->execute(), true);
i::NestedTimedHistogramScope execute_timer(
isolate->counters()->execute_precise());
i::AggregatingHistogramTimerScope timer(isolate->counters()->compile_lazy()); i::AggregatingHistogramTimerScope timer(isolate->counters()->compile_lazy());
i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
i::Handle<i::Module> self = Utils::OpenHandle(this); i::Handle<i::Module> self = Utils::OpenHandle(this);
Utils::ApiCheck(self->status() >= i::Module::kInstantiated, Utils::ApiCheck(self->status() >= i::Module::kInstantiated,
...@@ -4952,8 +4950,6 @@ MaybeLocal<Value> Object::CallAsFunction(Local<Context> context, ...@@ -4952,8 +4950,6 @@ MaybeLocal<Value> Object::CallAsFunction(Local<Context> context,
ENTER_V8(isolate, context, Object, CallAsFunction, MaybeLocal<Value>(), ENTER_V8(isolate, context, Object, CallAsFunction, MaybeLocal<Value>(),
InternalEscapableScope); InternalEscapableScope);
i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate); i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
i::NestedTimedHistogramScope execute_timer(
isolate->counters()->execute_precise());
auto self = Utils::OpenHandle(this); auto self = Utils::OpenHandle(this);
auto recv_obj = Utils::OpenHandle(*recv); auto recv_obj = Utils::OpenHandle(*recv);
STATIC_ASSERT(sizeof(v8::Local<v8::Value>) == sizeof(i::Handle<i::Object>)); STATIC_ASSERT(sizeof(v8::Local<v8::Value>) == sizeof(i::Handle<i::Object>));
...@@ -4972,8 +4968,6 @@ MaybeLocal<Value> Object::CallAsConstructor(Local<Context> context, int argc, ...@@ -4972,8 +4968,6 @@ MaybeLocal<Value> Object::CallAsConstructor(Local<Context> context, int argc,
ENTER_V8(isolate, context, Object, CallAsConstructor, MaybeLocal<Value>(), ENTER_V8(isolate, context, Object, CallAsConstructor, MaybeLocal<Value>(),
InternalEscapableScope); InternalEscapableScope);
i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate); i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
i::NestedTimedHistogramScope execute_timer(
isolate->counters()->execute_precise());
auto self = Utils::OpenHandle(this); auto self = Utils::OpenHandle(this);
STATIC_ASSERT(sizeof(v8::Local<v8::Value>) == sizeof(i::Handle<i::Object>)); STATIC_ASSERT(sizeof(v8::Local<v8::Value>) == sizeof(i::Handle<i::Object>));
i::Handle<i::Object>* args = reinterpret_cast<i::Handle<i::Object>*>(argv); i::Handle<i::Object>* args = reinterpret_cast<i::Handle<i::Object>*>(argv);
...@@ -5011,8 +5005,6 @@ MaybeLocal<Object> Function::NewInstanceWithSideEffectType( ...@@ -5011,8 +5005,6 @@ MaybeLocal<Object> Function::NewInstanceWithSideEffectType(
ENTER_V8(isolate, context, Function, NewInstance, MaybeLocal<Object>(), ENTER_V8(isolate, context, Function, NewInstance, MaybeLocal<Object>(),
InternalEscapableScope); InternalEscapableScope);
i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate); i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
i::NestedTimedHistogramScope execute_timer(
isolate->counters()->execute_precise());
auto self = Utils::OpenHandle(this); auto self = Utils::OpenHandle(this);
STATIC_ASSERT(sizeof(v8::Local<v8::Value>) == sizeof(i::Handle<i::Object>)); STATIC_ASSERT(sizeof(v8::Local<v8::Value>) == sizeof(i::Handle<i::Object>));
bool should_set_has_no_side_effect = bool should_set_has_no_side_effect =
...@@ -5062,8 +5054,6 @@ MaybeLocal<v8::Value> Function::Call(Local<Context> context, ...@@ -5062,8 +5054,6 @@ MaybeLocal<v8::Value> Function::Call(Local<Context> context,
ENTER_V8(isolate, context, Function, Call, MaybeLocal<Value>(), ENTER_V8(isolate, context, Function, Call, MaybeLocal<Value>(),
InternalEscapableScope); InternalEscapableScope);
i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate); i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
i::NestedTimedHistogramScope execute_timer(
isolate->counters()->execute_precise());
auto self = Utils::OpenHandle(this); auto self = Utils::OpenHandle(this);
Utils::ApiCheck(!self.is_null(), "v8::Function::Call", Utils::ApiCheck(!self.is_null(), "v8::Function::Call",
"Function to be called is a null pointer"); "Function to be called is a null pointer");
...@@ -8894,7 +8884,7 @@ bool Isolate::IdleNotificationDeadline(double deadline_in_seconds) { ...@@ -8894,7 +8884,7 @@ bool Isolate::IdleNotificationDeadline(double deadline_in_seconds) {
void Isolate::LowMemoryNotification() { void Isolate::LowMemoryNotification() {
i::Isolate* isolate = reinterpret_cast<i::Isolate*>(this); i::Isolate* isolate = reinterpret_cast<i::Isolate*>(this);
{ {
i::NestedTimedHistogramScope idle_notification_scope( i::HistogramTimerScope idle_notification_scope(
isolate->counters()->gc_low_memory_notification()); isolate->counters()->gc_low_memory_notification());
TRACE_EVENT0("v8", "V8.GCLowMemoryNotification"); TRACE_EVENT0("v8", "V8.GCLowMemoryNotification");
isolate->heap()->CollectAllAvailableGarbage( isolate->heap()->CollectAllAvailableGarbage(
...@@ -10240,6 +10230,7 @@ void InvokeAccessorGetterCallback( ...@@ -10240,6 +10230,7 @@ void InvokeAccessorGetterCallback(
Isolate* isolate = reinterpret_cast<Isolate*>(info.GetIsolate()); Isolate* isolate = reinterpret_cast<Isolate*>(info.GetIsolate());
RCS_SCOPE(isolate, RuntimeCallCounterId::kAccessorGetterCallback); RCS_SCOPE(isolate, RuntimeCallCounterId::kAccessorGetterCallback);
Address getter_address = reinterpret_cast<Address>(getter); Address getter_address = reinterpret_cast<Address>(getter);
VMState<EXTERNAL> state(isolate);
ExternalCallbackScope call_scope(isolate, getter_address); ExternalCallbackScope call_scope(isolate, getter_address);
getter(property, info); getter(property, info);
} }
...@@ -10249,6 +10240,7 @@ void InvokeFunctionCallback(const v8::FunctionCallbackInfo<v8::Value>& info, ...@@ -10249,6 +10240,7 @@ void InvokeFunctionCallback(const v8::FunctionCallbackInfo<v8::Value>& info,
Isolate* isolate = reinterpret_cast<Isolate*>(info.GetIsolate()); Isolate* isolate = reinterpret_cast<Isolate*>(info.GetIsolate());
RCS_SCOPE(isolate, RuntimeCallCounterId::kFunctionCallback); RCS_SCOPE(isolate, RuntimeCallCounterId::kFunctionCallback);
Address callback_address = reinterpret_cast<Address>(callback); Address callback_address = reinterpret_cast<Address>(callback);
VMState<EXTERNAL> state(isolate);
ExternalCallbackScope call_scope(isolate, callback_address); ExternalCallbackScope call_scope(isolate, callback_address);
callback(info); callback(info);
} }
......
...@@ -14,20 +14,15 @@ namespace base { ...@@ -14,20 +14,15 @@ namespace base {
class ElapsedTimer final { class ElapsedTimer final {
public: public:
#ifdef DEBUG #ifdef DEBUG
ElapsedTimer() : start_ticks_(), started_(false) {} ElapsedTimer() : started_(false) {}
#else
ElapsedTimer() : start_ticks_() {}
#endif #endif
// Starts this timer. Once started a timer can be checked with // Starts this timer. Once started a timer can be checked with
// |Elapsed()| or |HasExpired()|, and may be restarted using |Restart()|. // |Elapsed()| or |HasExpired()|, and may be restarted using |Restart()|.
// This method must not be called on an already started timer. // This method must not be called on an already started timer.
void Start() { Start(Now()); } void Start() {
void Start(TimeTicks now) {
DCHECK(!now.IsNull());
DCHECK(!IsStarted()); DCHECK(!IsStarted());
set_start_ticks(now); start_ticks_ = Now();
#ifdef DEBUG #ifdef DEBUG
started_ = true; started_ = true;
#endif #endif
...@@ -38,7 +33,7 @@ class ElapsedTimer final { ...@@ -38,7 +33,7 @@ class ElapsedTimer final {
// started before. // started before.
void Stop() { void Stop() {
DCHECK(IsStarted()); DCHECK(IsStarted());
set_start_ticks(TimeTicks()); start_ticks_ = TimeTicks();
#ifdef DEBUG #ifdef DEBUG
started_ = false; started_ = false;
#endif #endif
...@@ -57,51 +52,21 @@ class ElapsedTimer final { ...@@ -57,51 +52,21 @@ class ElapsedTimer final {
// and then starting the timer again, but does so in one single operation, // 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 // avoiding the need to obtain the clock value twice. It may only be called
// on a previously started timer. // on a previously started timer.
TimeDelta Restart() { return Restart(Now()); } TimeDelta Restart() {
TimeDelta Restart(TimeTicks now) {
DCHECK(!now.IsNull());
DCHECK(IsStarted()); DCHECK(IsStarted());
TimeDelta elapsed = now - start_ticks_; TimeTicks ticks = Now();
TimeDelta elapsed = ticks - start_ticks_;
DCHECK_GE(elapsed.InMicroseconds(), 0); DCHECK_GE(elapsed.InMicroseconds(), 0);
set_start_ticks(now); start_ticks_ = ticks;
DCHECK(IsStarted()); DCHECK(IsStarted());
return elapsed; return elapsed;
} }
void Pause() { Pause(Now()); }
void Pause(TimeTicks now) {
TimeDelta elapsed = Elapsed(now);
DCHECK(IsStarted());
DCHECK(!is_paused_);
#ifdef DEBUG
is_paused_ = true;
#endif
set_paused_elapsed(elapsed);
}
void Resume() { Resume(Now()); }
void Resume(TimeTicks now) {
DCHECK(!now.IsNull());
DCHECK(IsStarted());
TimeDelta elapsed = paused_elapsed();
#ifdef DEBUG
is_paused_ = false;
#endif
set_start_ticks(now - elapsed);
DCHECK(IsStarted());
}
// Returns the time elapsed since the previous start. This method may only // Returns the time elapsed since the previous start. This method may only
// be called on a previously started timer. // be called on a previously started timer.
TimeDelta Elapsed() const { return Elapsed(Now()); } TimeDelta Elapsed() const {
TimeDelta Elapsed(TimeTicks now) const {
DCHECK(!now.IsNull());
DCHECK(IsStarted()); DCHECK(IsStarted());
TimeDelta elapsed = now - start_ticks(); TimeDelta elapsed = Now() - start_ticks_;
DCHECK_GE(elapsed.InMicroseconds(), 0); DCHECK_GE(elapsed.InMicroseconds(), 0);
return elapsed; return elapsed;
} }
...@@ -121,34 +86,9 @@ class ElapsedTimer final { ...@@ -121,34 +86,9 @@ class ElapsedTimer final {
return now; return now;
} }
TimeDelta paused_elapsed() { TimeTicks start_ticks_;
DCHECK(IsStarted());
DCHECK(is_paused_);
return paused_elapsed_;
}
void set_paused_elapsed(TimeDelta delta) {
DCHECK(IsStarted());
DCHECK(is_paused_);
paused_elapsed_ = delta;
}
TimeTicks start_ticks() const {
DCHECK(!is_paused_);
return start_ticks_;
}
void set_start_ticks(TimeTicks start_ticks) {
DCHECK(!is_paused_);
start_ticks_ = start_ticks;
}
union {
TimeTicks start_ticks_;
TimeDelta paused_elapsed_;
};
#ifdef DEBUG #ifdef DEBUG
bool started_; bool started_;
bool is_paused_ = false;
#endif #endif
}; };
......
...@@ -44,7 +44,7 @@ ...@@ -44,7 +44,7 @@
#include "src/heap/parked-scope.h" #include "src/heap/parked-scope.h"
#include "src/init/bootstrapper.h" #include "src/init/bootstrapper.h"
#include "src/interpreter/interpreter.h" #include "src/interpreter/interpreter.h"
#include "src/logging/counters-scopes.h" #include "src/logging/counters.h"
#include "src/logging/log-inl.h" #include "src/logging/log-inl.h"
#include "src/logging/runtime-call-stats-scope.h" #include "src/logging/runtime-call-stats-scope.h"
#include "src/objects/feedback-cell-inl.h" #include "src/objects/feedback-cell-inl.h"
...@@ -1354,10 +1354,10 @@ MaybeHandle<SharedFunctionInfo> CompileToplevel( ...@@ -1354,10 +1354,10 @@ MaybeHandle<SharedFunctionInfo> CompileToplevel(
// Measure how long it takes to do the compilation; only take the // Measure how long it takes to do the compilation; only take the
// rest of the function into account to avoid overlap with the // rest of the function into account to avoid overlap with the
// parsing statistics. // parsing statistics.
NestedTimedHistogram* rate = parse_info->flags().is_eval() HistogramTimer* rate = parse_info->flags().is_eval()
? isolate->counters()->compile_eval() ? isolate->counters()->compile_eval()
: isolate->counters()->compile(); : isolate->counters()->compile();
NestedTimedHistogramScope timer(rate); HistogramTimerScope timer(rate);
TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("v8.compile"), TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("v8.compile"),
parse_info->flags().is_eval() ? "V8.CompileEval" : "V8.Compile"); parse_info->flags().is_eval() ? "V8.CompileEval" : "V8.Compile");
...@@ -1726,8 +1726,7 @@ bool Compiler::CollectSourcePositions(Isolate* isolate, ...@@ -1726,8 +1726,7 @@ bool Compiler::CollectSourcePositions(Isolate* isolate,
RCS_SCOPE(isolate, RuntimeCallCounterId::kCompileCollectSourcePositions); RCS_SCOPE(isolate, RuntimeCallCounterId::kCompileCollectSourcePositions);
TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("v8.compile"), TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("v8.compile"),
"V8.CollectSourcePositions"); "V8.CollectSourcePositions");
NestedTimedHistogramScope timer( HistogramTimerScope timer(isolate->counters()->collect_source_positions());
isolate->counters()->collect_source_positions());
// Set up parse info. // Set up parse info.
UnoptimizedCompileFlags flags = UnoptimizedCompileFlags flags =
...@@ -2249,14 +2248,14 @@ MaybeHandle<JSFunction> Compiler::GetFunctionFromEval( ...@@ -2249,14 +2248,14 @@ MaybeHandle<JSFunction> Compiler::GetFunctionFromEval(
// (via v8::Isolate::SetAllowCodeGenerationFromStringsCallback) // (via v8::Isolate::SetAllowCodeGenerationFromStringsCallback)
bool CodeGenerationFromStringsAllowed(Isolate* isolate, Handle<Context> context, bool CodeGenerationFromStringsAllowed(Isolate* isolate, Handle<Context> context,
Handle<String> source) { Handle<String> source) {
RCS_SCOPE(isolate, RuntimeCallCounterId::kCodeGenerationFromStringsCallbacks);
DCHECK(context->allow_code_gen_from_strings().IsFalse(isolate)); DCHECK(context->allow_code_gen_from_strings().IsFalse(isolate));
DCHECK(isolate->allow_code_gen_callback()); DCHECK(isolate->allow_code_gen_callback());
// Callback set. Let it decide if code generation is allowed.
VMState<EXTERNAL> state(isolate);
RCS_SCOPE(isolate, RuntimeCallCounterId::kCodeGenerationFromStringsCallbacks);
AllowCodeGenerationFromStringsCallback callback = AllowCodeGenerationFromStringsCallback callback =
isolate->allow_code_gen_callback(); isolate->allow_code_gen_callback();
ExternalCallbackScope external_callback(isolate,
reinterpret_cast<Address>(callback));
// Callback set. Let it decide if code generation is allowed.
return callback(v8::Utils::ToLocal(context), v8::Utils::ToLocal(source)); return callback(v8::Utils::ToLocal(context), v8::Utils::ToLocal(source));
} }
...@@ -2440,7 +2439,8 @@ struct ScriptCompileTimerScope { ...@@ -2440,7 +2439,8 @@ struct ScriptCompileTimerScope {
explicit ScriptCompileTimerScope( explicit ScriptCompileTimerScope(
Isolate* isolate, ScriptCompiler::NoCacheReason no_cache_reason) Isolate* isolate, ScriptCompiler::NoCacheReason no_cache_reason)
: isolate_(isolate), : isolate_(isolate),
all_scripts_histogram_scope_(isolate->counters()->compile_script()), all_scripts_histogram_scope_(isolate->counters()->compile_script(),
true),
no_cache_reason_(no_cache_reason), no_cache_reason_(no_cache_reason),
hit_isolate_cache_(false), hit_isolate_cache_(false),
producing_code_cache_(false), producing_code_cache_(false),
...@@ -2479,7 +2479,7 @@ struct ScriptCompileTimerScope { ...@@ -2479,7 +2479,7 @@ struct ScriptCompileTimerScope {
LazyTimedHistogramScope histogram_scope_; LazyTimedHistogramScope histogram_scope_;
// TODO(leszeks): This timer is the sum of the other times, consider removing // TODO(leszeks): This timer is the sum of the other times, consider removing
// it to save space. // it to save space.
NestedTimedHistogramScope all_scripts_histogram_scope_; HistogramTimerScope all_scripts_histogram_scope_;
ScriptCompiler::NoCacheReason no_cache_reason_; ScriptCompiler::NoCacheReason no_cache_reason_;
bool hit_isolate_cache_; bool hit_isolate_cache_;
bool producing_code_cache_; bool producing_code_cache_;
...@@ -2845,8 +2845,7 @@ MaybeHandle<SharedFunctionInfo> Compiler::GetSharedFunctionInfoForScript( ...@@ -2845,8 +2845,7 @@ MaybeHandle<SharedFunctionInfo> Compiler::GetSharedFunctionInfoForScript(
} else if (can_consume_code_cache) { } else if (can_consume_code_cache) {
compile_timer.set_consuming_code_cache(); compile_timer.set_consuming_code_cache();
// Then check cached code provided by embedder. // Then check cached code provided by embedder.
NestedTimedHistogramScope timer( HistogramTimerScope timer(isolate->counters()->compile_deserialize());
isolate->counters()->compile_deserialize());
RCS_SCOPE(isolate, RuntimeCallCounterId::kCompileDeserialize); RCS_SCOPE(isolate, RuntimeCallCounterId::kCompileDeserialize);
TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("v8.compile"), TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("v8.compile"),
"V8.CompileDeserialize"); "V8.CompileDeserialize");
...@@ -2933,7 +2932,7 @@ MaybeHandle<JSFunction> Compiler::GetWrappedFunction( ...@@ -2933,7 +2932,7 @@ MaybeHandle<JSFunction> Compiler::GetWrappedFunction(
if (can_consume_code_cache) { if (can_consume_code_cache) {
compile_timer.set_consuming_code_cache(); compile_timer.set_consuming_code_cache();
// Then check cached code provided by embedder. // Then check cached code provided by embedder.
NestedTimedHistogramScope timer(isolate->counters()->compile_deserialize()); HistogramTimerScope timer(isolate->counters()->compile_deserialize());
RCS_SCOPE(isolate, RuntimeCallCounterId::kCompileDeserialize); RCS_SCOPE(isolate, RuntimeCallCounterId::kCompileDeserialize);
TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("v8.compile"), TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("v8.compile"),
"V8.CompileDeserialize"); "V8.CompileDeserialize");
......
...@@ -54,9 +54,7 @@ VMState<Tag>::~VMState() { ...@@ -54,9 +54,7 @@ VMState<Tag>::~VMState() {
ExternalCallbackScope::ExternalCallbackScope(Isolate* isolate, Address callback) ExternalCallbackScope::ExternalCallbackScope(Isolate* isolate, Address callback)
: isolate_(isolate), : isolate_(isolate),
callback_(callback), 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 #ifdef USE_SIMULATOR
scope_address_ = Simulator::current(isolate)->get_sp(); scope_address_ = Simulator::current(isolate)->get_sp();
#endif #endif
......
...@@ -7,7 +7,6 @@ ...@@ -7,7 +7,6 @@
#include "include/v8.h" #include "include/v8.h"
#include "src/common/globals.h" #include "src/common/globals.h"
#include "src/logging/counters-scopes.h"
namespace v8 { namespace v8 {
namespace internal { namespace internal {
...@@ -47,8 +46,6 @@ class V8_NODISCARD ExternalCallbackScope { ...@@ -47,8 +46,6 @@ class V8_NODISCARD ExternalCallbackScope {
Isolate* isolate_; Isolate* isolate_;
Address callback_; Address callback_;
ExternalCallbackScope* previous_scope_; ExternalCallbackScope* previous_scope_;
VMState<EXTERNAL> vm_state_;
PauseNestedTimedHistogramScope pause_timed_histogram_scope_;
#ifdef USE_SIMULATOR #ifdef USE_SIMULATOR
Address scope_address_; Address scope_address_;
#endif #endif
......
...@@ -3767,7 +3767,7 @@ void Heap::FinalizeIncrementalMarkingIncrementally( ...@@ -3767,7 +3767,7 @@ void Heap::FinalizeIncrementalMarkingIncrementally(
DevToolsTraceEventScope devtools_trace_event_scope( DevToolsTraceEventScope devtools_trace_event_scope(
this, "MajorGC", "incremental finalization step"); this, "MajorGC", "incremental finalization step");
NestedTimedHistogramScope incremental_marking_scope( HistogramTimerScope incremental_marking_scope(
isolate()->counters()->gc_incremental_marking_finalize()); isolate()->counters()->gc_incremental_marking_finalize());
TRACE_EVENT1("v8", "V8.GCIncrementalMarkingFinalize", "epoch", epoch_full()); TRACE_EVENT1("v8", "V8.GCIncrementalMarkingFinalize", "epoch", epoch_full());
TRACE_GC_EPOCH(tracer(), GCTracer::Scope::MC_INCREMENTAL_FINALIZE, TRACE_GC_EPOCH(tracer(), GCTracer::Scope::MC_INCREMENTAL_FINALIZE,
...@@ -4001,7 +4001,7 @@ bool Heap::IdleNotification(double deadline_in_seconds) { ...@@ -4001,7 +4001,7 @@ bool Heap::IdleNotification(double deadline_in_seconds) {
double deadline_in_ms = double deadline_in_ms =
deadline_in_seconds * deadline_in_seconds *
static_cast<double>(base::Time::kMillisecondsPerSecond); static_cast<double>(base::Time::kMillisecondsPerSecond);
NestedTimedHistogramScope idle_notification_scope( HistogramTimerScope idle_notification_scope(
isolate_->counters()->gc_idle_notification()); isolate_->counters()->gc_idle_notification());
TRACE_EVENT0("v8", "V8.GCIdleNotification"); TRACE_EVENT0("v8", "V8.GCIdleNotification");
double start_ms = MonotonicallyIncreasingTimeInMs(); double start_ms = MonotonicallyIncreasingTimeInMs();
......
...@@ -194,7 +194,7 @@ void IncrementalMarking::Start(GarbageCollectionReason gc_reason) { ...@@ -194,7 +194,7 @@ void IncrementalMarking::Start(GarbageCollectionReason gc_reason) {
counters->incremental_marking_reason()->AddSample( counters->incremental_marking_reason()->AddSample(
static_cast<int>(gc_reason)); static_cast<int>(gc_reason));
NestedTimedHistogramScope incremental_marking_scope( HistogramTimerScope incremental_marking_scope(
counters->gc_incremental_marking_start()); counters->gc_incremental_marking_start());
TRACE_EVENT1("v8", "V8.GCIncrementalMarkingStart", "epoch", TRACE_EVENT1("v8", "V8.GCIncrementalMarkingStart", "epoch",
heap_->epoch_full()); heap_->epoch_full());
...@@ -784,7 +784,7 @@ StepResult CombineStepResults(StepResult a, StepResult b) { ...@@ -784,7 +784,7 @@ StepResult CombineStepResults(StepResult a, StepResult b) {
StepResult IncrementalMarking::AdvanceWithDeadline( StepResult IncrementalMarking::AdvanceWithDeadline(
double deadline_in_ms, CompletionAction completion_action, double deadline_in_ms, CompletionAction completion_action,
StepOrigin step_origin) { StepOrigin step_origin) {
NestedTimedHistogramScope incremental_marking_scope( HistogramTimerScope incremental_marking_scope(
heap_->isolate()->counters()->gc_incremental_marking()); heap_->isolate()->counters()->gc_incremental_marking());
TRACE_EVENT1("v8", "V8.GCIncrementalMarking", "epoch", heap_->epoch_full()); TRACE_EVENT1("v8", "V8.GCIncrementalMarking", "epoch", heap_->epoch_full());
TRACE_GC_EPOCH(heap_->tracer(), GCTracer::Scope::MC_INCREMENTAL, TRACE_GC_EPOCH(heap_->tracer(), GCTracer::Scope::MC_INCREMENTAL,
...@@ -889,7 +889,7 @@ void IncrementalMarking::AdvanceOnAllocation() { ...@@ -889,7 +889,7 @@ void IncrementalMarking::AdvanceOnAllocation() {
state_ != MARKING || heap_->always_allocate()) { state_ != MARKING || heap_->always_allocate()) {
return; return;
} }
NestedTimedHistogramScope incremental_marking_scope( HistogramTimerScope incremental_marking_scope(
heap_->isolate()->counters()->gc_incremental_marking()); heap_->isolate()->counters()->gc_incremental_marking());
TRACE_EVENT0("v8", "V8.GCIncrementalMarking"); TRACE_EVENT0("v8", "V8.GCIncrementalMarking");
TRACE_GC_EPOCH(heap_->tracer(), GCTracer::Scope::MC_INCREMENTAL, TRACE_GC_EPOCH(heap_->tracer(), GCTracer::Scope::MC_INCREMENTAL,
......
...@@ -14,7 +14,6 @@ ...@@ -14,7 +14,6 @@
#include "src/heap/heap-inl.h" #include "src/heap/heap-inl.h"
#include "src/heap/heap.h" #include "src/heap/heap.h"
#include "src/heap/local-heap.h" #include "src/heap/local-heap.h"
#include "src/logging/counters-scopes.h"
namespace v8 { namespace v8 {
namespace internal { namespace internal {
......
...@@ -102,35 +102,35 @@ namespace internal { ...@@ -102,35 +102,35 @@ namespace internal {
/* The maximum of 100M backtracks takes roughly 2 seconds on my machine. */ \ /* The maximum of 100M backtracks takes roughly 2 seconds on my machine. */ \
HR(regexp_backtracks, V8.RegExpBacktracks, 1, 100000000, 50) HR(regexp_backtracks, V8.RegExpBacktracks, 1, 100000000, 50)
#define NESTED_TIMED_HISTOGRAM_LIST(HT) \ #define HISTOGRAM_TIMER_LIST(HT) \
/* Timer histograms, not thread safe: HT(name, caption, max, unit) */ \ /* Timer histograms, not thread safe: HT(name, caption, max, unit) */ \
/* Garbage collection timers. */ \ /* Garbage collection timers. */ \
HT(gc_idle_notification, V8.GCIdleNotification, 10000, MILLISECOND) \ HT(gc_idle_notification, V8.GCIdleNotification, 10000, MILLISECOND) \
HT(gc_incremental_marking, V8.GCIncrementalMarking, 10000, MILLISECOND) \ HT(gc_incremental_marking, V8.GCIncrementalMarking, 10000, MILLISECOND) \
HT(gc_incremental_marking_start, V8.GCIncrementalMarkingStart, 10000, \ HT(gc_incremental_marking_start, V8.GCIncrementalMarkingStart, 10000, \
MILLISECOND) \ MILLISECOND) \
HT(gc_incremental_marking_finalize, V8.GCIncrementalMarkingFinalize, 10000, \ HT(gc_incremental_marking_finalize, V8.GCIncrementalMarkingFinalize, 10000, \
MILLISECOND) \ MILLISECOND) \
HT(gc_low_memory_notification, V8.GCLowMemoryNotification, 10000, \ HT(gc_low_memory_notification, V8.GCLowMemoryNotification, 10000, \
MILLISECOND) \ MILLISECOND) \
/* Compilation times. */ \ /* Compilation times. */ \
HT(collect_source_positions, V8.CollectSourcePositions, 1000000, \ HT(collect_source_positions, V8.CollectSourcePositions, 1000000, \
MICROSECOND) \ MICROSECOND) \
HT(compile, V8.CompileMicroSeconds, 1000000, MICROSECOND) \ HT(compile, V8.CompileMicroSeconds, 1000000, MICROSECOND) \
HT(compile_eval, V8.CompileEvalMicroSeconds, 1000000, MICROSECOND) \ HT(compile_eval, V8.CompileEvalMicroSeconds, 1000000, MICROSECOND) \
/* Serialization as part of compilation (code caching) */ \ /* Serialization as part of compilation (code caching) */ \
HT(compile_serialize, V8.CompileSerializeMicroSeconds, 100000, MICROSECOND) \ HT(compile_serialize, V8.CompileSerializeMicroSeconds, 100000, MICROSECOND) \
HT(compile_deserialize, V8.CompileDeserializeMicroSeconds, 1000000, \ HT(compile_deserialize, V8.CompileDeserializeMicroSeconds, 1000000, \
MICROSECOND) \ MICROSECOND) \
/* Total compilation time incl. caching/parsing */ \ /* Total compilation time incl. caching/parsing */ \
HT(compile_script, V8.CompileScriptMicroSeconds, 1000000, MICROSECOND) \ HT(compile_script, V8.CompileScriptMicroSeconds, 1000000, MICROSECOND) \
/* Time for lazily compiling Wasm functions. */ \ /* Time for lazily compiling Wasm functions. */ \
HT(wasm_lazy_compile_time, V8.WasmLazyCompileTimeMicroSeconds, 100000000, \ HT(wasm_lazy_compile_time, V8.WasmLazyCompileTimeMicroSeconds, 100000000, \
MICROSECOND) MICROSECOND)
#define NESTED_TIMED_HISTOGRAM_LIST_SLOW(HT) \ #define HISTOGRAM_TIMER_LIST_SLOW(HT) \
/* Total V8 time (including JS and runtime calls, exluding callbacks) */ \ /* Total JavaScript execution time (including callbacks and runtime calls */ \
HT(execute_precise, V8.ExecuteMicroSeconds, 1000000, MICROSECOND) HT(execute, V8.Execute, 1000000, MICROSECOND)
#define TIMED_HISTOGRAM_LIST(HT) \ #define TIMED_HISTOGRAM_LIST(HT) \
/* Timer histograms, thread safe: HT(name, caption, max, unit) */ \ /* Timer histograms, thread safe: HT(name, caption, max, unit) */ \
......
// 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(), Logger::START, true);
}
void LogEnd(Isolate* isolate) {
Logger::CallEventLogger(isolate, histogram_->name(), Logger::END, 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<NestedTimedHistogram*>(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_
...@@ -77,27 +77,37 @@ void* Histogram::CreateHistogram() const { ...@@ -77,27 +77,37 @@ void* Histogram::CreateHistogram() const {
return counters_->CreateHistogram(name_, min_, max_, num_buckets_); 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) { void TimedHistogram::AddTimedSample(base::TimeDelta sample) {
if (Enabled()) { if (Enabled()) {
int64_t sample_int = resolution_ == TimedHistogramResolution::MICROSECOND int64_t sample_int = resolution_ == HistogramTimerResolution::MICROSECOND
? sample.InMicroseconds() ? sample.InMicroseconds()
: sample.InMilliseconds(); : sample.InMilliseconds();
AddSample(static_cast<int>(sample_int)); AddSample(static_cast<int>(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, void TimedHistogram::RecordAbandon(base::ElapsedTimer* timer,
Isolate* isolate) { Isolate* isolate) {
if (Enabled()) { if (Enabled()) {
DCHECK(timer->IsStarted()); DCHECK(timer->IsStarted());
timer->Stop(); timer->Stop();
int64_t sample = resolution_ == TimedHistogramResolution::MICROSECOND int64_t sample = resolution_ == HistogramTimerResolution::MICROSECOND
? base::TimeDelta::Max().InMicroseconds() ? base::TimeDelta::Max().InMicroseconds()
: base::TimeDelta::Max().InMilliseconds(); : base::TimeDelta::Max().InMilliseconds();
AddSample(static_cast<int>(sample)); AddSample(static_cast<int>(sample));
...@@ -107,18 +117,6 @@ void TimedHistogram::RecordAbandon(base::ElapsedTimer* timer, ...@@ -107,18 +117,6 @@ void TimedHistogram::RecordAbandon(base::ElapsedTimer* timer,
} }
} }
#ifdef DEBUG
bool TimedHistogram::ToggleRunningState(bool expect_to_run) const {
static thread_local base::LazyInstance<
std::unordered_map<const TimedHistogram*, bool>>::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) Counters::Counters(Isolate* isolate)
: :
#define SC(name, caption) name##_(this, "c:" #caption), #define SC(name, caption) name##_(this, "c:" #caption),
...@@ -151,30 +149,29 @@ Counters::Counters(Isolate* isolate) ...@@ -151,30 +149,29 @@ Counters::Counters(Isolate* isolate)
const int DefaultTimedHistogramNumBuckets = 50; const int DefaultTimedHistogramNumBuckets = 50;
static const struct { static const struct {
NestedTimedHistogram Counters::*member; HistogramTimer Counters::*member;
const char* caption; const char* caption;
int max; int max;
TimedHistogramResolution res; HistogramTimerResolution res;
} kNestedTimedHistograms[] = { } kHistogramTimers[] = {
#define HT(name, caption, max, res) \ #define HT(name, caption, max, res) \
{&Counters::name##_, #caption, max, TimedHistogramResolution::res}, {&Counters::name##_, #caption, max, HistogramTimerResolution::res},
NESTED_TIMED_HISTOGRAM_LIST(HT) NESTED_TIMED_HISTOGRAM_LIST_SLOW(HT) HISTOGRAM_TIMER_LIST(HT) HISTOGRAM_TIMER_LIST_SLOW(HT)
#undef HT #undef HT
}; };
for (const auto& timer : kNestedTimedHistograms) { for (const auto& timer : kHistogramTimers) {
this->*timer.member = this->*timer.member = HistogramTimer(timer.caption, 0, timer.max, timer.res,
NestedTimedHistogram(timer.caption, 0, timer.max, timer.res, DefaultTimedHistogramNumBuckets, this);
DefaultTimedHistogramNumBuckets, this);
} }
static const struct { static const struct {
TimedHistogram Counters::*member; TimedHistogram Counters::*member;
const char* caption; const char* caption;
int max; int max;
TimedHistogramResolution res; HistogramTimerResolution res;
} kTimedHistograms[] = { } kTimedHistograms[] = {
#define HT(name, caption, max, res) \ #define HT(name, caption, max, res) \
{&Counters::name##_, #caption, max, TimedHistogramResolution::res}, {&Counters::name##_, #caption, max, HistogramTimerResolution::res},
TIMED_HISTOGRAM_LIST(HT) TIMED_HISTOGRAM_LIST(HT)
#undef HT #undef HT
}; };
...@@ -300,11 +297,11 @@ void Counters::ResetCreateHistogramFunction(CreateHistogramCallback f) { ...@@ -300,11 +297,11 @@ void Counters::ResetCreateHistogramFunction(CreateHistogramCallback f) {
#undef HR #undef HR
#define HT(name, caption, max, res) name##_.Reset(); #define HT(name, caption, max, res) name##_.Reset();
NESTED_TIMED_HISTOGRAM_LIST(HT) HISTOGRAM_TIMER_LIST(HT)
#undef HT #undef HT
#define HT(name, caption, max, res) name##_.Reset(FLAG_slow_histograms); #define HT(name, caption, max, res) name##_.Reset(FLAG_slow_histograms);
NESTED_TIMED_HISTOGRAM_LIST_SLOW(HT) HISTOGRAM_TIMER_LIST_SLOW(HT)
#undef HT #undef HT
#define HT(name, caption, max, res) name##_.Reset(); #define HT(name, caption, max, res) name##_.Reset();
......
This diff is collapsed.
...@@ -28,6 +28,16 @@ CodeEventListener::LogEventsAndTags Logger::ToNativeByScript( ...@@ -28,6 +28,16 @@ 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 <class TimerEvent> template <class TimerEvent>
void TimerEventScope<TimerEvent>::LogTimerEvent(Logger::StartEnd se) { void TimerEventScope<TimerEvent>::LogTimerEvent(Logger::StartEnd se) {
......
...@@ -12,7 +12,6 @@ ...@@ -12,7 +12,6 @@
#include "include/v8-profiler.h" #include "include/v8-profiler.h"
#include "src/base/platform/elapsed-timer.h" #include "src/base/platform/elapsed-timer.h"
#include "src/execution/isolate.h"
#include "src/logging/code-events.h" #include "src/logging/code-events.h"
#include "src/objects/objects.h" #include "src/objects/objects.h"
...@@ -274,15 +273,8 @@ class Logger : public CodeEventListener { ...@@ -274,15 +273,8 @@ class Logger : public CodeEventListener {
static void DefaultEventLoggerSentinel(const char* name, int event) {} static void DefaultEventLoggerSentinel(const char* name, int event) {}
static void CallEventLogger(Isolate* isolate, const char* name, StartEnd se, V8_INLINE static void CallEventLogger(Isolate* isolate, const char* name,
bool expose_to_api) { StartEnd 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, se);
}
}
V8_EXPORT_PRIVATE bool is_logging(); V8_EXPORT_PRIVATE bool is_logging();
......
...@@ -516,6 +516,8 @@ void MaybeProcessSourceRanges(ParseInfo* parse_info, Expression* root, ...@@ -516,6 +516,8 @@ void MaybeProcessSourceRanges(ParseInfo* parse_info, Expression* root,
void Parser::ParseProgram(Isolate* isolate, Handle<Script> script, void Parser::ParseProgram(Isolate* isolate, Handle<Script> script,
ParseInfo* info, ParseInfo* info,
MaybeHandle<ScopeInfo> maybe_outer_scope_info) { MaybeHandle<ScopeInfo> maybe_outer_scope_info) {
// TODO(bmeurer): We temporarily need to pass allow_nesting = true here,
// see comment for HistogramTimerScope class.
DCHECK_EQ(script->id(), flags().script_id()); DCHECK_EQ(script->id(), flags().script_id());
// It's OK to use the Isolate & counters here, since this function is only // It's OK to use the Isolate & counters here, since this function is only
......
...@@ -14,7 +14,7 @@ ...@@ -14,7 +14,7 @@
#include "src/heap/heap-inl.h" #include "src/heap/heap-inl.h"
#include "src/heap/local-factory-inl.h" #include "src/heap/local-factory-inl.h"
#include "src/heap/parked-scope.h" #include "src/heap/parked-scope.h"
#include "src/logging/counters-scopes.h" #include "src/logging/counters.h"
#include "src/logging/log.h" #include "src/logging/log.h"
#include "src/logging/runtime-call-stats-scope.h" #include "src/logging/runtime-call-stats-scope.h"
#include "src/objects/objects-inl.h" #include "src/objects/objects-inl.h"
...@@ -48,8 +48,7 @@ ScriptCompiler::CachedData* CodeSerializer::Serialize( ...@@ -48,8 +48,7 @@ ScriptCompiler::CachedData* CodeSerializer::Serialize(
Handle<SharedFunctionInfo> info) { Handle<SharedFunctionInfo> info) {
Isolate* isolate = info->GetIsolate(); Isolate* isolate = info->GetIsolate();
TRACE_EVENT_CALL_STATS_SCOPED(isolate, "v8", "V8.Execute"); TRACE_EVENT_CALL_STATS_SCOPED(isolate, "v8", "V8.Execute");
NestedTimedHistogramScope histogram_timer( HistogramTimerScope histogram_timer(isolate->counters()->compile_serialize());
isolate->counters()->compile_serialize());
RCS_SCOPE(isolate, RuntimeCallCounterId::kCompileSerialize); RCS_SCOPE(isolate, RuntimeCallCounterId::kCompileSerialize);
TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("v8.compile"), "V8.CompileSerialize"); TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("v8.compile"), "V8.CompileSerialize");
......
...@@ -11,7 +11,7 @@ ...@@ -11,7 +11,7 @@
#include "src/codegen/optimized-compilation-info.h" #include "src/codegen/optimized-compilation-info.h"
#include "src/compiler/wasm-compiler.h" #include "src/compiler/wasm-compiler.h"
#include "src/diagnostics/code-tracer.h" #include "src/diagnostics/code-tracer.h"
#include "src/logging/counters-scopes.h" #include "src/logging/counters.h"
#include "src/logging/log.h" #include "src/logging/log.h"
#include "src/utils/ostreams.h" #include "src/utils/ostreams.h"
#include "src/wasm/baseline/liftoff-compiler.h" #include "src/wasm/baseline/liftoff-compiler.h"
......
...@@ -17,7 +17,7 @@ ...@@ -17,7 +17,7 @@
#include "src/base/utils/random-number-generator.h" #include "src/base/utils/random-number-generator.h"
#include "src/compiler/wasm-compiler.h" #include "src/compiler/wasm-compiler.h"
#include "src/heap/heap-inl.h" // For CodeSpaceMemoryModificationScope. #include "src/heap/heap-inl.h" // For CodeSpaceMemoryModificationScope.
#include "src/logging/counters-scopes.h" #include "src/logging/counters.h"
#include "src/logging/metrics.h" #include "src/logging/metrics.h"
#include "src/objects/property-descriptor.h" #include "src/objects/property-descriptor.h"
#include "src/tasks/task-utils.h" #include "src/tasks/task-utils.h"
......
...@@ -7,7 +7,7 @@ ...@@ -7,7 +7,7 @@
#include "src/api/api.h" #include "src/api/api.h"
#include "src/asmjs/asm-js.h" #include "src/asmjs/asm-js.h"
#include "src/base/platform/wrappers.h" #include "src/base/platform/wrappers.h"
#include "src/logging/counters-scopes.h" #include "src/logging/counters.h"
#include "src/logging/metrics.h" #include "src/logging/metrics.h"
#include "src/numbers/conversions-inl.h" #include "src/numbers/conversions-inl.h"
#include "src/objects/descriptor-array-inl.h" #include "src/objects/descriptor-array-inl.h"
......
...@@ -22622,68 +22622,25 @@ TEST(ChainSignatureCheck) { ...@@ -22622,68 +22622,25 @@ TEST(ChainSignatureCheck) {
static const char* last_event_message; static const char* last_event_message;
// See Logger::StartEnd
static int last_event_status; static int last_event_status;
static int event_count = 0;
void StoringEventLoggerCallback(const char* message, int status) { void StoringEventLoggerCallback(const char* message, int status) {
last_event_message = message; last_event_message = message;
last_event_status = status; last_event_status = status;
event_count++;
} }
TEST(EventLogging) { TEST(EventLogging) {
v8::Isolate* isolate = CcTest::isolate(); v8::Isolate* isolate = CcTest::isolate();
isolate->SetEventLogger(StoringEventLoggerCallback); isolate->SetEventLogger(StoringEventLoggerCallback);
v8::internal::NestedTimedHistogram histogram( v8::internal::HistogramTimer histogramTimer(
"V8.Test", 0, 10000, v8::internal::TimedHistogramResolution::MILLISECOND, "V8.Test", 0, 10000, v8::internal::HistogramTimerResolution::MILLISECOND,
50, reinterpret_cast<v8::internal::Isolate*>(isolate)->counters()); 50, reinterpret_cast<v8::internal::Isolate*>(isolate)->counters());
event_count = 0; histogramTimer.Start();
int count = 0; CHECK_EQ(0, strcmp("V8.Test", last_event_message));
{ CHECK_EQ(0, last_event_status);
CHECK_EQ(0, event_count); histogramTimer.Stop();
v8::internal::NestedTimedHistogramScope scope1(&histogram);
CHECK_EQ(0, strcmp("V8.Test", last_event_message));
CHECK_EQ(0, last_event_status);
CHECK_EQ(++count, event_count);
{
CHECK_EQ(count, event_count);
v8::internal::NestedTimedHistogramScope scope2(&histogram);
CHECK_EQ(0, strcmp("V8.Test", last_event_message));
CHECK_EQ(0, last_event_status);
CHECK_EQ(++count, event_count);
{
CHECK_EQ(count, event_count);
v8::internal::NestedTimedHistogramScope scope3(&histogram);
CHECK_EQ(++count, event_count);
v8::internal::PauseNestedTimedHistogramScope scope4(&histogram);
// The outer timer scope is just paused, no event is emited yet.
CHECK_EQ(count, event_count);
{
CHECK_EQ(count, event_count);
v8::internal::NestedTimedHistogramScope scope5(&histogram);
CHECK_EQ(0, strcmp("V8.Test", last_event_message));
CHECK_EQ(0, last_event_status);
CHECK_EQ(++count, event_count);
}
CHECK_EQ(0, strcmp("V8.Test", last_event_message));
CHECK_EQ(1, last_event_status);
CHECK_EQ(++count, event_count);
}
CHECK_EQ(0, strcmp("V8.Test", last_event_message));
CHECK_EQ(1, last_event_status);
CHECK_EQ(++count, event_count);
v8::internal::PauseNestedTimedHistogramScope scope6(&histogram);
// The outer timer scope is just paused, no event is emited yet.
CHECK_EQ(count, event_count);
}
CHECK_EQ(0, strcmp("V8.Test", last_event_message));
CHECK_EQ(1, last_event_status);
CHECK_EQ(++count, event_count);
}
CHECK_EQ(0, strcmp("V8.Test", last_event_message)); CHECK_EQ(0, strcmp("V8.Test", last_event_message));
CHECK_EQ(1, last_event_status); CHECK_EQ(1, last_event_status);
CHECK_EQ(++count, event_count);
} }
TEST(PropertyDescriptor) { TEST(PropertyDescriptor) {
...@@ -379,108 +379,6 @@ TEST(TimeTicks, IsMonotonic) { ...@@ -379,108 +379,6 @@ TEST(TimeTicks, IsMonotonic) {
} }
} }
namespace {
void Sleep(TimeDelta wait_time) {
ElapsedTimer waiter;
waiter.Start();
while (!waiter.HasExpired(wait_time)) {
OS::Sleep(TimeDelta::FromMilliseconds(1));
}
}
} // namespace
TEST(ElapsedTimer, StartStop) {
TimeDelta wait_time = TimeDelta::FromMilliseconds(100);
TimeDelta noise = TimeDelta::FromMilliseconds(100);
ElapsedTimer timer;
DCHECK(!timer.IsStarted());
timer.Start();
DCHECK(timer.IsStarted());
Sleep(wait_time);
TimeDelta delta = timer.Elapsed();
DCHECK(timer.IsStarted());
EXPECT_GE(delta, wait_time);
EXPECT_LT(delta, wait_time + noise);
timer.Pause();
DCHECK(timer.IsStarted());
Sleep(wait_time);
timer.Resume();
DCHECK(timer.IsStarted());
delta = timer.Elapsed();
timer.Pause();
DCHECK(timer.IsStarted());
EXPECT_GE(delta, wait_time);
EXPECT_LT(delta, wait_time + noise);
Sleep(wait_time);
timer.Resume();
DCHECK(timer.IsStarted());
delta = timer.Elapsed();
EXPECT_GE(delta, wait_time);
EXPECT_LT(delta, wait_time + noise);
timer.Stop();
DCHECK(!timer.IsStarted());
}
TEST(ElapsedTimer, StartStopArgs) {
TimeDelta wait_time = TimeDelta::FromMilliseconds(100);
ElapsedTimer timer1;
ElapsedTimer timer2;
DCHECK(!timer1.IsStarted());
DCHECK(!timer2.IsStarted());
TimeTicks now = TimeTicks::HighResolutionNow();
timer1.Start(now);
timer2.Start(now);
DCHECK(timer1.IsStarted());
DCHECK(timer2.IsStarted());
Sleep(wait_time);
now = TimeTicks::HighResolutionNow();
TimeDelta delta1 = timer1.Elapsed(now);
Sleep(wait_time);
TimeDelta delta2 = timer2.Elapsed(now);
DCHECK(timer1.IsStarted());
DCHECK(timer2.IsStarted());
EXPECT_GE(delta1, delta2);
Sleep(wait_time);
EXPECT_NE(delta1, timer2.Elapsed());
TimeTicks now2 = TimeTicks::HighResolutionNow();
EXPECT_NE(timer1.Elapsed(now), timer1.Elapsed(now2));
EXPECT_NE(delta1, timer1.Elapsed(now2));
EXPECT_NE(delta2, timer2.Elapsed(now2));
EXPECT_GE(timer1.Elapsed(now2), timer2.Elapsed(now2));
now = TimeTicks::HighResolutionNow();
timer1.Pause(now);
timer2.Pause(now);
DCHECK(timer1.IsStarted());
DCHECK(timer2.IsStarted());
Sleep(wait_time);
now = TimeTicks::HighResolutionNow();
timer1.Resume(now);
Sleep(wait_time);
timer2.Resume(now);
DCHECK(timer1.IsStarted());
DCHECK(timer2.IsStarted());
delta1 = timer1.Elapsed(now);
Sleep(wait_time);
delta2 = timer2.Elapsed(now);
EXPECT_GE(delta1, delta2);
timer1.Stop();
timer2.Stop();
DCHECK(!timer1.IsStarted());
DCHECK(!timer2.IsStarted());
}
#if V8_OS_ANDROID #if V8_OS_ANDROID
#define MAYBE_ThreadNow DISABLED_ThreadNow #define MAYBE_ThreadNow DISABLED_ThreadNow
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment