Skip to content

Commit fffcbae

Browse files
camillobruniV8 LUCI CQ
camillobruni
authored and
V8 LUCI CQ
committed
[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}
1 parent 549eff7 commit fffcbae

24 files changed

Lines changed: 579 additions & 308 deletions

‎BUILD.bazel‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1411,6 +1411,7 @@ filegroup(
14111411
"src/logging/counters-definitions.h",
14121412
"src/logging/counters.cc",
14131413
"src/logging/counters.h",
1414+
"src/logging/counters-scopes.h",
14141415
"src/logging/local-logger.cc",
14151416
"src/logging/local-logger.h",
14161417
"src/logging/log-inl.h",

‎BUILD.gn‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -2829,6 +2829,7 @@ v8_header_set("v8_internal_headers") {
28292829
"src/libsampler/sampler.h",
28302830
"src/logging/code-events.h",
28312831
"src/logging/counters-definitions.h",
2832+
"src/logging/counters-scopes.h",
28322833
"src/logging/counters.h",
28332834
"src/logging/local-logger.h",
28342835
"src/logging/log-inl.h",

‎src/api/api-arguments-inl.h‎

Lines changed: 0 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -76,7 +76,6 @@ inline JSReceiver FunctionCallbackArguments::holder() {
7676
CALLBACK_INFO, RECEIVER, Debug::k##ACCESSOR_KIND)) { \
7777
return RETURN_VALUE(); \
7878
} \
79-
VMState<EXTERNAL> state(ISOLATE); \
8079
ExternalCallbackScope call_scope(ISOLATE, FUNCTION_ADDR(F)); \
8180
PropertyCallbackInfo<API_RETURN_TYPE> callback_info(values_);
8281

@@ -85,7 +84,6 @@ inline JSReceiver FunctionCallbackArguments::holder() {
8584
if (ISOLATE->debug_execution_mode() == DebugInfo::kSideEffects) { \
8685
return RETURN_VALUE(); \
8786
} \
88-
VMState<EXTERNAL> state(ISOLATE); \
8987
ExternalCallbackScope call_scope(ISOLATE, FUNCTION_ADDR(F)); \
9088
PropertyCallbackInfo<API_RETURN_TYPE> callback_info(values_);
9189

@@ -149,7 +147,6 @@ Handle<Object> FunctionCallbackArguments::Call(CallHandlerInfo handler) {
149147
Debug::kNotAccessor)) {
150148
return Handle<Object>();
151149
}
152-
VMState<EXTERNAL> state(isolate);
153150
ExternalCallbackScope call_scope(isolate, FUNCTION_ADDR(f));
154151
FunctionCallbackInfo<v8::Value> info(values_, argv_, argc_);
155152
f(info);

‎src/api/api.cc‎

Lines changed: 16 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -58,7 +58,7 @@
5858
#include "src/init/v8.h"
5959
#include "src/json/json-parser.h"
6060
#include "src/json/json-stringifier.h"
61-
#include "src/logging/counters.h"
61+
#include "src/logging/counters-scopes.h"
6262
#include "src/logging/metrics.h"
6363
#include "src/logging/runtime-call-stats-scope.h"
6464
#include "src/logging/tracing-flags.h"
@@ -1967,10 +1967,11 @@ MaybeLocal<Value> Script::Run(Local<Context> context) {
19671967
TRACE_EVENT_CALL_STATS_SCOPED(isolate, "v8", "V8.Execute");
19681968
ENTER_V8(isolate, context, Script, Run, MaybeLocal<Value>(),
19691969
InternalEscapableScope);
1970-
i::HistogramTimerScope execute_timer(isolate->counters()->execute(), true);
1970+
i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
1971+
i::NestedTimedHistogramScope execute_timer(
1972+
isolate->counters()->execute_precise());
19711973
i::AggregatingHistogramTimerScope histogram_timer(
19721974
isolate->counters()->compile_lazy());
1973-
i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
19741975
auto fun = i::Handle<i::JSFunction>::cast(Utils::OpenHandle(this));
19751976

19761977
// TODO(crbug.com/1193459): remove once ablation study is completed
@@ -2293,9 +2294,10 @@ MaybeLocal<Value> Module::Evaluate(Local<Context> context) {
22932294
TRACE_EVENT_CALL_STATS_SCOPED(isolate, "v8", "V8.Execute");
22942295
ENTER_V8(isolate, context, Module, Evaluate, MaybeLocal<Value>(),
22952296
InternalEscapableScope);
2296-
i::HistogramTimerScope execute_timer(isolate->counters()->execute(), true);
2297-
i::AggregatingHistogramTimerScope timer(isolate->counters()->compile_lazy());
22982297
i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
2298+
i::NestedTimedHistogramScope execute_timer(
2299+
isolate->counters()->execute_precise());
2300+
i::AggregatingHistogramTimerScope timer(isolate->counters()->compile_lazy());
22992301

23002302
i::Handle<i::Module> self = Utils::OpenHandle(this);
23012303
Utils::ApiCheck(self->status() >= i::Module::kInstantiated,
@@ -4950,6 +4952,8 @@ MaybeLocal<Value> Object::CallAsFunction(Local<Context> context,
49504952
ENTER_V8(isolate, context, Object, CallAsFunction, MaybeLocal<Value>(),
49514953
InternalEscapableScope);
49524954
i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
4955+
i::NestedTimedHistogramScope execute_timer(
4956+
isolate->counters()->execute_precise());
49534957
auto self = Utils::OpenHandle(this);
49544958
auto recv_obj = Utils::OpenHandle(*recv);
49554959
STATIC_ASSERT(sizeof(v8::Local<v8::Value>) == sizeof(i::Handle<i::Object>));
@@ -4968,6 +4972,8 @@ MaybeLocal<Value> Object::CallAsConstructor(Local<Context> context, int argc,
49684972
ENTER_V8(isolate, context, Object, CallAsConstructor, MaybeLocal<Value>(),
49694973
InternalEscapableScope);
49704974
i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
4975+
i::NestedTimedHistogramScope execute_timer(
4976+
isolate->counters()->execute_precise());
49714977
auto self = Utils::OpenHandle(this);
49724978
STATIC_ASSERT(sizeof(v8::Local<v8::Value>) == sizeof(i::Handle<i::Object>));
49734979
i::Handle<i::Object>* args = reinterpret_cast<i::Handle<i::Object>*>(argv);
@@ -5005,6 +5011,8 @@ MaybeLocal<Object> Function::NewInstanceWithSideEffectType(
50055011
ENTER_V8(isolate, context, Function, NewInstance, MaybeLocal<Object>(),
50065012
InternalEscapableScope);
50075013
i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
5014+
i::NestedTimedHistogramScope execute_timer(
5015+
isolate->counters()->execute_precise());
50085016
auto self = Utils::OpenHandle(this);
50095017
STATIC_ASSERT(sizeof(v8::Local<v8::Value>) == sizeof(i::Handle<i::Object>));
50105018
bool should_set_has_no_side_effect =
@@ -5054,6 +5062,8 @@ MaybeLocal<v8::Value> Function::Call(Local<Context> context,
50545062
ENTER_V8(isolate, context, Function, Call, MaybeLocal<Value>(),
50555063
InternalEscapableScope);
50565064
i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
5065+
i::NestedTimedHistogramScope execute_timer(
5066+
isolate->counters()->execute_precise());
50575067
auto self = Utils::OpenHandle(this);
50585068
Utils::ApiCheck(!self.is_null(), "v8::Function::Call",
50595069
"Function to be called is a null pointer");
@@ -8884,7 +8894,7 @@ bool Isolate::IdleNotificationDeadline(double deadline_in_seconds) {
88848894
void Isolate::LowMemoryNotification() {
88858895
i::Isolate* isolate = reinterpret_cast<i::Isolate*>(this);
88868896
{
8887-
i::HistogramTimerScope idle_notification_scope(
8897+
i::NestedTimedHistogramScope idle_notification_scope(
88888898
isolate->counters()->gc_low_memory_notification());
88898899
TRACE_EVENT0("v8", "V8.GCLowMemoryNotification");
88908900
isolate->heap()->CollectAllAvailableGarbage(
@@ -10230,7 +10240,6 @@ void InvokeAccessorGetterCallback(
1023010240
Isolate* isolate = reinterpret_cast<Isolate*>(info.GetIsolate());
1023110241
RCS_SCOPE(isolate, RuntimeCallCounterId::kAccessorGetterCallback);
1023210242
Address getter_address = reinterpret_cast<Address>(getter);
10233-
VMState<EXTERNAL> state(isolate);
1023410243
ExternalCallbackScope call_scope(isolate, getter_address);
1023510244
getter(property, info);
1023610245
}
@@ -10240,7 +10249,6 @@ void InvokeFunctionCallback(const v8::FunctionCallbackInfo<v8::Value>& info,
1024010249
Isolate* isolate = reinterpret_cast<Isolate*>(info.GetIsolate());
1024110250
RCS_SCOPE(isolate, RuntimeCallCounterId::kFunctionCallback);
1024210251
Address callback_address = reinterpret_cast<Address>(callback);
10243-
VMState<EXTERNAL> state(isolate);
1024410252
ExternalCallbackScope call_scope(isolate, callback_address);
1024510253
callback(info);
1024610254
}

‎src/base/platform/elapsed-timer.h‎

Lines changed: 71 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -14,15 +14,20 @@ namespace base {
1414
class ElapsedTimer final {
1515
public:
1616
#ifdef DEBUG
17-
ElapsedTimer() : started_(false) {}
17+
ElapsedTimer() : start_ticks_(), started_(false) {}
18+
#else
19+
ElapsedTimer() : start_ticks_() {}
1820
#endif
1921

2022
// Starts this timer. Once started a timer can be checked with
2123
// |Elapsed()| or |HasExpired()|, and may be restarted using |Restart()|.
2224
// This method must not be called on an already started timer.
23-
void Start() {
25+
void Start() { Start(Now()); }
26+
27+
void Start(TimeTicks now) {
28+
DCHECK(!now.IsNull());
2429
DCHECK(!IsStarted());
25-
start_ticks_ = Now();
30+
set_start_ticks(now);
2631
#ifdef DEBUG
2732
started_ = true;
2833
#endif
@@ -33,7 +38,7 @@ class ElapsedTimer final {
3338
// started before.
3439
void Stop() {
3540
DCHECK(IsStarted());
36-
start_ticks_ = TimeTicks();
41+
set_start_ticks(TimeTicks());
3742
#ifdef DEBUG
3843
started_ = false;
3944
#endif
@@ -52,21 +57,51 @@ class ElapsedTimer final {
5257
// and then starting the timer again, but does so in one single operation,
5358
// avoiding the need to obtain the clock value twice. It may only be called
5459
// on a previously started timer.
55-
TimeDelta Restart() {
60+
TimeDelta Restart() { return Restart(Now()); }
61+
62+
TimeDelta Restart(TimeTicks now) {
63+
DCHECK(!now.IsNull());
5664
DCHECK(IsStarted());
57-
TimeTicks ticks = Now();
58-
TimeDelta elapsed = ticks - start_ticks_;
65+
TimeDelta elapsed = now - start_ticks_;
5966
DCHECK_GE(elapsed.InMicroseconds(), 0);
60-
start_ticks_ = ticks;
67+
set_start_ticks(now);
6168
DCHECK(IsStarted());
6269
return elapsed;
6370
}
6471

72+
void Pause() { Pause(Now()); }
73+
74+
void Pause(TimeTicks now) {
75+
TimeDelta elapsed = Elapsed(now);
76+
DCHECK(IsStarted());
77+
DCHECK(!is_paused_);
78+
#ifdef DEBUG
79+
is_paused_ = true;
80+
#endif
81+
set_paused_elapsed(elapsed);
82+
}
83+
84+
void Resume() { Resume(Now()); }
85+
86+
void Resume(TimeTicks now) {
87+
DCHECK(!now.IsNull());
88+
DCHECK(IsStarted());
89+
TimeDelta elapsed = paused_elapsed();
90+
#ifdef DEBUG
91+
is_paused_ = false;
92+
#endif
93+
set_start_ticks(now - elapsed);
94+
DCHECK(IsStarted());
95+
}
96+
6597
// Returns the time elapsed since the previous start. This method may only
6698
// be called on a previously started timer.
67-
TimeDelta Elapsed() const {
99+
TimeDelta Elapsed() const { return Elapsed(Now()); }
100+
101+
TimeDelta Elapsed(TimeTicks now) const {
102+
DCHECK(!now.IsNull());
68103
DCHECK(IsStarted());
69-
TimeDelta elapsed = Now() - start_ticks_;
104+
TimeDelta elapsed = now - start_ticks();
70105
DCHECK_GE(elapsed.InMicroseconds(), 0);
71106
return elapsed;
72107
}
@@ -86,9 +121,34 @@ class ElapsedTimer final {
86121
return now;
87122
}
88123

89-
TimeTicks start_ticks_;
124+
TimeDelta paused_elapsed() {
125+
DCHECK(IsStarted());
126+
DCHECK(is_paused_);
127+
return paused_elapsed_;
128+
}
129+
130+
void set_paused_elapsed(TimeDelta delta) {
131+
DCHECK(IsStarted());
132+
DCHECK(is_paused_);
133+
paused_elapsed_ = delta;
134+
}
135+
136+
TimeTicks start_ticks() const {
137+
DCHECK(!is_paused_);
138+
return start_ticks_;
139+
}
140+
void set_start_ticks(TimeTicks start_ticks) {
141+
DCHECK(!is_paused_);
142+
start_ticks_ = start_ticks;
143+
}
144+
145+
union {
146+
TimeTicks start_ticks_;
147+
TimeDelta paused_elapsed_;
148+
};
90149
#ifdef DEBUG
91150
bool started_;
151+
bool is_paused_ = false;
92152
#endif
93153
};
94154

‎src/codegen/compiler.cc‎

Lines changed: 16 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -44,7 +44,7 @@
4444
#include "src/heap/parked-scope.h"
4545
#include "src/init/bootstrapper.h"
4646
#include "src/interpreter/interpreter.h"
47-
#include "src/logging/counters.h"
47+
#include "src/logging/counters-scopes.h"
4848
#include "src/logging/log-inl.h"
4949
#include "src/logging/runtime-call-stats-scope.h"
5050
#include "src/objects/feedback-cell-inl.h"
@@ -1354,10 +1354,10 @@ MaybeHandle<SharedFunctionInfo> CompileToplevel(
13541354
// Measure how long it takes to do the compilation; only take the
13551355
// rest of the function into account to avoid overlap with the
13561356
// parsing statistics.
1357-
HistogramTimer* rate = parse_info->flags().is_eval()
1358-
? isolate->counters()->compile_eval()
1359-
: isolate->counters()->compile();
1360-
HistogramTimerScope timer(rate);
1357+
NestedTimedHistogram* rate = parse_info->flags().is_eval()
1358+
? isolate->counters()->compile_eval()
1359+
: isolate->counters()->compile();
1360+
NestedTimedHistogramScope timer(rate);
13611361
TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("v8.compile"),
13621362
parse_info->flags().is_eval() ? "V8.CompileEval" : "V8.Compile");
13631363

@@ -1726,7 +1726,8 @@ bool Compiler::CollectSourcePositions(Isolate* isolate,
17261726
RCS_SCOPE(isolate, RuntimeCallCounterId::kCompileCollectSourcePositions);
17271727
TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("v8.compile"),
17281728
"V8.CollectSourcePositions");
1729-
HistogramTimerScope timer(isolate->counters()->collect_source_positions());
1729+
NestedTimedHistogramScope timer(
1730+
isolate->counters()->collect_source_positions());
17301731

17311732
// Set up parse info.
17321733
UnoptimizedCompileFlags flags =
@@ -2248,14 +2249,14 @@ MaybeHandle<JSFunction> Compiler::GetFunctionFromEval(
22482249
// (via v8::Isolate::SetAllowCodeGenerationFromStringsCallback)
22492250
bool CodeGenerationFromStringsAllowed(Isolate* isolate, Handle<Context> context,
22502251
Handle<String> source) {
2252+
RCS_SCOPE(isolate, RuntimeCallCounterId::kCodeGenerationFromStringsCallbacks);
22512253
DCHECK(context->allow_code_gen_from_strings().IsFalse(isolate));
22522254
DCHECK(isolate->allow_code_gen_callback());
2253-
2254-
// Callback set. Let it decide if code generation is allowed.
2255-
VMState<EXTERNAL> state(isolate);
2256-
RCS_SCOPE(isolate, RuntimeCallCounterId::kCodeGenerationFromStringsCallbacks);
22572255
AllowCodeGenerationFromStringsCallback callback =
22582256
isolate->allow_code_gen_callback();
2257+
ExternalCallbackScope external_callback(isolate,
2258+
reinterpret_cast<Address>(callback));
2259+
// Callback set. Let it decide if code generation is allowed.
22592260
return callback(v8::Utils::ToLocal(context), v8::Utils::ToLocal(source));
22602261
}
22612262

@@ -2439,8 +2440,7 @@ struct ScriptCompileTimerScope {
24392440
explicit ScriptCompileTimerScope(
24402441
Isolate* isolate, ScriptCompiler::NoCacheReason no_cache_reason)
24412442
: isolate_(isolate),
2442-
all_scripts_histogram_scope_(isolate->counters()->compile_script(),
2443-
true),
2443+
all_scripts_histogram_scope_(isolate->counters()->compile_script()),
24442444
no_cache_reason_(no_cache_reason),
24452445
hit_isolate_cache_(false),
24462446
producing_code_cache_(false),
@@ -2479,7 +2479,7 @@ struct ScriptCompileTimerScope {
24792479
LazyTimedHistogramScope histogram_scope_;
24802480
// TODO(leszeks): This timer is the sum of the other times, consider removing
24812481
// it to save space.
2482-
HistogramTimerScope all_scripts_histogram_scope_;
2482+
NestedTimedHistogramScope all_scripts_histogram_scope_;
24832483
ScriptCompiler::NoCacheReason no_cache_reason_;
24842484
bool hit_isolate_cache_;
24852485
bool producing_code_cache_;
@@ -2845,7 +2845,8 @@ MaybeHandle<SharedFunctionInfo> Compiler::GetSharedFunctionInfoForScript(
28452845
} else if (can_consume_code_cache) {
28462846
compile_timer.set_consuming_code_cache();
28472847
// Then check cached code provided by embedder.
2848-
HistogramTimerScope timer(isolate->counters()->compile_deserialize());
2848+
NestedTimedHistogramScope timer(
2849+
isolate->counters()->compile_deserialize());
28492850
RCS_SCOPE(isolate, RuntimeCallCounterId::kCompileDeserialize);
28502851
TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("v8.compile"),
28512852
"V8.CompileDeserialize");
@@ -2932,7 +2933,7 @@ MaybeHandle<JSFunction> Compiler::GetWrappedFunction(
29322933
if (can_consume_code_cache) {
29332934
compile_timer.set_consuming_code_cache();
29342935
// Then check cached code provided by embedder.
2935-
HistogramTimerScope timer(isolate->counters()->compile_deserialize());
2936+
NestedTimedHistogramScope timer(isolate->counters()->compile_deserialize());
29362937
RCS_SCOPE(isolate, RuntimeCallCounterId::kCompileDeserialize);
29372938
TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("v8.compile"),
29382939
"V8.CompileDeserialize");

‎src/execution/vm-state-inl.h‎

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -54,7 +54,9 @@ VMState<Tag>::~VMState() {
5454
ExternalCallbackScope::ExternalCallbackScope(Isolate* isolate, Address callback)
5555
: isolate_(isolate),
5656
callback_(callback),
57-
previous_scope_(isolate->external_callback_scope()) {
57+
previous_scope_(isolate->external_callback_scope()),
58+
vm_state_(isolate),
59+
pause_timed_histogram_scope_(isolate->counters()->execute_precise()) {
5860
#ifdef USE_SIMULATOR
5961
scope_address_ = Simulator::current(isolate)->get_sp();
6062
#endif

‎src/execution/vm-state.h‎

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -7,6 +7,7 @@
77

88
#include "include/v8.h"
99
#include "src/common/globals.h"
10+
#include "src/logging/counters-scopes.h"
1011

1112
namespace v8 {
1213
namespace internal {
@@ -46,6 +47,8 @@ class V8_NODISCARD ExternalCallbackScope {
4647
Isolate* isolate_;
4748
Address callback_;
4849
ExternalCallbackScope* previous_scope_;
50+
VMState<EXTERNAL> vm_state_;
51+
PauseNestedTimedHistogramScope pause_timed_histogram_scope_;
4952
#ifdef USE_SIMULATOR
5053
Address scope_address_;
5154
#endif

0 commit comments

Comments
 (0)