Skip to content

Commit a12c6fa

Browse files
LeszekSwirskiV8 LUCI CQ
authored andcommitted
Revert "[counters] Fix reentrant timers for V8.Execute"
This reverts commit fffcbae. 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}
1 parent 7810ce0 commit a12c6fa

24 files changed

Lines changed: 308 additions & 579 deletions

BUILD.bazel

Lines changed: 0 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1411,7 +1411,6 @@ filegroup(
14111411
"src/logging/counters-definitions.h",
14121412
"src/logging/counters.cc",
14131413
"src/logging/counters.h",
1414-
"src/logging/counters-scopes.h",
14151414
"src/logging/local-logger.cc",
14161415
"src/logging/local-logger.h",
14171416
"src/logging/log-inl.h",

BUILD.gn

Lines changed: 0 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -2835,7 +2835,6 @@ v8_header_set("v8_internal_headers") {
28352835
"src/libsampler/sampler.h",
28362836
"src/logging/code-events.h",
28372837
"src/logging/counters-definitions.h",
2838-
"src/logging/counters-scopes.h",
28392838
"src/logging/counters.h",
28402839
"src/logging/local-logger.h",
28412840
"src/logging/log-inl.h",

src/api/api-arguments-inl.h

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

@@ -84,6 +85,7 @@ inline JSReceiver FunctionCallbackArguments::holder() {
8485
if (ISOLATE->debug_execution_mode() == DebugInfo::kSideEffects) { \
8586
return RETURN_VALUE(); \
8687
} \
88+
VMState<EXTERNAL> state(ISOLATE); \
8789
ExternalCallbackScope call_scope(ISOLATE, FUNCTION_ADDR(F)); \
8890
PropertyCallbackInfo<API_RETURN_TYPE> callback_info(values_);
8991

@@ -147,6 +149,7 @@ Handle<Object> FunctionCallbackArguments::Call(CallHandlerInfo handler) {
147149
Debug::kNotAccessor)) {
148150
return Handle<Object>();
149151
}
152+
VMState<EXTERNAL> state(isolate);
150153
ExternalCallbackScope call_scope(isolate, FUNCTION_ADDR(f));
151154
FunctionCallbackInfo<v8::Value> info(values_, argv_, argc_);
152155
f(info);

src/api/api.cc

Lines changed: 8 additions & 16 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-scopes.h"
61+
#include "src/logging/counters.h"
6262
#include "src/logging/metrics.h"
6363
#include "src/logging/runtime-call-stats-scope.h"
6464
#include "src/logging/tracing-flags.h"
@@ -1967,11 +1967,10 @@ 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::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
1971-
i::NestedTimedHistogramScope execute_timer(
1972-
isolate->counters()->execute_precise());
1970+
i::HistogramTimerScope execute_timer(isolate->counters()->execute(), true);
19731971
i::AggregatingHistogramTimerScope histogram_timer(
19741972
isolate->counters()->compile_lazy());
1973+
i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
19751974
auto fun = i::Handle<i::JSFunction>::cast(Utils::OpenHandle(this));
19761975

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

23022300
i::Handle<i::Module> self = Utils::OpenHandle(this);
23032301
Utils::ApiCheck(self->status() >= i::Module::kInstantiated,
@@ -4952,8 +4950,6 @@ MaybeLocal<Value> Object::CallAsFunction(Local<Context> context,
49524950
ENTER_V8(isolate, context, Object, CallAsFunction, MaybeLocal<Value>(),
49534951
InternalEscapableScope);
49544952
i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
4955-
i::NestedTimedHistogramScope execute_timer(
4956-
isolate->counters()->execute_precise());
49574953
auto self = Utils::OpenHandle(this);
49584954
auto recv_obj = Utils::OpenHandle(*recv);
49594955
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,
49724968
ENTER_V8(isolate, context, Object, CallAsConstructor, MaybeLocal<Value>(),
49734969
InternalEscapableScope);
49744970
i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
4975-
i::NestedTimedHistogramScope execute_timer(
4976-
isolate->counters()->execute_precise());
49774971
auto self = Utils::OpenHandle(this);
49784972
STATIC_ASSERT(sizeof(v8::Local<v8::Value>) == sizeof(i::Handle<i::Object>));
49794973
i::Handle<i::Object>* args = reinterpret_cast<i::Handle<i::Object>*>(argv);
@@ -5011,8 +5005,6 @@ MaybeLocal<Object> Function::NewInstanceWithSideEffectType(
50115005
ENTER_V8(isolate, context, Function, NewInstance, MaybeLocal<Object>(),
50125006
InternalEscapableScope);
50135007
i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
5014-
i::NestedTimedHistogramScope execute_timer(
5015-
isolate->counters()->execute_precise());
50165008
auto self = Utils::OpenHandle(this);
50175009
STATIC_ASSERT(sizeof(v8::Local<v8::Value>) == sizeof(i::Handle<i::Object>));
50185010
bool should_set_has_no_side_effect =
@@ -5062,8 +5054,6 @@ MaybeLocal<v8::Value> Function::Call(Local<Context> context,
50625054
ENTER_V8(isolate, context, Function, Call, MaybeLocal<Value>(),
50635055
InternalEscapableScope);
50645056
i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
5065-
i::NestedTimedHistogramScope execute_timer(
5066-
isolate->counters()->execute_precise());
50675057
auto self = Utils::OpenHandle(this);
50685058
Utils::ApiCheck(!self.is_null(), "v8::Function::Call",
50695059
"Function to be called is a null pointer");
@@ -8894,7 +8884,7 @@ bool Isolate::IdleNotificationDeadline(double deadline_in_seconds) {
88948884
void Isolate::LowMemoryNotification() {
88958885
i::Isolate* isolate = reinterpret_cast<i::Isolate*>(this);
88968886
{
8897-
i::NestedTimedHistogramScope idle_notification_scope(
8887+
i::HistogramTimerScope idle_notification_scope(
88988888
isolate->counters()->gc_low_memory_notification());
88998889
TRACE_EVENT0("v8", "V8.GCLowMemoryNotification");
89008890
isolate->heap()->CollectAllAvailableGarbage(
@@ -10240,6 +10230,7 @@ void InvokeAccessorGetterCallback(
1024010230
Isolate* isolate = reinterpret_cast<Isolate*>(info.GetIsolate());
1024110231
RCS_SCOPE(isolate, RuntimeCallCounterId::kAccessorGetterCallback);
1024210232
Address getter_address = reinterpret_cast<Address>(getter);
10233+
VMState<EXTERNAL> state(isolate);
1024310234
ExternalCallbackScope call_scope(isolate, getter_address);
1024410235
getter(property, info);
1024510236
}
@@ -10249,6 +10240,7 @@ void InvokeFunctionCallback(const v8::FunctionCallbackInfo<v8::Value>& info,
1024910240
Isolate* isolate = reinterpret_cast<Isolate*>(info.GetIsolate());
1025010241
RCS_SCOPE(isolate, RuntimeCallCounterId::kFunctionCallback);
1025110242
Address callback_address = reinterpret_cast<Address>(callback);
10243+
VMState<EXTERNAL> state(isolate);
1025210244
ExternalCallbackScope call_scope(isolate, callback_address);
1025310245
callback(info);
1025410246
}

src/base/platform/elapsed-timer.h

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

2220
// Starts this timer. Once started a timer can be checked with
2321
// |Elapsed()| or |HasExpired()|, and may be restarted using |Restart()|.
2422
// This method must not be called on an already started timer.
25-
void Start() { Start(Now()); }
26-
27-
void Start(TimeTicks now) {
28-
DCHECK(!now.IsNull());
23+
void Start() {
2924
DCHECK(!IsStarted());
30-
set_start_ticks(now);
25+
start_ticks_ = Now();
3126
#ifdef DEBUG
3227
started_ = true;
3328
#endif
@@ -38,7 +33,7 @@ class ElapsedTimer final {
3833
// started before.
3934
void Stop() {
4035
DCHECK(IsStarted());
41-
set_start_ticks(TimeTicks());
36+
start_ticks_ = TimeTicks();
4237
#ifdef DEBUG
4338
started_ = false;
4439
#endif
@@ -57,51 +52,21 @@ class ElapsedTimer final {
5752
// and then starting the timer again, but does so in one single operation,
5853
// avoiding the need to obtain the clock value twice. It may only be called
5954
// on a previously started timer.
60-
TimeDelta Restart() { return Restart(Now()); }
61-
62-
TimeDelta Restart(TimeTicks now) {
63-
DCHECK(!now.IsNull());
55+
TimeDelta Restart() {
6456
DCHECK(IsStarted());
65-
TimeDelta elapsed = now - start_ticks_;
57+
TimeTicks ticks = Now();
58+
TimeDelta elapsed = ticks - start_ticks_;
6659
DCHECK_GE(elapsed.InMicroseconds(), 0);
67-
set_start_ticks(now);
60+
start_ticks_ = ticks;
6861
DCHECK(IsStarted());
6962
return elapsed;
7063
}
7164

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-
9765
// Returns the time elapsed since the previous start. This method may only
9866
// be called on a previously started timer.
99-
TimeDelta Elapsed() const { return Elapsed(Now()); }
100-
101-
TimeDelta Elapsed(TimeTicks now) const {
102-
DCHECK(!now.IsNull());
67+
TimeDelta Elapsed() const {
10368
DCHECK(IsStarted());
104-
TimeDelta elapsed = now - start_ticks();
69+
TimeDelta elapsed = Now() - start_ticks_;
10570
DCHECK_GE(elapsed.InMicroseconds(), 0);
10671
return elapsed;
10772
}
@@ -121,34 +86,9 @@ class ElapsedTimer final {
12186
return now;
12287
}
12388

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-
};
89+
TimeTicks start_ticks_;
14990
#ifdef DEBUG
15091
bool started_;
151-
bool is_paused_ = false;
15292
#endif
15393
};
15494

src/codegen/compiler.cc

Lines changed: 15 additions & 16 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-scopes.h"
47+
#include "src/logging/counters.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-
NestedTimedHistogram* rate = parse_info->flags().is_eval()
1358-
? isolate->counters()->compile_eval()
1359-
: isolate->counters()->compile();
1360-
NestedTimedHistogramScope timer(rate);
1357+
HistogramTimer* rate = parse_info->flags().is_eval()
1358+
? isolate->counters()->compile_eval()
1359+
: isolate->counters()->compile();
1360+
HistogramTimerScope timer(rate);
13611361
TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("v8.compile"),
13621362
parse_info->flags().is_eval() ? "V8.CompileEval" : "V8.Compile");
13631363

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

17321731
// Set up parse info.
17331732
UnoptimizedCompileFlags flags =
@@ -2249,14 +2248,14 @@ MaybeHandle<JSFunction> Compiler::GetFunctionFromEval(
22492248
// (via v8::Isolate::SetAllowCodeGenerationFromStringsCallback)
22502249
bool CodeGenerationFromStringsAllowed(Isolate* isolate, Handle<Context> context,
22512250
Handle<String> source) {
2252-
RCS_SCOPE(isolate, RuntimeCallCounterId::kCodeGenerationFromStringsCallbacks);
22532251
DCHECK(context->allow_code_gen_from_strings().IsFalse(isolate));
22542252
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);
22552257
AllowCodeGenerationFromStringsCallback callback =
22562258
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.
22602259
return callback(v8::Utils::ToLocal(context), v8::Utils::ToLocal(source));
22612260
}
22622261

@@ -2440,7 +2439,8 @@ struct ScriptCompileTimerScope {
24402439
explicit ScriptCompileTimerScope(
24412440
Isolate* isolate, ScriptCompiler::NoCacheReason no_cache_reason)
24422441
: isolate_(isolate),
2443-
all_scripts_histogram_scope_(isolate->counters()->compile_script()),
2442+
all_scripts_histogram_scope_(isolate->counters()->compile_script(),
2443+
true),
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-
NestedTimedHistogramScope all_scripts_histogram_scope_;
2482+
HistogramTimerScope all_scripts_histogram_scope_;
24832483
ScriptCompiler::NoCacheReason no_cache_reason_;
24842484
bool hit_isolate_cache_;
24852485
bool producing_code_cache_;
@@ -2845,8 +2845,7 @@ 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-
NestedTimedHistogramScope timer(
2849-
isolate->counters()->compile_deserialize());
2848+
HistogramTimerScope timer(isolate->counters()->compile_deserialize());
28502849
RCS_SCOPE(isolate, RuntimeCallCounterId::kCompileDeserialize);
28512850
TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("v8.compile"),
28522851
"V8.CompileDeserialize");
@@ -2933,7 +2932,7 @@ MaybeHandle<JSFunction> Compiler::GetWrappedFunction(
29332932
if (can_consume_code_cache) {
29342933
compile_timer.set_consuming_code_cache();
29352934
// Then check cached code provided by embedder.
2936-
NestedTimedHistogramScope timer(isolate->counters()->compile_deserialize());
2935+
HistogramTimerScope timer(isolate->counters()->compile_deserialize());
29372936
RCS_SCOPE(isolate, RuntimeCallCounterId::kCompileDeserialize);
29382937
TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("v8.compile"),
29392938
"V8.CompileDeserialize");

src/execution/vm-state-inl.h

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

src/execution/vm-state.h

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

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

1211
namespace v8 {
1312
namespace internal {
@@ -47,8 +46,6 @@ class V8_NODISCARD ExternalCallbackScope {
4746
Isolate* isolate_;
4847
Address callback_;
4948
ExternalCallbackScope* previous_scope_;
50-
VMState<EXTERNAL> vm_state_;
51-
PauseNestedTimedHistogramScope pause_timed_histogram_scope_;
5249
#ifdef USE_SIMULATOR
5350
Address scope_address_;
5451
#endif

0 commit comments

Comments
 (0)