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(Entry(counter->name, counter->time, counter->count));
221     total_time += counter->time;
222     total_call_count += counter->count;
223   }
224 
225  private:
226   class Entry {
227    public:
Entry(const char * name,base::TimeDelta time,uint64_t count)228     Entry(const char* name, base::TimeDelta time, uint64_t count)
229         : name_(name),
230           time_(time.InMicroseconds()),
231           count_(count),
232           time_percent_(100),
233           count_percent_(100) {}
234 
operator <(const Entry & other) const235     bool operator<(const Entry& other) const {
236       if (time_ < other.time_) return true;
237       if (time_ > other.time_) return false;
238       return count_ < other.count_;
239     }
240 
Print(std::ostream & os)241     V8_NOINLINE void Print(std::ostream& os) {
242       os.precision(2);
243       os << std::fixed << std::setprecision(2);
244       os << std::setw(50) << name_;
245       os << std::setw(10) << static_cast<double>(time_) / 1000 << "ms ";
246       os << std::setw(6) << time_percent_ << "%";
247       os << std::setw(10) << count_ << " ";
248       os << std::setw(6) << count_percent_ << "%";
249       os << std::endl;
250     }
251 
SetTotal(base::TimeDelta total_time,uint64_t total_count)252     V8_NOINLINE void SetTotal(base::TimeDelta total_time,
253                               uint64_t total_count) {
254       if (total_time.InMicroseconds() == 0) {
255         time_percent_ = 0;
256       } else {
257         time_percent_ = 100.0 * time_ / total_time.InMicroseconds();
258       }
259       count_percent_ = 100.0 * count_ / total_count;
260     }
261 
262    private:
263     const char* name_;
264     int64_t time_;
265     uint64_t count_;
266     double time_percent_;
267     double count_percent_;
268   };
269 
270   uint64_t total_call_count = 0;
271   base::TimeDelta total_time;
272   std::vector<Entry> entries;
273 };
274 
Reset()275 void RuntimeCallCounter::Reset() {
276   count = 0;
277   time = base::TimeDelta();
278 }
279 
Dump(v8::tracing::TracedValue * value)280 void RuntimeCallCounter::Dump(v8::tracing::TracedValue* value) {
281   value->BeginArray(name);
282   value->AppendLongInteger(count);
283   value->AppendLongInteger(time.InMicroseconds());
284   value->EndArray();
285 }
286 
Add(RuntimeCallCounter * other)287 void RuntimeCallCounter::Add(RuntimeCallCounter* other) {
288   count += other->count;
289   time += other->time;
290 }
291 
292 // static
293 const RuntimeCallStats::CounterId RuntimeCallStats::counters[] = {
294 #define CALL_RUNTIME_COUNTER(name) &RuntimeCallStats::name,
295     FOR_EACH_MANUAL_COUNTER(CALL_RUNTIME_COUNTER)  //
296 #undef CALL_RUNTIME_COUNTER
297 #define CALL_RUNTIME_COUNTER(name, nargs, ressize) \
298   &RuntimeCallStats::Runtime_##name,          //
299     FOR_EACH_INTRINSIC(CALL_RUNTIME_COUNTER)  //
300 #undef CALL_RUNTIME_COUNTER
301 #define CALL_BUILTIN_COUNTER(name) &RuntimeCallStats::Builtin_##name,
302     BUILTIN_LIST_C(CALL_BUILTIN_COUNTER)  //
303 #undef CALL_BUILTIN_COUNTER
304 #define CALL_BUILTIN_COUNTER(name) &RuntimeCallStats::API_##name,
305     FOR_EACH_API_COUNTER(CALL_BUILTIN_COUNTER)  //
306 #undef CALL_BUILTIN_COUNTER
307 #define CALL_BUILTIN_COUNTER(name) &RuntimeCallStats::Handler_##name,
308     FOR_EACH_HANDLER_COUNTER(CALL_BUILTIN_COUNTER)
309 #undef CALL_BUILTIN_COUNTER
310 };
311 
312 // static
Enter(RuntimeCallStats * stats,RuntimeCallTimer * timer,CounterId counter_id)313 void RuntimeCallStats::Enter(RuntimeCallStats* stats, RuntimeCallTimer* timer,
314                              CounterId counter_id) {
315   RuntimeCallCounter* counter = &(stats->*counter_id);
316   DCHECK(counter->name != nullptr);
317   timer->Start(counter, stats->current_timer_.Value());
318   stats->current_timer_.SetValue(timer);
319 }
320 
321 // static
Leave(RuntimeCallStats * stats,RuntimeCallTimer * timer)322 void RuntimeCallStats::Leave(RuntimeCallStats* stats, RuntimeCallTimer* timer) {
323   if (stats->current_timer_.Value() == timer) {
324     stats->current_timer_.SetValue(timer->Stop());
325   } else {
326     // Must be a Threading cctest. Walk the chain of Timers to find the
327     // buried one that's leaving. We don't care about keeping nested timings
328     // accurate, just avoid crashing by keeping the chain intact.
329     RuntimeCallTimer* next = stats->current_timer_.Value();
330     while (next && next->parent() != timer) next = next->parent();
331     if (next == nullptr) return;
332     next->parent_.SetValue(timer->Stop());
333   }
334 }
335 
Add(RuntimeCallStats * other)336 void RuntimeCallStats::Add(RuntimeCallStats* other) {
337   for (const RuntimeCallStats::CounterId counter_id :
338        RuntimeCallStats::counters) {
339     RuntimeCallCounter* counter = &(this->*counter_id);
340     RuntimeCallCounter* other_counter = &(other->*counter_id);
341     counter->Add(other_counter);
342   }
343 }
344 
345 // static
CorrectCurrentCounterId(RuntimeCallStats * stats,CounterId counter_id)346 void RuntimeCallStats::CorrectCurrentCounterId(RuntimeCallStats* stats,
347                                                CounterId counter_id) {
348   RuntimeCallTimer* timer = stats->current_timer_.Value();
349   // When RCS are enabled dynamically there might be no current timer set up.
350   if (timer == nullptr) return;
351   timer->counter_ = &(stats->*counter_id);
352 }
353 
Print(std::ostream & os)354 void RuntimeCallStats::Print(std::ostream& os) {
355   RuntimeCallStatEntries entries;
356   if (current_timer_.Value() != nullptr) {
357     current_timer_.Value()->Elapsed();
358   }
359   for (const RuntimeCallStats::CounterId counter_id :
360        RuntimeCallStats::counters) {
361     RuntimeCallCounter* counter = &(this->*counter_id);
362     entries.Add(counter);
363   }
364   entries.Print(os);
365 }
366 
Reset()367 void RuntimeCallStats::Reset() {
368   if (V8_LIKELY(FLAG_runtime_stats == 0)) return;
369 
370   // In tracing, we only what to trace the time spent on top level trace events,
371   // if runtime counter stack is not empty, we should clear the whole runtime
372   // counter stack, and then reset counters so that we can dump counters into
373   // top level trace events accurately.
374   while (current_timer_.Value()) {
375     current_timer_.SetValue(current_timer_.Value()->Stop());
376   }
377 
378   for (const RuntimeCallStats::CounterId counter_id :
379        RuntimeCallStats::counters) {
380     RuntimeCallCounter* counter = &(this->*counter_id);
381     counter->Reset();
382   }
383 
384   in_use_ = true;
385 }
386 
Dump(v8::tracing::TracedValue * value)387 void RuntimeCallStats::Dump(v8::tracing::TracedValue* value) {
388   for (const RuntimeCallStats::CounterId counter_id :
389        RuntimeCallStats::counters) {
390     RuntimeCallCounter* counter = &(this->*counter_id);
391     if (counter->count > 0) counter->Dump(value);
392   }
393 
394   in_use_ = false;
395 }
396 
397 }  // namespace internal
398 }  // namespace v8
399