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