1// Copyright 2012 the V8 project authors. All rights reserved.
2// Use of this source code is governed by a BSD-style license that can be
3// found in the LICENSE file.
4
5#include "src/counters.h"
6
7#include <iomanip>
8
9#include "src/base/platform/platform.h"
10#include "src/builtins/builtins-definitions.h"
11#include "src/counters-inl.h"
12#include "src/isolate.h"
13#include "src/log-inl.h"
14#include "src/log.h"
15#include "src/ostreams.h"
16
17namespace v8 {
18namespace internal {
19
20std::atomic_uint TracingFlags::runtime_stats{0};
21std::atomic_uint TracingFlags::gc_stats{0};
22std::atomic_uint TracingFlags::ic_stats{0};
23
24StatsTable::StatsTable(Counters* counters)
25 : lookup_function_(nullptr),
26 create_histogram_function_(nullptr),
27 add_histogram_sample_function_(nullptr) {}
28
29void StatsTable::SetCounterFunction(CounterLookupCallback f) {
30 lookup_function_ = f;
31}
32
33int* StatsCounterBase::FindLocationInStatsTable() const {
34 return counters_->FindLocation(name_);
35}
36
37StatsCounterThreadSafe::StatsCounterThreadSafe(Counters* counters,
38 const char* name)
39 : StatsCounterBase(counters, name) {}
40
41void StatsCounterThreadSafe::Set(int Value) {
42 if (ptr_) {
43 base::MutexGuard Guard(&mutex_);
44 SetLoc(ptr_, Value);
45 }
46}
47
48void StatsCounterThreadSafe::Increment() {
49 if (ptr_) {
50 base::MutexGuard Guard(&mutex_);
51 IncrementLoc(ptr_);
52 }
53}
54
55void StatsCounterThreadSafe::Increment(int value) {
56 if (ptr_) {
57 base::MutexGuard Guard(&mutex_);
58 IncrementLoc(ptr_, value);
59 }
60}
61
62void StatsCounterThreadSafe::Decrement() {
63 if (ptr_) {
64 base::MutexGuard Guard(&mutex_);
65 DecrementLoc(ptr_);
66 }
67}
68
69void StatsCounterThreadSafe::Decrement(int value) {
70 if (ptr_) {
71 base::MutexGuard Guard(&mutex_);
72 DecrementLoc(ptr_, value);
73 }
74}
75
76void Histogram::AddSample(int sample) {
77 if (Enabled()) {
78 counters_->AddHistogramSample(histogram_, sample);
79 }
80}
81
82void* Histogram::CreateHistogram() const {
83 return counters_->CreateHistogram(name_, min_, max_, num_buckets_);
84}
85
86void TimedHistogram::Start(base::ElapsedTimer* timer, Isolate* isolate) {
87 if (Enabled()) timer->Start();
88 if (isolate) Logger::CallEventLogger(isolate, name(), Logger::START, true);
89}
90
91void TimedHistogram::Stop(base::ElapsedTimer* timer, Isolate* isolate) {
92 if (Enabled()) {
93 int64_t sample = resolution_ == HistogramTimerResolution::MICROSECOND
94 ? timer->Elapsed().InMicroseconds()
95 : timer->Elapsed().InMilliseconds();
96 timer->Stop();
97 AddSample(static_cast<int>(sample));
98 }
99 if (isolate != nullptr) {
100 Logger::CallEventLogger(isolate, name(), Logger::END, true);
101 }
102}
103
104void TimedHistogram::RecordAbandon(base::ElapsedTimer* timer,
105 Isolate* isolate) {
106 if (Enabled()) {
107 DCHECK(timer->IsStarted());
108 timer->Stop();
109 int64_t sample = resolution_ == HistogramTimerResolution::MICROSECOND
110 ? base::TimeDelta::Max().InMicroseconds()
111 : base::TimeDelta::Max().InMilliseconds();
112 AddSample(static_cast<int>(sample));
113 }
114 if (isolate != nullptr) {
115 Logger::CallEventLogger(isolate, name(), Logger::END, true);
116 }
117}
118
119Counters::Counters(Isolate* isolate)
120 : isolate_(isolate),
121 stats_table_(this),
122// clang format off
123#define SC(name, caption) name##_(this, "c:" #caption),
124 STATS_COUNTER_TS_LIST(SC)
125#undef SC
126 // clang format on
127 runtime_call_stats_(),
128 worker_thread_runtime_call_stats_() {
129 static const struct {
130 Histogram Counters::*member;
131 const char* caption;
132 int min;
133 int max;
134 int num_buckets;
135 } kHistograms[] = {
136#define HR(name, caption, min, max, num_buckets) \
137 {&Counters::name##_, #caption, min, max, num_buckets},
138 HISTOGRAM_RANGE_LIST(HR)
139#undef HR
140 };
141 for (const auto& histogram : kHistograms) {
142 this->*histogram.member =
143 Histogram(histogram.caption, histogram.min, histogram.max,
144 histogram.num_buckets, this);
145 }
146
147 const int DefaultTimedHistogramNumBuckets = 50;
148
149 static const struct {
150 HistogramTimer Counters::*member;
151 const char* caption;
152 int max;
153 HistogramTimerResolution res;
154 } kHistogramTimers[] = {
155#define HT(name, caption, max, res) \
156 {&Counters::name##_, #caption, max, HistogramTimerResolution::res},
157 HISTOGRAM_TIMER_LIST(HT)
158#undef HT
159 };
160 for (const auto& timer : kHistogramTimers) {
161 this->*timer.member = HistogramTimer(timer.caption, 0, timer.max, timer.res,
162 DefaultTimedHistogramNumBuckets, this);
163 }
164
165 static const struct {
166 TimedHistogram Counters::*member;
167 const char* caption;
168 int max;
169 HistogramTimerResolution res;
170 } kTimedHistograms[] = {
171#define HT(name, caption, max, res) \
172 {&Counters::name##_, #caption, max, HistogramTimerResolution::res},
173 TIMED_HISTOGRAM_LIST(HT)
174#undef HT
175 };
176 for (const auto& timer : kTimedHistograms) {
177 this->*timer.member = TimedHistogram(timer.caption, 0, timer.max, timer.res,
178 DefaultTimedHistogramNumBuckets, this);
179 }
180
181 static const struct {
182 AggregatableHistogramTimer Counters::*member;
183 const char* caption;
184 } kAggregatableHistogramTimers[] = {
185#define AHT(name, caption) {&Counters::name##_, #caption},
186 AGGREGATABLE_HISTOGRAM_TIMER_LIST(AHT)
187#undef AHT
188 };
189 for (const auto& aht : kAggregatableHistogramTimers) {
190 this->*aht.member = AggregatableHistogramTimer(
191 aht.caption, 0, 10000000, DefaultTimedHistogramNumBuckets, this);
192 }
193
194 static const struct {
195 Histogram Counters::*member;
196 const char* caption;
197 } kHistogramPercentages[] = {
198#define HP(name, caption) {&Counters::name##_, #caption},
199 HISTOGRAM_PERCENTAGE_LIST(HP)
200#undef HP
201 };
202 for (const auto& percentage : kHistogramPercentages) {
203 this->*percentage.member = Histogram(percentage.caption, 0, 101, 100, this);
204 }
205
206 // Exponential histogram assigns bucket limits to points
207 // p[1], p[2], ... p[n] such that p[i+1] / p[i] = constant.
208 // The constant factor is equal to the n-th root of (high / low),
209 // where the n is the number of buckets, the low is the lower limit,
210 // the high is the upper limit.
211 // For n = 50, low = 1000, high = 500000: the factor = 1.13.
212 static const struct {
213 Histogram Counters::*member;
214 const char* caption;
215 } kLegacyMemoryHistograms[] = {
216#define HM(name, caption) {&Counters::name##_, #caption},
217 HISTOGRAM_LEGACY_MEMORY_LIST(HM)
218#undef HM
219 };
220 for (const auto& histogram : kLegacyMemoryHistograms) {
221 this->*histogram.member =
222 Histogram(histogram.caption, 1000, 500000, 50, this);
223 }
224
225 // clang-format off
226 static const struct {
227 StatsCounter Counters::*member;
228 const char* caption;
229 } kStatsCounters[] = {
230#define SC(name, caption) {&Counters::name##_, "c:" #caption},
231 STATS_COUNTER_LIST_1(SC)
232 STATS_COUNTER_LIST_2(SC)
233 STATS_COUNTER_NATIVE_CODE_LIST(SC)
234#undef SC
235#define SC(name) \
236 {&Counters::count_of_##name##_, "c:" "V8.CountOf_" #name}, \
237 {&Counters::size_of_##name##_, "c:" "V8.SizeOf_" #name},
238 INSTANCE_TYPE_LIST(SC)
239#undef SC
240#define SC(name) \
241 {&Counters::count_of_CODE_TYPE_##name##_, \
242 "c:" "V8.CountOf_CODE_TYPE-" #name}, \
243 {&Counters::size_of_CODE_TYPE_##name##_, \
244 "c:" "V8.SizeOf_CODE_TYPE-" #name},
245 CODE_KIND_LIST(SC)
246#undef SC
247#define SC(name) \
248 {&Counters::count_of_FIXED_ARRAY_##name##_, \
249 "c:" "V8.CountOf_FIXED_ARRAY-" #name}, \
250 {&Counters::size_of_FIXED_ARRAY_##name##_, \
251 "c:" "V8.SizeOf_FIXED_ARRAY-" #name},
252 FIXED_ARRAY_SUB_INSTANCE_TYPE_LIST(SC)
253#undef SC
254 };
255 // clang-format on
256 for (const auto& counter : kStatsCounters) {
257 this->*counter.member = StatsCounter(this, counter.caption);
258 }
259}
260
261void Counters::ResetCounterFunction(CounterLookupCallback f) {
262 stats_table_.SetCounterFunction(f);
263
264#define SC(name, caption) name##_.Reset();
265 STATS_COUNTER_LIST_1(SC)
266 STATS_COUNTER_LIST_2(SC)
267 STATS_COUNTER_TS_LIST(SC)
268 STATS_COUNTER_NATIVE_CODE_LIST(SC)
269#undef SC
270
271#define SC(name) \
272 count_of_##name##_.Reset(); \
273 size_of_##name##_.Reset();
274 INSTANCE_TYPE_LIST(SC)
275#undef SC
276
277#define SC(name) \
278 count_of_CODE_TYPE_##name##_.Reset(); \
279 size_of_CODE_TYPE_##name##_.Reset();
280 CODE_KIND_LIST(SC)
281#undef SC
282
283#define SC(name) \
284 count_of_FIXED_ARRAY_##name##_.Reset(); \
285 size_of_FIXED_ARRAY_##name##_.Reset();
286 FIXED_ARRAY_SUB_INSTANCE_TYPE_LIST(SC)
287#undef SC
288}
289
290void Counters::ResetCreateHistogramFunction(CreateHistogramCallback f) {
291 stats_table_.SetCreateHistogramFunction(f);
292
293#define HR(name, caption, min, max, num_buckets) name##_.Reset();
294 HISTOGRAM_RANGE_LIST(HR)
295#undef HR
296
297#define HT(name, caption, max, res) name##_.Reset();
298 HISTOGRAM_TIMER_LIST(HT)
299#undef HT
300
301#define HT(name, caption, max, res) name##_.Reset();
302 TIMED_HISTOGRAM_LIST(HT)
303#undef HT
304
305#define AHT(name, caption) name##_.Reset();
306 AGGREGATABLE_HISTOGRAM_TIMER_LIST(AHT)
307#undef AHT
308
309#define HP(name, caption) name##_.Reset();
310 HISTOGRAM_PERCENTAGE_LIST(HP)
311#undef HP
312
313#define HM(name, caption) name##_.Reset();
314 HISTOGRAM_LEGACY_MEMORY_LIST(HM)
315#undef HM
316}
317
318base::TimeTicks (*RuntimeCallTimer::Now)() =
319 &base::TimeTicks::HighResolutionNow;
320
321class RuntimeCallStatEntries {
322 public:
323 void Print(std::ostream& os) {
324 if (total_call_count == 0) return;
325 std::sort(entries.rbegin(), entries.rend());
326 os << std::setw(50) << "Runtime Function/C++ Builtin" << std::setw(12)
327 << "Time" << std::setw(18) << "Count" << std::endl
328 << std::string(88, '=') << std::endl;
329 for (Entry& entry : entries) {
330 entry.SetTotal(total_time, total_call_count);
331 entry.Print(os);
332 }
333 os << std::string(88, '-') << std::endl;
334 Entry("Total", total_time, total_call_count).Print(os);
335 }
336
337 // By default, the compiler will usually inline this, which results in a large
338 // binary size increase: std::vector::push_back expands to a large amount of
339 // instructions, and this function is invoked repeatedly by macros.
340 V8_NOINLINE void Add(RuntimeCallCounter* counter) {
341 if (counter->count() == 0) return;
342 entries.push_back(
343 Entry(counter->name(), counter->time(), counter->count()));
344 total_time += counter->time();
345 total_call_count += counter->count();
346 }
347
348 private:
349 class Entry {
350 public:
351 Entry(const char* name, base::TimeDelta time, uint64_t count)
352 : name_(name),
353 time_(time.InMicroseconds()),
354 count_(count),
355 time_percent_(100),
356 count_percent_(100) {}
357
358 bool operator<(const Entry& other) const {
359 if (time_ < other.time_) return true;
360 if (time_ > other.time_) return false;
361 return count_ < other.count_;
362 }
363
364 V8_NOINLINE void Print(std::ostream& os) {
365 os.precision(2);
366 os << std::fixed << std::setprecision(2);
367 os << std::setw(50) << name_;
368 os << std::setw(10) << static_cast<double>(time_) / 1000 << "ms ";
369 os << std::setw(6) << time_percent_ << "%";
370 os << std::setw(10) << count_ << " ";
371 os << std::setw(6) << count_percent_ << "%";
372 os << std::endl;
373 }
374
375 V8_NOINLINE void SetTotal(base::TimeDelta total_time,
376 uint64_t total_count) {
377 if (total_time.InMicroseconds() == 0) {
378 time_percent_ = 0;
379 } else {
380 time_percent_ = 100.0 * time_ / total_time.InMicroseconds();
381 }
382 count_percent_ = 100.0 * count_ / total_count;
383 }
384
385 private:
386 const char* name_;
387 int64_t time_;
388 uint64_t count_;
389 double time_percent_;
390 double count_percent_;
391 };
392
393 uint64_t total_call_count = 0;
394 base::TimeDelta total_time;
395 std::vector<Entry> entries;
396};
397
398void RuntimeCallCounter::Reset() {
399 count_ = 0;
400 time_ = 0;
401}
402
403void RuntimeCallCounter::Dump(v8::tracing::TracedValue* value) {
404 value->BeginArray(name_);
405 value->AppendDouble(count_);
406 value->AppendDouble(time_);
407 value->EndArray();
408}
409
410void RuntimeCallCounter::Add(RuntimeCallCounter* other) {
411 count_ += other->count();
412 time_ += other->time().InMicroseconds();
413}
414
415void RuntimeCallTimer::Snapshot() {
416 base::TimeTicks now = Now();
417 // Pause only / topmost timer in the timer stack.
418 Pause(now);
419 // Commit all the timer's elapsed time to the counters.
420 RuntimeCallTimer* timer = this;
421 while (timer != nullptr) {
422 timer->CommitTimeToCounter();
423 timer = timer->parent();
424 }
425 Resume(now);
426}
427
428RuntimeCallStats::RuntimeCallStats() : in_use_(false) {
429 static const char* const kNames[] = {
430#define CALL_BUILTIN_COUNTER(name) "GC_" #name,
431 FOR_EACH_GC_COUNTER(CALL_BUILTIN_COUNTER) //
432#undef CALL_BUILTIN_COUNTER
433#define CALL_RUNTIME_COUNTER(name) #name,
434 FOR_EACH_MANUAL_COUNTER(CALL_RUNTIME_COUNTER) //
435#undef CALL_RUNTIME_COUNTER
436#define CALL_RUNTIME_COUNTER(name, nargs, ressize) #name,
437 FOR_EACH_INTRINSIC(CALL_RUNTIME_COUNTER) //
438#undef CALL_RUNTIME_COUNTER
439#define CALL_BUILTIN_COUNTER(name) #name,
440 BUILTIN_LIST_C(CALL_BUILTIN_COUNTER) //
441#undef CALL_BUILTIN_COUNTER
442#define CALL_BUILTIN_COUNTER(name) "API_" #name,
443 FOR_EACH_API_COUNTER(CALL_BUILTIN_COUNTER) //
444#undef CALL_BUILTIN_COUNTER
445#define CALL_BUILTIN_COUNTER(name) #name,
446 FOR_EACH_HANDLER_COUNTER(CALL_BUILTIN_COUNTER) //
447#undef CALL_BUILTIN_COUNTER
448 };
449 for (int i = 0; i < kNumberOfCounters; i++) {
450 this->counters_[i] = RuntimeCallCounter(kNames[i]);
451 }
452}
453
454void RuntimeCallStats::Enter(RuntimeCallTimer* timer,
455 RuntimeCallCounterId counter_id) {
456 DCHECK(IsCalledOnTheSameThread());
457 RuntimeCallCounter* counter = GetCounter(counter_id);
458 DCHECK_NOT_NULL(counter->name());
459 timer->Start(counter, current_timer());
460 current_timer_.SetValue(timer);
461 current_counter_.SetValue(counter);
462}
463
464void RuntimeCallStats::Leave(RuntimeCallTimer* timer) {
465 DCHECK(IsCalledOnTheSameThread());
466 RuntimeCallTimer* stack_top = current_timer();
467 if (stack_top == nullptr) return; // Missing timer is a result of Reset().
468 CHECK(stack_top == timer);
469 current_timer_.SetValue(timer->Stop());
470 RuntimeCallTimer* cur_timer = current_timer();
471 current_counter_.SetValue(cur_timer ? cur_timer->counter() : nullptr);
472}
473
474void RuntimeCallStats::Add(RuntimeCallStats* other) {
475 for (int i = 0; i < kNumberOfCounters; i++) {
476 GetCounter(i)->Add(other->GetCounter(i));
477 }
478}
479
480// static
481void RuntimeCallStats::CorrectCurrentCounterId(
482 RuntimeCallCounterId counter_id) {
483 DCHECK(IsCalledOnTheSameThread());
484 RuntimeCallTimer* timer = current_timer();
485 if (timer == nullptr) return;
486 RuntimeCallCounter* counter = GetCounter(counter_id);
487 timer->set_counter(counter);
488 current_counter_.SetValue(counter);
489}
490
491bool RuntimeCallStats::IsCalledOnTheSameThread() {
492 if (thread_id_.IsValid()) return thread_id_ == ThreadId::Current();
493 thread_id_ = ThreadId::Current();
494 return true;
495}
496
497void RuntimeCallStats::Print() {
498 StdoutStream os;
499 Print(os);
500}
501
502void RuntimeCallStats::Print(std::ostream& os) {
503 RuntimeCallStatEntries entries;
504 if (current_timer_.Value() != nullptr) {
505 current_timer_.Value()->Snapshot();
506 }
507 for (int i = 0; i < kNumberOfCounters; i++) {
508 entries.Add(GetCounter(i));
509 }
510 entries.Print(os);
511}
512
513void RuntimeCallStats::Reset() {
514 if (V8_LIKELY(!TracingFlags::is_runtime_stats_enabled())) return;
515
516 // In tracing, we only what to trace the time spent on top level trace events,
517 // if runtime counter stack is not empty, we should clear the whole runtime
518 // counter stack, and then reset counters so that we can dump counters into
519 // top level trace events accurately.
520 while (current_timer_.Value()) {
521 current_timer_.SetValue(current_timer_.Value()->Stop());
522 }
523
524 for (int i = 0; i < kNumberOfCounters; i++) {
525 GetCounter(i)->Reset();
526 }
527
528 in_use_ = true;
529}
530
531void RuntimeCallStats::Dump(v8::tracing::TracedValue* value) {
532 for (int i = 0; i < kNumberOfCounters; i++) {
533 if (GetCounter(i)->count() > 0) GetCounter(i)->Dump(value);
534 }
535 in_use_ = false;
536}
537
538WorkerThreadRuntimeCallStats::WorkerThreadRuntimeCallStats() {}
539
540WorkerThreadRuntimeCallStats::~WorkerThreadRuntimeCallStats() {
541 if (tls_key_) base::Thread::DeleteThreadLocalKey(*tls_key_);
542}
543
544base::Thread::LocalStorageKey WorkerThreadRuntimeCallStats::GetKey() {
545 DCHECK(TracingFlags::is_runtime_stats_enabled());
546 if (!tls_key_) tls_key_ = base::Thread::CreateThreadLocalKey();
547 return *tls_key_;
548}
549
550RuntimeCallStats* WorkerThreadRuntimeCallStats::NewTable() {
551 DCHECK(TracingFlags::is_runtime_stats_enabled());
552 std::unique_ptr<RuntimeCallStats> new_table =
553 base::make_unique<RuntimeCallStats>();
554 RuntimeCallStats* result = new_table.get();
555
556 base::MutexGuard lock(&mutex_);
557 tables_.push_back(std::move(new_table));
558 return result;
559}
560
561void WorkerThreadRuntimeCallStats::AddToMainTable(
562 RuntimeCallStats* main_call_stats) {
563 base::MutexGuard lock(&mutex_);
564 for (auto& worker_stats : tables_) {
565 DCHECK_NE(main_call_stats, worker_stats.get());
566 main_call_stats->Add(worker_stats.get());
567 worker_stats->Reset();
568 }
569}
570
571WorkerThreadRuntimeCallStatsScope::WorkerThreadRuntimeCallStatsScope(
572 WorkerThreadRuntimeCallStats* worker_stats)
573 : table_(nullptr) {
574 if (V8_LIKELY(!TracingFlags::is_runtime_stats_enabled())) return;
575
576 table_ = reinterpret_cast<RuntimeCallStats*>(
577 base::Thread::GetThreadLocal(worker_stats->GetKey()));
578 if (table_ == nullptr) {
579 table_ = worker_stats->NewTable();
580 base::Thread::SetThreadLocal(worker_stats->GetKey(), table_);
581 }
582
583 if ((TracingFlags::runtime_stats.load(std::memory_order_relaxed) &
584 v8::tracing::TracingCategoryObserver::ENABLED_BY_TRACING)) {
585 table_->Reset();
586 }
587}
588
589WorkerThreadRuntimeCallStatsScope::~WorkerThreadRuntimeCallStatsScope() {
590 if (V8_LIKELY(table_ == nullptr)) return;
591
592 if ((TracingFlags::runtime_stats.load(std::memory_order_relaxed) &
593 v8::tracing::TracingCategoryObserver::ENABLED_BY_TRACING)) {
594 auto value = v8::tracing::TracedValue::Create();
595 table_->Dump(value.get());
596 TRACE_EVENT_INSTANT1(TRACE_DISABLED_BY_DEFAULT("v8.runtime_stats"),
597 "V8.RuntimeStats", TRACE_EVENT_SCOPE_THREAD,
598 "runtime-call-stats", std::move(value));
599 }
600}
601
602} // namespace internal
603} // namespace v8
604