diff options
Diffstat (limited to 'deps/v8/src/logging/counters.cc')
-rw-r--r-- | deps/v8/src/logging/counters.cc | 370 |
1 files changed, 9 insertions, 361 deletions
diff --git a/deps/v8/src/logging/counters.cc b/deps/v8/src/logging/counters.cc index c9c9aa0ebe..3ffced0832 100644 --- a/deps/v8/src/logging/counters.cc +++ b/deps/v8/src/logging/counters.cc @@ -4,16 +4,13 @@ #include "src/logging/counters.h" -#include <iomanip> - -#include "src/base/platform/platform.h" +#include "src/base/atomic-utils.h" +#include "src/base/platform/elapsed-timer.h" #include "src/base/platform/time.h" #include "src/builtins/builtins-definitions.h" #include "src/execution/isolate.h" -#include "src/logging/counters-inl.h" #include "src/logging/log-inl.h" #include "src/logging/log.h" -#include "src/utils/ostreams.h" namespace v8 { namespace internal { @@ -121,15 +118,16 @@ void TimedHistogram::RecordAbandon(base::ElapsedTimer* timer, } Counters::Counters(Isolate* isolate) - : isolate_(isolate), - stats_table_(this), -// clang format off + : #define SC(name, caption) name##_(this, "c:" #caption), STATS_COUNTER_TS_LIST(SC) #undef SC - // clang format on - runtime_call_stats_(RuntimeCallStats::kMainIsolateThread), - worker_thread_runtime_call_stats_() { +#ifdef V8_RUNTIME_CALL_STATS + runtime_call_stats_(RuntimeCallStats::kMainIsolateThread), + worker_thread_runtime_call_stats_(), +#endif + isolate_(isolate), + stats_table_(this) { static const struct { Histogram Counters::*member; const char* caption; @@ -319,355 +317,5 @@ void Counters::ResetCreateHistogramFunction(CreateHistogramCallback f) { #undef HM } -base::TimeTicks (*RuntimeCallTimer::Now)() = - &base::TimeTicks::HighResolutionNow; - -base::TimeTicks RuntimeCallTimer::NowCPUTime() { - base::ThreadTicks ticks = base::ThreadTicks::Now(); - return base::TimeTicks::FromInternalValue(ticks.ToInternalValue()); -} - -class RuntimeCallStatEntries { - public: - void Print(std::ostream& os) { - if (total_call_count == 0) return; - std::sort(entries.rbegin(), entries.rend()); - os << std::setw(50) << "Runtime Function/C++ Builtin" << std::setw(12) - << "Time" << std::setw(18) << "Count" << std::endl - << std::string(88, '=') << std::endl; - for (Entry& entry : entries) { - entry.SetTotal(total_time, total_call_count); - entry.Print(os); - } - os << std::string(88, '-') << std::endl; - Entry("Total", total_time, total_call_count).Print(os); - } - - // By default, the compiler will usually inline this, which results in a large - // binary size increase: std::vector::push_back expands to a large amount of - // instructions, and this function is invoked repeatedly by macros. - V8_NOINLINE void Add(RuntimeCallCounter* counter) { - if (counter->count() == 0) return; - entries.push_back( - Entry(counter->name(), counter->time(), counter->count())); - total_time += counter->time(); - total_call_count += counter->count(); - } - - private: - class Entry { - public: - Entry(const char* name, base::TimeDelta time, uint64_t count) - : name_(name), - time_(time.InMicroseconds()), - count_(count), - time_percent_(100), - count_percent_(100) {} - - bool operator<(const Entry& other) const { - if (time_ < other.time_) return true; - if (time_ > other.time_) return false; - return count_ < other.count_; - } - - V8_NOINLINE void Print(std::ostream& os) { - os.precision(2); - os << std::fixed << std::setprecision(2); - os << std::setw(50) << name_; - os << std::setw(10) << static_cast<double>(time_) / 1000 << "ms "; - os << std::setw(6) << time_percent_ << "%"; - os << std::setw(10) << count_ << " "; - os << std::setw(6) << count_percent_ << "%"; - os << std::endl; - } - - V8_NOINLINE void SetTotal(base::TimeDelta total_time, - uint64_t total_count) { - if (total_time.InMicroseconds() == 0) { - time_percent_ = 0; - } else { - time_percent_ = 100.0 * time_ / total_time.InMicroseconds(); - } - count_percent_ = 100.0 * count_ / total_count; - } - - private: - const char* name_; - int64_t time_; - uint64_t count_; - double time_percent_; - double count_percent_; - }; - - uint64_t total_call_count = 0; - base::TimeDelta total_time; - std::vector<Entry> entries; -}; - -void RuntimeCallCounter::Reset() { - count_ = 0; - time_ = 0; -} - -void RuntimeCallCounter::Dump(v8::tracing::TracedValue* value) { - value->BeginArray(name_); - value->AppendDouble(count_); - value->AppendDouble(time_); - value->EndArray(); -} - -void RuntimeCallCounter::Add(RuntimeCallCounter* other) { - count_ += other->count(); - time_ += other->time().InMicroseconds(); -} - -void RuntimeCallTimer::Snapshot() { - base::TimeTicks now = Now(); - // Pause only / topmost timer in the timer stack. - Pause(now); - // Commit all the timer's elapsed time to the counters. - RuntimeCallTimer* timer = this; - while (timer != nullptr) { - timer->CommitTimeToCounter(); - timer = timer->parent(); - } - Resume(now); -} - -RuntimeCallStats::RuntimeCallStats(ThreadType thread_type) - : in_use_(false), thread_type_(thread_type) { - static const char* const kNames[] = { -#define CALL_BUILTIN_COUNTER(name) "GC_" #name, - FOR_EACH_GC_COUNTER(CALL_BUILTIN_COUNTER) // -#undef CALL_BUILTIN_COUNTER -#define CALL_RUNTIME_COUNTER(name) #name, - FOR_EACH_MANUAL_COUNTER(CALL_RUNTIME_COUNTER) // -#undef CALL_RUNTIME_COUNTER -#define CALL_RUNTIME_COUNTER(name, nargs, ressize) #name, - FOR_EACH_INTRINSIC(CALL_RUNTIME_COUNTER) // -#undef CALL_RUNTIME_COUNTER -#define CALL_BUILTIN_COUNTER(name) #name, - BUILTIN_LIST_C(CALL_BUILTIN_COUNTER) // -#undef CALL_BUILTIN_COUNTER -#define CALL_BUILTIN_COUNTER(name) "API_" #name, - FOR_EACH_API_COUNTER(CALL_BUILTIN_COUNTER) // -#undef CALL_BUILTIN_COUNTER -#define CALL_BUILTIN_COUNTER(name) #name, - FOR_EACH_HANDLER_COUNTER(CALL_BUILTIN_COUNTER) // -#undef CALL_BUILTIN_COUNTER -#define THREAD_SPECIFIC_COUNTER(name) #name, - FOR_EACH_THREAD_SPECIFIC_COUNTER(THREAD_SPECIFIC_COUNTER) // -#undef THREAD_SPECIFIC_COUNTER - }; - for (int i = 0; i < kNumberOfCounters; i++) { - this->counters_[i] = RuntimeCallCounter(kNames[i]); - } - if (FLAG_rcs_cpu_time) { - CHECK(base::ThreadTicks::IsSupported()); - base::ThreadTicks::WaitUntilInitialized(); - RuntimeCallTimer::Now = &RuntimeCallTimer::NowCPUTime; - } -} - -namespace { -constexpr RuntimeCallCounterId FirstCounter(RuntimeCallCounterId first, ...) { - return first; -} - -#define THREAD_SPECIFIC_COUNTER(name) k##name, -constexpr RuntimeCallCounterId kFirstThreadVariantCounter = - FirstCounter(FOR_EACH_THREAD_SPECIFIC_COUNTER(THREAD_SPECIFIC_COUNTER) 0); -#undef THREAD_SPECIFIC_COUNTER - -#define THREAD_SPECIFIC_COUNTER(name) +1 -constexpr int kThreadVariantCounterCount = - 0 FOR_EACH_THREAD_SPECIFIC_COUNTER(THREAD_SPECIFIC_COUNTER); -#undef THREAD_SPECIFIC_COUNTER - -constexpr auto kLastThreadVariantCounter = static_cast<RuntimeCallCounterId>( - kFirstThreadVariantCounter + kThreadVariantCounterCount - 1); -} // namespace - -bool RuntimeCallStats::HasThreadSpecificCounterVariants( - RuntimeCallCounterId id) { - // Check that it's in the range of the thread-specific variant counters and - // also that it's one of the background counters. - return id >= kFirstThreadVariantCounter && id <= kLastThreadVariantCounter; -} - -bool RuntimeCallStats::IsBackgroundThreadSpecificVariant( - RuntimeCallCounterId id) { - return HasThreadSpecificCounterVariants(id) && - (id - kFirstThreadVariantCounter) % 2 == 1; -} - -void RuntimeCallStats::Enter(RuntimeCallTimer* timer, - RuntimeCallCounterId counter_id) { - DCHECK(IsCalledOnTheSameThread()); - RuntimeCallCounter* counter = GetCounter(counter_id); - DCHECK_NOT_NULL(counter->name()); - timer->Start(counter, current_timer()); - current_timer_.SetValue(timer); - current_counter_.SetValue(counter); -} - -void RuntimeCallStats::Leave(RuntimeCallTimer* timer) { - DCHECK(IsCalledOnTheSameThread()); - RuntimeCallTimer* stack_top = current_timer(); - if (stack_top == nullptr) return; // Missing timer is a result of Reset(). - CHECK(stack_top == timer); - current_timer_.SetValue(timer->Stop()); - RuntimeCallTimer* cur_timer = current_timer(); - current_counter_.SetValue(cur_timer ? cur_timer->counter() : nullptr); -} - -void RuntimeCallStats::Add(RuntimeCallStats* other) { - for (int i = 0; i < kNumberOfCounters; i++) { - GetCounter(i)->Add(other->GetCounter(i)); - } -} - -// static -void RuntimeCallStats::CorrectCurrentCounterId(RuntimeCallCounterId counter_id, - CounterMode mode) { - DCHECK(IsCalledOnTheSameThread()); - if (mode == RuntimeCallStats::CounterMode::kThreadSpecific) { - counter_id = CounterIdForThread(counter_id); - } - DCHECK(IsCounterAppropriateForThread(counter_id)); - - RuntimeCallTimer* timer = current_timer(); - if (timer == nullptr) return; - RuntimeCallCounter* counter = GetCounter(counter_id); - timer->set_counter(counter); - current_counter_.SetValue(counter); -} - -bool RuntimeCallStats::IsCalledOnTheSameThread() { - if (thread_id_.IsValid()) return thread_id_ == ThreadId::Current(); - thread_id_ = ThreadId::Current(); - return true; -} - -void RuntimeCallStats::Print() { - StdoutStream os; - Print(os); -} - -void RuntimeCallStats::Print(std::ostream& os) { - RuntimeCallStatEntries entries; - if (current_timer_.Value() != nullptr) { - current_timer_.Value()->Snapshot(); - } - for (int i = 0; i < kNumberOfCounters; i++) { - entries.Add(GetCounter(i)); - } - entries.Print(os); -} - -void RuntimeCallStats::EnumerateCounters( - debug::RuntimeCallCounterCallback callback) { - if (current_timer_.Value() != nullptr) { - current_timer_.Value()->Snapshot(); - } - for (int i = 0; i < kNumberOfCounters; i++) { - RuntimeCallCounter* counter = GetCounter(i); - callback(counter->name(), counter->count(), counter->time()); - } -} - -void RuntimeCallStats::Reset() { - if (V8_LIKELY(!TracingFlags::is_runtime_stats_enabled())) return; - - // In tracing, we only what to trace the time spent on top level trace events, - // if runtime counter stack is not empty, we should clear the whole runtime - // counter stack, and then reset counters so that we can dump counters into - // top level trace events accurately. - while (current_timer_.Value()) { - current_timer_.SetValue(current_timer_.Value()->Stop()); - } - - for (int i = 0; i < kNumberOfCounters; i++) { - GetCounter(i)->Reset(); - } - - in_use_ = true; -} - -void RuntimeCallStats::Dump(v8::tracing::TracedValue* value) { - for (int i = 0; i < kNumberOfCounters; i++) { - if (GetCounter(i)->count() > 0) GetCounter(i)->Dump(value); - } - in_use_ = false; -} - -WorkerThreadRuntimeCallStats::WorkerThreadRuntimeCallStats() - : isolate_thread_id_(ThreadId::Current()) {} - -WorkerThreadRuntimeCallStats::~WorkerThreadRuntimeCallStats() { - if (tls_key_) base::Thread::DeleteThreadLocalKey(*tls_key_); -} - -base::Thread::LocalStorageKey WorkerThreadRuntimeCallStats::GetKey() { - base::MutexGuard lock(&mutex_); - DCHECK(TracingFlags::is_runtime_stats_enabled()); - if (!tls_key_) tls_key_ = base::Thread::CreateThreadLocalKey(); - return *tls_key_; -} - -RuntimeCallStats* WorkerThreadRuntimeCallStats::NewTable() { - DCHECK(TracingFlags::is_runtime_stats_enabled()); - // Never create a new worker table on the isolate's main thread. - DCHECK_NE(ThreadId::Current(), isolate_thread_id_); - std::unique_ptr<RuntimeCallStats> new_table = - std::make_unique<RuntimeCallStats>(RuntimeCallStats::kWorkerThread); - RuntimeCallStats* result = new_table.get(); - - base::MutexGuard lock(&mutex_); - tables_.push_back(std::move(new_table)); - return result; -} - -void WorkerThreadRuntimeCallStats::AddToMainTable( - RuntimeCallStats* main_call_stats) { - base::MutexGuard lock(&mutex_); - for (auto& worker_stats : tables_) { - DCHECK_NE(main_call_stats, worker_stats.get()); - main_call_stats->Add(worker_stats.get()); - worker_stats->Reset(); - } -} - -WorkerThreadRuntimeCallStatsScope::WorkerThreadRuntimeCallStatsScope( - WorkerThreadRuntimeCallStats* worker_stats) - : table_(nullptr) { - if (V8_LIKELY(!TracingFlags::is_runtime_stats_enabled())) return; - - table_ = reinterpret_cast<RuntimeCallStats*>( - base::Thread::GetThreadLocal(worker_stats->GetKey())); - if (table_ == nullptr) { - table_ = worker_stats->NewTable(); - base::Thread::SetThreadLocal(worker_stats->GetKey(), table_); - } - - if ((TracingFlags::runtime_stats.load(std::memory_order_relaxed) & - v8::tracing::TracingCategoryObserver::ENABLED_BY_TRACING)) { - table_->Reset(); - } -} - -WorkerThreadRuntimeCallStatsScope::~WorkerThreadRuntimeCallStatsScope() { - if (V8_LIKELY(table_ == nullptr)) return; - - if ((TracingFlags::runtime_stats.load(std::memory_order_relaxed) & - v8::tracing::TracingCategoryObserver::ENABLED_BY_TRACING)) { - auto value = v8::tracing::TracedValue::Create(); - table_->Dump(value.get()); - TRACE_EVENT_INSTANT1(TRACE_DISABLED_BY_DEFAULT("v8.runtime_stats"), - "V8.RuntimeStats", TRACE_EVENT_SCOPE_THREAD, - "runtime-call-stats", std::move(value)); - } -} - } // namespace internal } // namespace v8 |