Commit e4311846 authored by Camillo Bruni's avatar Camillo Bruni Committed by V8 LUCI CQ

Reland "[counters] Improve v8.execute histogram timer"

This is a reland of 69564827

Original change's description:
> [counters] Improve v8.execute histogram timer
>
> - Mark uncommon timer-paths as V8_NOINLINE
> - Add explicit LongTaskNestedTimedHistogramScope class
> - Use explicit LongTaskRecordMode enum
> - Mark a few more isolate methods as const
> - Add more timer scopes:
>   - Accessors::ArrayLengthSetter
>   - v8::NewContext
>
> Bug: v8:12498, chromium:1275056
> Change-Id: I7896ee341c3c3a1fd5acf8f3f59347ff01dda9c0
> Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/3338258
> Reviewed-by: Marja Hölttä <marja@chromium.org>
> Auto-Submit: Camillo Bruni <cbruni@chromium.org>
> Reviewed-by: Jakob Kummerow <jkummerow@chromium.org>
> Commit-Queue: Jakob Kummerow <jkummerow@chromium.org>
> Cr-Commit-Position: refs/heads/main@{#78372}

Bug: v8:12498, chromium:1275056
Change-Id: Ic153f1235d83340722fbd1053d2eba41133364d2
Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/3338700Reviewed-by: 's avatarJakob Kummerow <jkummerow@chromium.org>
Commit-Queue: Camillo Bruni <cbruni@chromium.org>
Cr-Commit-Position: refs/heads/main@{#78843}
parent a865d16b
......@@ -2057,8 +2057,8 @@ MaybeLocal<Value> Script::Run(Local<Context> context,
ENTER_V8(isolate, context, Script, Run, MaybeLocal<Value>(),
InternalEscapableScope);
i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
i::NestedTimedHistogramScope execute_timer(isolate->counters()->execute(),
isolate);
i::LongTaskNestedTimedHistogramScope execute_timer(
isolate->counters()->execute());
i::AggregatingHistogramTimerScope histogram_timer(
isolate->counters()->compile_lazy());
auto fun = i::Handle<i::JSFunction>::cast(Utils::OpenHandle(this));
......@@ -2363,8 +2363,8 @@ MaybeLocal<Value> Module::Evaluate(Local<Context> context) {
ENTER_V8(isolate, context, Module, Evaluate, MaybeLocal<Value>(),
InternalEscapableScope);
i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
i::NestedTimedHistogramScope execute_timer(isolate->counters()->execute(),
isolate);
i::LongTaskNestedTimedHistogramScope execute_timer(
isolate->counters()->execute());
i::AggregatingHistogramTimerScope timer(isolate->counters()->compile_lazy());
i::Handle<i::Module> self = Utils::OpenHandle(this);
......@@ -5120,8 +5120,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(),
isolate);
i::LongTaskNestedTimedHistogramScope execute_timer(
isolate->counters()->execute());
auto self = Utils::OpenHandle(this);
auto recv_obj = Utils::OpenHandle(*recv);
STATIC_ASSERT(sizeof(v8::Local<v8::Value>) == sizeof(i::Handle<i::Object>));
......@@ -5140,8 +5140,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(),
isolate);
i::LongTaskNestedTimedHistogramScope execute_timer(
isolate->counters()->execute());
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);
......@@ -5179,8 +5179,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(),
isolate);
i::LongTaskNestedTimedHistogramScope execute_timer(
isolate->counters()->execute());
auto self = Utils::OpenHandle(this);
STATIC_ASSERT(sizeof(v8::Local<v8::Value>) == sizeof(i::Handle<i::Object>));
bool should_set_has_no_side_effect =
......@@ -5230,8 +5230,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(),
isolate);
i::LongTaskNestedTimedHistogramScope execute_timer(
isolate->counters()->execute());
auto self = Utils::OpenHandle(this);
Utils::ApiCheck(!self.is_null(), "v8::Function::Call",
"Function to be called is a null pointer");
......@@ -6367,6 +6367,8 @@ Local<Context> NewContext(
TRACE_EVENT_CALL_STATS_SCOPED(isolate, "v8", "V8.NewContext");
LOG_API(isolate, Context, New);
i::LongTaskNestedTimedHistogramScope execute_timer(
isolate->counters()->execute());
i::HandleScope scope(isolate);
ExtensionConfiguration no_extensions;
if (extensions == nullptr) extensions = &no_extensions;
......
......@@ -12,6 +12,7 @@
#include "src/execution/isolate-inl.h"
#include "src/execution/messages.h"
#include "src/heap/factory.h"
#include "src/logging/counters-scopes.h"
#include "src/logging/runtime-call-stats-scope.h"
#include "src/objects/api-callbacks.h"
#include "src/objects/contexts.h"
......@@ -166,6 +167,8 @@ void Accessors::ArrayLengthSetter(
const v8::PropertyCallbackInfo<v8::Boolean>& info) {
i::Isolate* isolate = reinterpret_cast<i::Isolate*>(info.GetIsolate());
RCS_SCOPE(isolate, RuntimeCallCounterId::kArrayLengthSetter);
i::LongTaskNestedTimedHistogramScope timer_scope(
isolate->counters()->execute());
HandleScope scope(isolate);
DCHECK(Utils::OpenHandle(*name)->SameValue(
......
......@@ -1083,21 +1083,21 @@ class V8_EXPORT_PRIVATE Isolate final : private HiddenFactory {
NATIVE_CONTEXT_FIELDS(NATIVE_CONTEXT_FIELD_ACCESSOR)
#undef NATIVE_CONTEXT_FIELD_ACCESSOR
Bootstrapper* bootstrapper() { return bootstrapper_; }
Bootstrapper* bootstrapper() const { return bootstrapper_; }
// Use for updating counters on a foreground thread.
Counters* counters() { return async_counters().get(); }
Counters* counters() const { return async_counters().get(); }
// Use for updating counters on a background thread.
const std::shared_ptr<Counters>& async_counters() {
const std::shared_ptr<Counters>& async_counters() const {
// Make sure InitializeCounters() has been called.
DCHECK_NOT_NULL(async_counters_.get());
return async_counters_;
}
const std::shared_ptr<metrics::Recorder>& metrics_recorder() {
const std::shared_ptr<metrics::Recorder>& metrics_recorder() const {
return metrics_recorder_;
}
RuntimeProfiler* runtime_profiler() { return runtime_profiler_; }
CompilationCache* compilation_cache() { return compilation_cache_; }
Logger* logger() {
RuntimeProfiler* runtime_profiler() const { return runtime_profiler_; }
CompilationCache* compilation_cache() const { return compilation_cache_; }
Logger* logger() const {
// Call InitializeLoggingAndCounters() if logging is needed before
// the isolate is fully initialized.
DCHECK_NOT_NULL(logger_);
......
......@@ -119,9 +119,13 @@ class V8_NODISCARD LazyTimedHistogramScope : public BaseTimedHistogramScope {
// Helper class for scoping a NestedHistogramTimer.
class V8_NODISCARD NestedTimedHistogramScope : public BaseTimedHistogramScope {
public:
explicit NestedTimedHistogramScope(NestedTimedHistogram* histogram,
Isolate* isolate = nullptr)
: BaseTimedHistogramScope(histogram), isolate_(isolate) {
enum class LongTaskRecordMode { kSkip, kRecord };
explicit NestedTimedHistogramScope(
NestedTimedHistogram* histogram,
LongTaskRecordMode long_task_record_mode = LongTaskRecordMode::kSkip)
: BaseTimedHistogramScope(histogram),
long_task_record_mode_(long_task_record_mode) {
Start();
}
~NestedTimedHistogramScope() { Stop(); }
......@@ -130,19 +134,36 @@ class V8_NODISCARD NestedTimedHistogramScope : public BaseTimedHistogramScope {
friend NestedTimedHistogram;
friend PauseNestedTimedHistogramScope;
void StartInteral() {
V8_INLINE void Start() {
if (histogram_->Enabled()) StartInteral();
LogStart(isolate());
}
V8_NOINLINE void StartInteral() {
previous_scope_ = timed_histogram()->Enter(this);
base::TimeTicks now = base::TimeTicks::HighResolutionNow();
if (previous_scope_) previous_scope_->Pause(now);
timer_.Start(now);
}
void StopInternal() {
void Pause(base::TimeTicks now) {
DCHECK(histogram_->Enabled());
timer_.Pause(now);
}
V8_INLINE void Stop() {
if (histogram_->Enabled()) StopInternal();
LogEnd(isolate());
}
V8_NOINLINE void StopInternal() {
timed_histogram()->Leave(previous_scope_);
base::TimeTicks now = base::TimeTicks::HighResolutionNow();
base::TimeDelta elapsed = timer_.Elapsed(now);
histogram_->AddTimedSample(elapsed);
if (isolate_) RecordLongTaskTime(elapsed);
if (long_task_record_mode_ == LongTaskRecordMode::kRecord) {
RecordLongTaskTime(elapsed);
}
#ifdef DEBUG
// StopInternal() is called in the destructor and don't access timer_
// after that.
......@@ -151,39 +172,33 @@ class V8_NODISCARD NestedTimedHistogramScope : public BaseTimedHistogramScope {
if (previous_scope_) previous_scope_->Resume(now);
}
V8_INLINE void Start() {
if (histogram_->Enabled()) StartInteral();
LogStart(timed_histogram()->counters()->isolate());
}
V8_INLINE void Stop() {
if (histogram_->Enabled()) StopInternal();
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);
}
void RecordLongTaskTime(base::TimeDelta elapsed) const {
if (histogram_ == isolate_->counters()->execute()) {
isolate_->GetCurrentLongTaskStats()->v8_execute_us +=
if (histogram_ == timed_histogram()->counters()->execute()) {
isolate()->GetCurrentLongTaskStats()->v8_execute_us +=
elapsed.InMicroseconds();
}
}
NestedTimedHistogram* timed_histogram() {
Isolate* isolate() const { return timed_histogram()->counters()->isolate(); }
NestedTimedHistogram* timed_histogram() const {
return static_cast<NestedTimedHistogram*>(histogram_);
}
NestedTimedHistogramScope* previous_scope_;
Isolate* isolate_;
LongTaskRecordMode long_task_record_mode_;
};
class V8_NODISCARD LongTaskNestedTimedHistogramScope
: public NestedTimedHistogramScope {
public:
explicit LongTaskNestedTimedHistogramScope(NestedTimedHistogram* histogram)
: NestedTimedHistogramScope(histogram, LongTaskRecordMode::kRecord) {}
};
// Temporarily pause a NestedTimedHistogram when for instance leaving V8 for
......@@ -191,21 +206,31 @@ class V8_NODISCARD NestedTimedHistogramScope : public BaseTimedHistogramScope {
class V8_NODISCARD PauseNestedTimedHistogramScope {
public:
explicit PauseNestedTimedHistogramScope(NestedTimedHistogram* histogram)
: histogram_(histogram) {
: histogram_(histogram), previous_scope_(nullptr) {
if (histogram_->Enabled()) Pause();
}
~PauseNestedTimedHistogramScope() {
if (previous_scope_ && histogram_->Enabled()) Resume();
}
private:
V8_NOINLINE void Pause() {
previous_scope_ = histogram_->Enter(nullptr);
if (isEnabled()) {
// For performance reasons we don't annotate all internal callbacks with
// NestedTimerScopes which might lead to double pausing and minor
// inaccuracies.
// TODO(v8:12498): Add DCHECK_NOT_NULL(previous_scope_)
if (previous_scope_) {
previous_scope_->Pause(base::TimeTicks::HighResolutionNow());
}
}
~PauseNestedTimedHistogramScope() {
V8_NOINLINE void Resume() {
histogram_->Leave(previous_scope_);
if (isEnabled()) {
previous_scope_->Resume(base::TimeTicks::HighResolutionNow());
}
previous_scope_->Resume(base::TimeTicks::HighResolutionNow());
}
private:
bool isEnabled() const { return previous_scope_ && histogram_->Enabled(); }
NestedTimedHistogram* histogram_;
NestedTimedHistogramScope* previous_scope_;
};
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment