AuroraMiddleware/v8
1
0
Fork 0
Code Issues 2 Pull Requests Releases Wiki Activity

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

Browse Source 
This is a reland of fffcbaea55

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<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: Ic2eef7456fbc245febcf780b23418f6ab0bebdb7
Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/3080566
Commit-Queue: Camillo Bruni <cbruni@chromium.org>
Reviewed-by: Leszek Swirski <leszeks@chromium.org>
Reviewed-by: Victor Gomes <victorgomes@chromium.org>
Reviewed-by: Thibaud Michaud <thibaudm@chromium.org>
Reviewed-by: Omer Katz <omerkatz@chromium.org>
Cr-Commit-Position: refs/heads/master@{#76180}
This commit is contained in:
Camillo Bruni 2021-08-09 16:30:16 +02:00 committed by V8 LUCI CQ
parent 688b3b2163
commit f688fe086f
27 changed files with 634 additions and 336 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

1
BUILD.bazel
View File

@ -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",

1
BUILD.gn
View File

@ -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",

4
include/v8.h
View File

@ -7266,7 +7266,9 @@ using MessageCallback = void (*)(Local<Message> message, Local<Value> 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

3
src/api/api-arguments-inl.h
View File

@ -76,7 +76,6 @@ inline JSReceiver FunctionCallbackArguments::holder() {
CALLBACK_INFO, RECEIVER, Debug::k##ACCESSOR_KIND)) { \
return RETURN_VALUE(); \
} \
VMState<EXTERNAL> state(ISOLATE); \
ExternalCallbackScope call_scope(ISOLATE, FUNCTION_ADDR(F)); \
PropertyCallbackInfo<API_RETURN_TYPE> callback_info(values_);
@ -85,7 +84,6 @@ inline JSReceiver FunctionCallbackArguments::holder() {
if (ISOLATE->debug_execution_mode() == DebugInfo::kSideEffects) { \
return RETURN_VALUE(); \
} \
VMState<EXTERNAL> state(ISOLATE); \
ExternalCallbackScope call_scope(ISOLATE, FUNCTION_ADDR(F)); \
PropertyCallbackInfo<API_RETURN_TYPE> callback_info(values_);
@ -149,7 +147,6 @@ Handle<Object> FunctionCallbackArguments::Call(CallHandlerInfo handler) {
Debug::kNotAccessor)) {
return Handle<Object>();
}
VMState<EXTERNAL> state(isolate);
ExternalCallbackScope call_scope(isolate, FUNCTION_ADDR(f));
FunctionCallbackInfo<v8::Value> info(values_, argv_, argc_);
f(info);

24
src/api/api.cc
View File

@ -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<Value> Script::Run(Local<Context> context) {
TRACE_EVENT_CALL_STATS_SCOPED(isolate, "v8", "V8.Execute");
ENTER_V8(isolate, context, Script, Run, MaybeLocal<Value>(),
InternalEscapableScope);
i::HistogramTimerScope execute_timer(isolate->counters()->execute(), true);
i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
i::NestedTimedHistogramScope execute_timer(
isolate->counters()->execute_precise());
i::AggregatingHistogramTimerScope histogram_timer(
isolate->counters()->compile_lazy());
i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
auto fun = i::Handle<i::JSFunction>::cast(Utils::OpenHandle(this));
// TODO(crbug.com/1193459): remove once ablation study is completed
@ -2298,9 +2299,10 @@ MaybeLocal<Value> Module::Evaluate(Local<Context> context) {
TRACE_EVENT_CALL_STATS_SCOPED(isolate, "v8", "V8.Execute");
ENTER_V8(isolate, context, Module, Evaluate, MaybeLocal<Value>(),
InternalEscapableScope);
i::HistogramTimerScope execute_timer(isolate->counters()->execute(), true);
i::AggregatingHistogramTimerScope timer(isolate->counters()->compile_lazy());
i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
i::NestedTimedHistogramScope execute_timer(
isolate->counters()->execute_precise());
i::AggregatingHistogramTimerScope timer(isolate->counters()->compile_lazy());
i::Handle<i::Module> self = Utils::OpenHandle(this);
Utils::ApiCheck(self->status() >= i::Module::kLinked, "Module::Evaluate",
@ -4994,6 +4996,8 @@ MaybeLocal<Value> Object::CallAsFunction(Local<Context> context,
ENTER_V8(isolate, context, Object, CallAsFunction, MaybeLocal<Value>(),
InternalEscapableScope);
i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
i::NestedTimedHistogramScope execute_timer(
isolate->counters()->execute_precise());
auto self = Utils::OpenHandle(this);
auto recv_obj = Utils::OpenHandle(*recv);
STATIC_ASSERT(sizeof(v8::Local<v8::Value>) == sizeof(i::Handle<i::Object>));
@ -5012,6 +5016,8 @@ MaybeLocal<Value> Object::CallAsConstructor(Local<Context> context, int argc,
ENTER_V8(isolate, context, Object, CallAsConstructor, MaybeLocal<Value>(),
InternalEscapableScope);
i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
i::NestedTimedHistogramScope execute_timer(
isolate->counters()->execute_precise());
auto self = Utils::OpenHandle(this);
STATIC_ASSERT(sizeof(v8::Local<v8::Value>) == sizeof(i::Handle<i::Object>));
i::Handle<i::Object>* args = reinterpret_cast<i::Handle<i::Object>*>(argv);
@ -5049,6 +5055,8 @@ MaybeLocal<Object> Function::NewInstanceWithSideEffectType(
ENTER_V8(isolate, context, Function, NewInstance, MaybeLocal<Object>(),
InternalEscapableScope);
i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
i::NestedTimedHistogramScope execute_timer(
isolate->counters()->execute_precise());
auto self = Utils::OpenHandle(this);
STATIC_ASSERT(sizeof(v8::Local<v8::Value>) == sizeof(i::Handle<i::Object>));
bool should_set_has_no_side_effect =
@ -5098,6 +5106,8 @@ MaybeLocal<v8::Value> Function::Call(Local<Context> context,
ENTER_V8(isolate, context, Function, Call, MaybeLocal<Value>(),
InternalEscapableScope);
i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
i::NestedTimedHistogramScope execute_timer(
isolate->counters()->execute_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<i::Isolate*>(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<Isolate*>(info.GetIsolate());
RCS_SCOPE(isolate, RuntimeCallCounterId::kAccessorGetterCallback);
Address getter_address = reinterpret_cast<Address>(getter);
VMState<EXTERNAL> state(isolate);
ExternalCallbackScope call_scope(isolate, getter_address);
getter(property, info);
}
@ -10284,7 +10293,6 @@ void InvokeFunctionCallback(const v8::FunctionCallbackInfo<v8::Value>& info,
Isolate* isolate = reinterpret_cast<Isolate*>(info.GetIsolate());
RCS_SCOPE(isolate, RuntimeCallCounterId::kFunctionCallback);
Address callback_address = reinterpret_cast<Address>(callback);
VMState<EXTERNAL> state(isolate);
ExternalCallbackScope call_scope(isolate, callback_address);
callback(info);
}

93
src/base/platform/elapsed-timer.h
View File

@ -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
};

8
src/builtins/builtins-console.cc
View File

@ -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<char[]> 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();

31
src/codegen/compiler.cc
View File

@ -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<SharedFunctionInfo> 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<JSFunction> Compiler::GetFunctionFromEval(
// (via v8::Isolate::SetAllowCodeGenerationFromStringsCallback)
bool CodeGenerationFromStringsAllowed(Isolate* isolate, Handle<Context> context,
Handle<String> 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<EXTERNAL> state(isolate);
RCS_SCOPE(isolate, RuntimeCallCounterId::kCodeGenerationFromStringsCallbacks);
AllowCodeGenerationFromStringsCallback 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));
}
@ -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<SharedFunctionInfo> 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<JSFunction> 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");

4
src/execution/vm-state-inl.h
View File

@ -54,7 +54,9 @@ VMState<Tag>::~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

3
src/execution/vm-state.h
View File

@ -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<EXTERNAL> vm_state_;
PauseNestedTimedHistogramScope pause_timed_histogram_scope_;
#ifdef USE_SIMULATOR
Address scope_address_;
#endif

4
src/heap/heap.cc
View File

@ -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<double>(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();

6
src/heap/incremental-marking.cc
View File

@ -194,7 +194,7 @@ void IncrementalMarking::Start(GarbageCollectionReason gc_reason) {
counters->incremental_marking_reason()->AddSample(
static_cast<int>(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,

1
src/heap/safepoint.cc
View File

@ -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 {

54
src/logging/counters-definitions.h
View File

@ -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) */ \

191
src/logging/counters-scopes.h Normal file
View File

@ -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<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_

65
src/logging/counters.cc
View File

@ -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<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,
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<int>(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<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)
:
#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();

231
src/logging/counters.h
View File

@ -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<Counters> 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<Counters> 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<Counters> {
#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<Counters> {
// 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<Counters> {
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<Counters> {
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<Counters> {
DISALLOW_IMPLICIT_CONSTRUCTORS(Counters);
};
void HistogramTimer::Start() {
TimedHistogram::Start(&timer_, counters()->isolate());
}
void HistogramTimer::Stop() {
TimedHistogram::Stop(&timer_, counters()->isolate());
}
} // namespace internal
} // namespace v8

13
src/logging/log-inl.h
View File

@ -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 <class TimerEvent>
void TimerEventScope<TimerEvent>::LogTimerEvent(Logger::StartEnd se) {
void TimerEventScope<TimerEvent>::LogTimerEvent(v8::LogEventStatus se) {
Logger::CallEventLogger(isolate_, TimerEvent::name(), se,
TimerEvent::expose_to_api());
}

10
src/logging/log.cc
View File

@ -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<TimerEvent##TimerName>::LogTimerEvent( \
Logger::StartEnd se);
v8::LogEventStatus se);
TIMER_EVENTS_LIST(V)
#undef V

22
src/logging/log.h
View File

@ -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<v8::LogEventStatus>(se));
}
}
V8_EXPORT_PRIVATE bool is_logging();
@ -399,13 +405,13 @@ template <class TimerEvent>
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_;
};

2
src/parsing/parser.cc
View File

@ -516,8 +516,6 @@ void MaybeProcessSourceRanges(ParseInfo* parse_info, Expression* root,
void Parser::ParseProgram(Isolate* isolate, Handle<Script> script,
ParseInfo* 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());
// It's OK to use the Isolate & counters here, since this function is only

5
src/snapshot/code-serializer.cc
View File

@ -17,7 +17,7 @@
#include "src/heap/heap-inl.h"
#include "src/heap/local-factory-inl.h"
#include "src/heap/parked-scope.h"
#include "src/logging/counters.h"
#include "src/logging/counters-scopes.h"
#include "src/logging/log.h"
#include "src/logging/runtime-call-stats-scope.h"
#include "src/objects/objects-inl.h"
@ -52,7 +52,8 @@ ScriptCompiler::CachedData* CodeSerializer::Serialize(
Handle<SharedFunctionInfo> info) {
Isolate* isolate = info->GetIsolate();
TRACE_EVENT_CALL_STATS_SCOPED(isolate, "v8", "V8.Execute");
HistogramTimerScope histogram_timer(isolate->counters()->compile_serialize());
NestedTimedHistogramScope histogram_timer(
isolate->counters()->compile_serialize());
RCS_SCOPE(isolate, RuntimeCallCounterId::kCompileSerialize);
TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("v8.compile"), "V8.CompileSerialize");

2
src/wasm/function-compiler.cc
View File

@ -11,7 +11,7 @@
#include "src/codegen/optimized-compilation-info.h"
#include "src/compiler/wasm-compiler.h"
#include "src/diagnostics/code-tracer.h"
#include "src/logging/counters.h"
#include "src/logging/counters-scopes.h"
#include "src/logging/log.h"
#include "src/utils/ostreams.h"
#include "src/wasm/baseline/liftoff-compiler.h"

2
src/wasm/module-compiler.cc
View File

@ -17,7 +17,7 @@
#include "src/base/utils/random-number-generator.h"
#include "src/compiler/wasm-compiler.h"
#include "src/heap/heap-inl.h" // For CodeSpaceMemoryModificationScope.
#include "src/logging/counters.h"
#include "src/logging/counters-scopes.h"
#include "src/logging/metrics.h"
#include "src/objects/property-descriptor.h"
#include "src/tasks/task-utils.h"

2
src/wasm/module-instantiate.cc
View File

@ -7,7 +7,7 @@
#include "src/api/api.h"
#include "src/asmjs/asm-js.h"
#include "src/base/platform/wrappers.h"
#include "src/logging/counters.h"
#include "src/logging/counters-scopes.h"
#include "src/logging/metrics.h"
#include "src/numbers/conversions-inl.h"
#include "src/objects/descriptor-array-inl.h"

79
test/cctest/test-api.cc
View File

@ -22622,25 +22622,86 @@ TEST(ChainSignatureCheck) {
static const char* last_event_message;
static int last_event_status;
// See v8::LogEventStatus
static v8::LogEventStatus last_event_status;
static int event_count = 0;
void StoringEventLoggerCallback(const char* message, int status) {
last_event_message = message;
last_event_status = status;
last_event_status = static_cast<v8::LogEventStatus>(status);
event_count++;
}
TEST(EventLogging) {
v8::Isolate* isolate = CcTest::isolate();
isolate->SetEventLogger(StoringEventLoggerCallback);
v8::internal::HistogramTimer histogramTimer(
"V8.Test", 0, 10000, v8::internal::HistogramTimerResolution::MILLISECOND,
v8::internal::NestedTimedHistogram histogram(
"V8.Test", 0, 10000, v8::internal::TimedHistogramResolution::MILLISECOND,
50, reinterpret_cast<v8::internal::Isolate*>(isolate)->counters());
histogramTimer.Start();
event_count = 0;
int count = 0;
{
CHECK_EQ(0, event_count);
{
CHECK_EQ(0, event_count);
v8::internal::NestedTimedHistogramScope scope0(&histogram);
CHECK_EQ(0, strcmp("V8.Test", last_event_message));
CHECK_EQ(v8::LogEventStatus::kStart, last_event_status);
CHECK_EQ(++count, event_count);
}
CHECK_EQ(v8::LogEventStatus::kEnd, last_event_status);
CHECK_EQ(++count, event_count);
v8::internal::NestedTimedHistogramScope scope1(&histogram);
CHECK_EQ(0, strcmp("V8.Test", last_event_message));
CHECK_EQ(v8::LogEventStatus::kStart, 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(v8::LogEventStatus::kStart, 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);
v8::internal::NestedTimedHistogramScope scope5_1(&histogram);
CHECK_EQ(0, strcmp("V8.Test", last_event_message));
CHECK_EQ(v8::LogEventStatus::kStart, last_event_status);
count++;
CHECK_EQ(++count, event_count);
}
CHECK_EQ(0, strcmp("V8.Test", last_event_message));
CHECK_EQ(v8::LogEventStatus::kEnd, last_event_status);
count++;
CHECK_EQ(++count, event_count);
}
CHECK_EQ(0, strcmp("V8.Test", last_event_message));
CHECK_EQ(v8::LogEventStatus::kEnd, 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);
{
v8::internal::PauseNestedTimedHistogramScope scope7(&histogram);
CHECK_EQ(count, event_count);
}
CHECK_EQ(count, event_count);
}
CHECK_EQ(0, strcmp("V8.Test", last_event_message));
CHECK_EQ(v8::LogEventStatus::kEnd, last_event_status);
CHECK_EQ(++count, event_count);
}
CHECK_EQ(0, strcmp("V8.Test", last_event_message));
CHECK_EQ(0, last_event_status);
histogramTimer.Stop();
CHECK_EQ(0, strcmp("V8.Test", last_event_message));
CHECK_EQ(1, last_event_status);
CHECK_EQ(v8::LogEventStatus::kEnd, last_event_status);
CHECK_EQ(++count, event_count);
}
TEST(PropertyDescriptor) {

109
test/unittests/base/platform/time-unittest.cc
View File

@ -379,6 +379,115 @@ 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);
DCHECK(!timer.IsPaused());
timer.Pause();
DCHECK(timer.IsPaused());
Sleep(wait_time);
timer.Resume();
DCHECK(timer.IsStarted());
delta = timer.Elapsed();
DCHECK(!timer.IsPaused());
timer.Pause();
DCHECK(timer.IsPaused());
EXPECT_GE(delta, wait_time);
EXPECT_LT(delta, wait_time + noise);
Sleep(wait_time);
timer.Resume();
DCHECK(!timer.IsPaused());
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.IsPaused());
DCHECK(timer2.IsPaused());
Sleep(wait_time);
now = TimeTicks::HighResolutionNow();
timer1.Resume(now);
DCHECK(!timer1.IsPaused());
DCHECK(timer2.IsPaused());
Sleep(wait_time);
timer2.Resume(now);
DCHECK(!timer1.IsPaused());
DCHECK(!timer2.IsPaused());
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
#define MAYBE_ThreadNow DISABLED_ThreadNow