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