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