diff options
Diffstat (limited to 'deps/v8/src/logging')
| -rw-r--r-- | deps/v8/src/logging/counters-definitions.h | 58 | ||||
| -rw-r--r-- | deps/v8/src/logging/counters-scopes.h | 191 | ||||
| -rw-r--r-- | deps/v8/src/logging/counters.cc | 67 | ||||
| -rw-r--r-- | deps/v8/src/logging/counters.h | 230 | ||||
| -rw-r--r-- | deps/v8/src/logging/local-logger.cc | 11 | ||||
| -rw-r--r-- | deps/v8/src/logging/local-logger.h | 6 | ||||
| -rw-r--r-- | deps/v8/src/logging/log-inl.h | 13 | ||||
| -rw-r--r-- | deps/v8/src/logging/log-utils.cc | 2 | ||||
| -rw-r--r-- | deps/v8/src/logging/log.cc | 100 | ||||
| -rw-r--r-- | deps/v8/src/logging/log.h | 60 | ||||
| -rw-r--r-- | deps/v8/src/logging/runtime-call-stats.h | 1 | ||||
| -rw-r--r-- | deps/v8/src/logging/tracing-flags.h | 2 |
12 files changed, 433 insertions, 308 deletions
diff --git a/deps/v8/src/logging/counters-definitions.h b/deps/v8/src/logging/counters-definitions.h index a939746cbc..0fcb2e15af 100644 --- a/deps/v8/src/logging/counters-definitions.h +++ b/deps/v8/src/logging/counters-definitions.h @@ -59,6 +59,8 @@ namespace internal { 51) \ HR(wasm_compile_function_peak_memory_bytes, \ V8.WasmCompileFunctionPeakMemoryBytes, 1, GB, 51) \ + HR(wasm_compile_huge_function_peak_memory_bytes, \ + V8.WasmCompileHugeFunctionPeakMemoryBytes, 1, GB, 51) \ HR(asm_module_size_bytes, V8.AsmModuleSizeBytes, 1, GB, 51) \ HR(compile_script_cache_behaviour, V8.CompileScript.CacheBehaviour, 0, 20, \ 21) \ @@ -102,34 +104,36 @@ 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) \ - /* Total JavaScript execution time (including callbacks and runtime calls */ \ - HT(execute, V8.Execute, 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 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) */ \ /* Garbage collection timers. */ \ @@ -199,6 +203,8 @@ namespace internal { 1000000, MICROSECOND) \ HT(wasm_compile_wasm_function_time, V8.WasmCompileFunctionMicroSeconds.wasm, \ 1000000, MICROSECOND) \ + HT(wasm_compile_huge_function_time, V8.WasmCompileHugeFunctionMilliSeconds, \ + 100000, MILLISECOND) \ HT(wasm_instantiate_wasm_module_time, \ V8.WasmInstantiateModuleMicroSeconds.wasm, 10000000, MICROSECOND) \ HT(wasm_instantiate_asm_module_time, \ diff --git a/deps/v8/src/logging/counters-scopes.h b/deps/v8/src/logging/counters-scopes.h new file mode 100644 index 0000000000..4f5c74b5ea --- /dev/null +++ b/deps/v8/src/logging/counters-scopes.h @@ -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_ diff --git a/deps/v8/src/logging/counters.cc b/deps/v8/src/logging/counters.cc index 3ffced0832..a333327e93 100644 --- a/deps/v8/src/logging/counters.cc +++ b/deps/v8/src/logging/counters.cc @@ -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) + {&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,7 +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); + NESTED_TIMED_HISTOGRAM_LIST_SLOW(HT) #undef HT #define HT(name, caption, max, res) name##_.Reset(); diff --git a/deps/v8/src/logging/counters.h b/deps/v8/src/logging/counters.h index 740fd2679a..3a2527f49c 100644 --- a/deps/v8/src/logging/counters.h +++ b/deps/v8/src/logging/counters.h @@ -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_; } @@ -242,7 +242,9 @@ class Histogram { Counters* counters() const { return counters_; } // Reset the cached internal pointer. - void Reset() { histogram_ = CreateHistogram(); } + void Reset(bool create_new = true) { + histogram_ = create_new ? CreateHistogram() : nullptr; + } private: friend class Counters; @@ -257,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); - } - - ~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_; -}; +class NestedTimedHistogramScope; +class PauseNestedTimedHistogramScope; -// 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(); + inline NestedTimedHistogramScope* Enter(NestedTimedHistogramScope* next) { + NestedTimedHistogramScope* previous = current_; + current_ = next; + return previous; } -#endif - ~HistogramTimerScope() { -#ifdef DEBUG - if (!skipped_timer_start_) { - timer_->Stop(); - } -#else - timer_->Stop(); -#endif + + inline void Leave(NestedTimedHistogramScope* previous) { + current_ = previous; } - private: - HistogramTimer* timer_; -#ifdef DEBUG - bool skipped_timer_start_; -#endif + NestedTimedHistogramScope* current_ = nullptr; + + NestedTimedHistogram() = default; }; // A histogram timer that can aggregate events within a larger scope. @@ -672,8 +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) + NestedTimedHistogram* name() { return &name##_; } + NESTED_TIMED_HISTOGRAM_LIST(HT) + NESTED_TIMED_HISTOGRAM_LIST_SLOW(HT) #undef HT #define HT(name, caption, max, res) \ @@ -711,7 +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) + 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, @@ -762,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); @@ -782,8 +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) +#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##_; @@ -840,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 diff --git a/deps/v8/src/logging/local-logger.cc b/deps/v8/src/logging/local-logger.cc index bd0a1598e3..e49bbfd3bd 100644 --- a/deps/v8/src/logging/local-logger.cc +++ b/deps/v8/src/logging/local-logger.cc @@ -5,6 +5,7 @@ #include "src/logging/local-logger.h" #include "src/execution/isolate.h" +#include "src/objects/map.h" namespace v8 { namespace internal { @@ -23,9 +24,15 @@ void LocalLogger::ScriptEvent(Logger::ScriptEventType type, int script_id) { logger_->ScriptEvent(type, script_id); } void LocalLogger::CodeLinePosInfoRecordEvent(Address code_start, - ByteArray source_position_table) { - logger_->CodeLinePosInfoRecordEvent(code_start, source_position_table); + ByteArray source_position_table, + JitCodeEvent::CodeType code_type) { + logger_->CodeLinePosInfoRecordEvent(code_start, source_position_table, + code_type); } +void LocalLogger::MapCreate(Map map) { logger_->MapCreate(map); } + +void LocalLogger::MapDetails(Map map) { logger_->MapDetails(map); } + } // namespace internal } // namespace v8 diff --git a/deps/v8/src/logging/local-logger.h b/deps/v8/src/logging/local-logger.h index a727013e92..a827980908 100644 --- a/deps/v8/src/logging/local-logger.h +++ b/deps/v8/src/logging/local-logger.h @@ -23,7 +23,11 @@ class LocalLogger { void ScriptDetails(Script script); void ScriptEvent(Logger::ScriptEventType type, int script_id); void CodeLinePosInfoRecordEvent(Address code_start, - ByteArray source_position_table); + ByteArray source_position_table, + JitCodeEvent::CodeType code_type); + + void MapCreate(Map map); + void MapDetails(Map map); private: Logger* logger_; diff --git a/deps/v8/src/logging/log-inl.h b/deps/v8/src/logging/log-inl.h index 83677f5f64..0929854dcb 100644 --- a/deps/v8/src/logging/log-inl.h +++ b/deps/v8/src/logging/log-inl.h @@ -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()); } diff --git a/deps/v8/src/logging/log-utils.cc b/deps/v8/src/logging/log-utils.cc index 5e27880560..67a52a5873 100644 --- a/deps/v8/src/logging/log-utils.cc +++ b/deps/v8/src/logging/log-utils.cc @@ -66,6 +66,8 @@ void Log::WriteLogHeader() { } msg << kNext << Version::IsCandidate(); msg.WriteToLogFile(); + msg << "v8-platform" << kNext << V8_OS_STRING << kNext << V8_TARGET_OS_STRING; + msg.WriteToLogFile(); } std::unique_ptr<Log::MessageBuilder> Log::NewMessageBuilder() { diff --git a/deps/v8/src/logging/log.cc b/deps/v8/src/logging/log.cc index 3fc145604b..4f6aa856d7 100644 --- a/deps/v8/src/logging/log.cc +++ b/deps/v8/src/logging/log.cc @@ -681,10 +681,12 @@ class JitLogger : public CodeEventLogger { Handle<SharedFunctionInfo> shared) override {} void AddCodeLinePosInfoEvent(void* jit_handler_data, int pc_offset, int position, - JitCodeEvent::PositionType position_type); + JitCodeEvent::PositionType position_type, + JitCodeEvent::CodeType code_type); - void* StartCodePosInfoEvent(); - void EndCodePosInfoEvent(Address start_address, void* jit_handler_data); + void* StartCodePosInfoEvent(JitCodeEvent::CodeType code_type); + void EndCodePosInfoEvent(Address start_address, void* jit_handler_data, + JitCodeEvent::CodeType code_type); private: void LogRecordedBuffer(Handle<AbstractCode> code, @@ -705,8 +707,7 @@ JitLogger::JitLogger(Isolate* isolate, JitCodeEventHandler code_event_handler) void JitLogger::LogRecordedBuffer(Handle<AbstractCode> code, MaybeHandle<SharedFunctionInfo> maybe_shared, const char* name, int length) { - JitCodeEvent event; - memset(static_cast<void*>(&event), 0, sizeof(event)); + JitCodeEvent event = {}; event.type = JitCodeEvent::CODE_ADDED; event.code_start = reinterpret_cast<void*>(code->InstructionStart()); event.code_type = @@ -727,8 +728,7 @@ void JitLogger::LogRecordedBuffer(Handle<AbstractCode> code, #if V8_ENABLE_WEBASSEMBLY void JitLogger::LogRecordedBuffer(const wasm::WasmCode* code, const char* name, int length) { - JitCodeEvent event; - memset(static_cast<void*>(&event), 0, sizeof(event)); + JitCodeEvent event = {}; event.type = JitCodeEvent::CODE_ADDED; event.code_type = JitCodeEvent::JIT_CODE; event.code_start = code->instructions().begin(); @@ -793,10 +793,11 @@ void JitLogger::CodeMoveEvent(AbstractCode from, AbstractCode to) { void JitLogger::AddCodeLinePosInfoEvent( void* jit_handler_data, int pc_offset, int position, - JitCodeEvent::PositionType position_type) { - JitCodeEvent event; - memset(static_cast<void*>(&event), 0, sizeof(event)); + JitCodeEvent::PositionType position_type, + JitCodeEvent::CodeType code_type) { + JitCodeEvent event = {}; event.type = JitCodeEvent::CODE_ADD_LINE_POS_INFO; + event.code_type = code_type; event.user_data = jit_handler_data; event.line_info.offset = pc_offset; event.line_info.pos = position; @@ -806,10 +807,10 @@ void JitLogger::AddCodeLinePosInfoEvent( code_event_handler_(&event); } -void* JitLogger::StartCodePosInfoEvent() { - JitCodeEvent event; - memset(static_cast<void*>(&event), 0, sizeof(event)); +void* JitLogger::StartCodePosInfoEvent(JitCodeEvent::CodeType code_type) { + JitCodeEvent event = {}; event.type = JitCodeEvent::CODE_START_LINE_INFO_RECORDING; + event.code_type = code_type; event.isolate = reinterpret_cast<v8::Isolate*>(isolate_); code_event_handler_(&event); @@ -817,10 +818,11 @@ void* JitLogger::StartCodePosInfoEvent() { } void JitLogger::EndCodePosInfoEvent(Address start_address, - void* jit_handler_data) { - JitCodeEvent event; - memset(static_cast<void*>(&event), 0, sizeof(event)); + void* jit_handler_data, + JitCodeEvent::CodeType code_type) { + JitCodeEvent event = {}; event.type = JitCodeEvent::CODE_END_LINE_INFO_RECORDING; + event.code_type = code_type; event.code_start = reinterpret_cast<void*>(start_address); event.user_data = jit_handler_data; event.isolate = reinterpret_cast<v8::Isolate*>(isolate_); @@ -974,6 +976,7 @@ void Profiler::Engage() { LOG(isolate_, SharedLibraryEvent(address.library_path, address.start, address.end, address.aslr_slide)); } + LOG(isolate_, SharedLibraryEnd()); // Start thread processing the profiler buffer. base::Relaxed_Store(&running_, 1); @@ -983,7 +986,7 @@ void Profiler::Engage() { Logger* logger = isolate_->logger(); logger->ticker_->SetProfiler(this); - logger->ProfilerBeginEvent(); + LOG(isolate_, ProfilerBeginEvent()); } void Profiler::Disengage() { @@ -1075,8 +1078,8 @@ void Logger::HandleEvent(const char* name, Address* location) { msg.WriteToLogFile(); } -void Logger::ApiSecurityCheck() { - if (!FLAG_log_api) return; +void Logger::WriteApiSecurityCheck() { + DCHECK(FLAG_log_api); MSG_BUILDER(); msg << "api" << kNext << "check-security"; msg.WriteToLogFile(); @@ -1093,6 +1096,13 @@ void Logger::SharedLibraryEvent(const std::string& library_path, msg.WriteToLogFile(); } +void Logger::SharedLibraryEnd() { + if (!FLAG_prof_cpp) return; + MSG_BUILDER(); + msg << "shared-library-end"; + msg.WriteToLogFile(); +} + void Logger::CurrentTimeEvent() { DCHECK(FLAG_log_internal_timer_events); MSG_BUILDER(); @@ -1100,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(); @@ -1142,38 +1152,38 @@ 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 -void Logger::ApiNamedPropertyAccess(const char* tag, JSObject holder, - Object property_name) { +void Logger::WriteApiNamedPropertyAccess(const char* tag, JSObject holder, + Object property_name) { + DCHECK(FLAG_log_api); DCHECK(property_name.IsName()); - if (!FLAG_log_api) return; MSG_BUILDER(); msg << "api" << kNext << tag << kNext << holder.class_name() << kNext << Name::cast(property_name); msg.WriteToLogFile(); } -void Logger::ApiIndexedPropertyAccess(const char* tag, JSObject holder, - uint32_t index) { - if (!FLAG_log_api) return; +void Logger::WriteApiIndexedPropertyAccess(const char* tag, JSObject holder, + uint32_t index) { + DCHECK(FLAG_log_api); MSG_BUILDER(); msg << "api" << kNext << tag << kNext << holder.class_name() << kNext << index; msg.WriteToLogFile(); } -void Logger::ApiObjectAccess(const char* tag, JSReceiver object) { - if (!FLAG_log_api) return; +void Logger::WriteApiObjectAccess(const char* tag, JSReceiver object) { + DCHECK(FLAG_log_api); MSG_BUILDER(); msg << "api" << kNext << tag << kNext << object.class_name(); msg.WriteToLogFile(); } -void Logger::ApiEntryCall(const char* name) { - if (!FLAG_log_api) return; +void Logger::WriteApiEntryCall(const char* name) { + DCHECK(FLAG_log_api); MSG_BUILDER(); msg << "api" << kNext << name; msg.WriteToLogFile(); @@ -1521,35 +1531,38 @@ void Logger::CodeDependencyChangeEvent(Handle<Code> code, namespace { void CodeLinePosEvent(JitLogger& jit_logger, Address code_start, - SourcePositionTableIterator& iter) { - void* jit_handler_data = jit_logger.StartCodePosInfoEvent(); + SourcePositionTableIterator& iter, + JitCodeEvent::CodeType code_type) { + void* jit_handler_data = jit_logger.StartCodePosInfoEvent(code_type); for (; !iter.done(); iter.Advance()) { if (iter.is_statement()) { jit_logger.AddCodeLinePosInfoEvent(jit_handler_data, iter.code_offset(), iter.source_position().ScriptOffset(), - JitCodeEvent::STATEMENT_POSITION); + JitCodeEvent::STATEMENT_POSITION, + code_type); } jit_logger.AddCodeLinePosInfoEvent(jit_handler_data, iter.code_offset(), iter.source_position().ScriptOffset(), - JitCodeEvent::POSITION); + JitCodeEvent::POSITION, code_type); } - jit_logger.EndCodePosInfoEvent(code_start, jit_handler_data); + jit_logger.EndCodePosInfoEvent(code_start, jit_handler_data, code_type); } } // namespace void Logger::CodeLinePosInfoRecordEvent(Address code_start, - ByteArray source_position_table) { + ByteArray source_position_table, + JitCodeEvent::CodeType code_type) { if (!jit_logger_) return; SourcePositionTableIterator iter(source_position_table); - CodeLinePosEvent(*jit_logger_, code_start, iter); + CodeLinePosEvent(*jit_logger_, code_start, iter, code_type); } void Logger::CodeLinePosInfoRecordEvent( Address code_start, base::Vector<const byte> source_position_table) { if (!jit_logger_) return; SourcePositionTableIterator iter(source_position_table); - CodeLinePosEvent(*jit_logger_, code_start, iter); + CodeLinePosEvent(*jit_logger_, code_start, iter, JitCodeEvent::JIT_CODE); } void Logger::CodeNameEvent(Address addr, int pos, const char* code_name) { @@ -2109,6 +2122,9 @@ FILE* Logger::TearDownAndGetLogFile() { void Logger::UpdateIsLogging(bool value) { base::MutexGuard guard(log_->mutex()); + if (value) { + isolate_->CollectSourcePositionsForAllBytecodeArrays(); + } // Relaxed atomic to avoid locking the mutex for the most common case: when // logging is disabled. is_logging_.store(value, std::memory_order_relaxed); diff --git a/deps/v8/src/logging/log.h b/deps/v8/src/logging/log.h index 45aadd7163..612c2a2df7 100644 --- a/deps/v8/src/logging/log.h +++ b/deps/v8/src/logging/log.h @@ -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, @@ -173,12 +172,28 @@ class Logger : public CodeEventListener { void ScriptDetails(Script script); // ==== Events logged by --log-api. ==== - void ApiSecurityCheck(); - void ApiNamedPropertyAccess(const char* tag, JSObject holder, Object name); + void ApiSecurityCheck() { + if (!FLAG_log_api) return; + WriteApiSecurityCheck(); + } + void ApiNamedPropertyAccess(const char* tag, JSObject holder, Object name) { + if (!FLAG_log_api) return; + WriteApiNamedPropertyAccess(tag, holder, name); + } void ApiIndexedPropertyAccess(const char* tag, JSObject holder, - uint32_t index); - void ApiObjectAccess(const char* tag, JSReceiver obj); - void ApiEntryCall(const char* name); + uint32_t index) { + if (!FLAG_log_api) return; + WriteApiIndexedPropertyAccess(tag, holder, index); + } + + void ApiObjectAccess(const char* tag, JSReceiver obj) { + if (!FLAG_log_api) return; + WriteApiObjectAccess(tag, obj); + } + void ApiEntryCall(const char* name) { + if (!FLAG_log_api) return; + WriteApiEntryCall(name); + } // ==== Events logged by --log-code. ==== V8_EXPORT_PRIVATE void AddCodeEventListener(CodeEventListener* listener); @@ -224,7 +239,8 @@ class Logger : public CodeEventListener { // Emits a code line info record event. void CodeLinePosInfoRecordEvent(Address code_start, - ByteArray source_position_table); + ByteArray source_position_table, + JitCodeEvent::CodeType code_type); void CodeLinePosInfoRecordEvent( Address code_start, base::Vector<const byte> source_position_table); @@ -242,10 +258,11 @@ class Logger : public CodeEventListener { void SharedLibraryEvent(const std::string& library_path, uintptr_t start, uintptr_t end, intptr_t aslr_slide); + void SharedLibraryEnd(); 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); @@ -256,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(); @@ -312,6 +336,14 @@ class Logger : public CodeEventListener { Handle<SharedFunctionInfo> shared); void LogCodeDisassemble(Handle<AbstractCode> code); + void WriteApiSecurityCheck(); + void WriteApiNamedPropertyAccess(const char* tag, JSObject holder, + Object name); + void WriteApiIndexedPropertyAccess(const char* tag, JSObject holder, + uint32_t index); + void WriteApiObjectAccess(const char* tag, JSReceiver obj); + void WriteApiEntryCall(const char* name); + int64_t Time(); Isolate* isolate_; @@ -373,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_; }; diff --git a/deps/v8/src/logging/runtime-call-stats.h b/deps/v8/src/logging/runtime-call-stats.h index d0687c2f62..5b3284a0c9 100644 --- a/deps/v8/src/logging/runtime-call-stats.h +++ b/deps/v8/src/logging/runtime-call-stats.h @@ -477,6 +477,7 @@ class RuntimeCallTimer final { V(WebSnapshotDeserialize_Contexts) \ V(WebSnapshotDeserialize_Exports) \ V(WebSnapshotDeserialize_Functions) \ + V(WebSnapshotDeserialize_Classes) \ V(WebSnapshotDeserialize_Maps) \ V(WebSnapshotDeserialize_Objects) \ V(WebSnapshotDeserialize_Strings) diff --git a/deps/v8/src/logging/tracing-flags.h b/deps/v8/src/logging/tracing-flags.h index b23ed03a20..b3ccb896aa 100644 --- a/deps/v8/src/logging/tracing-flags.h +++ b/deps/v8/src/logging/tracing-flags.h @@ -23,9 +23,11 @@ struct TracingFlags { static V8_EXPORT_PRIVATE std::atomic_uint ic_stats; static V8_EXPORT_PRIVATE std::atomic_uint zone_stats; +#ifdef V8_RUNTIME_CALL_STATS static bool is_runtime_stats_enabled() { return runtime_stats.load(std::memory_order_relaxed) != 0; } +#endif static bool is_gc_enabled() { return gc.load(std::memory_order_relaxed) != 0; |