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
14namespace v8 {
15namespace internal {
16
17StatsTable::StatsTable()
18    : lookup_function_(NULL),
19      create_histogram_function_(NULL),
20      add_histogram_sample_function_(NULL) {}
21
22
23int* StatsCounter::FindLocationInStatsTable() const {
24  return isolate_->stats_table()->FindLocation(name_);
25}
26
27
28void Histogram::AddSample(int sample) {
29  if (Enabled()) {
30    isolate()->stats_table()->AddHistogramSample(histogram_, sample);
31  }
32}
33
34void* Histogram::CreateHistogram() const {
35  return isolate()->stats_table()->
36      CreateHistogram(name_, min_, max_, num_buckets_);
37}
38
39
40// Start the timer.
41void 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.
50void 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
63Counters::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
145void 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
177void 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
199class RuntimeCallStatEntries {
200 public:
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.
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:
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
236    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
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
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
276void RuntimeCallCounter::Reset() {
277  count_ = 0;
278  time_ = base::TimeDelta();
279}
280
281void RuntimeCallCounter::Dump(v8::tracing::TracedValue* value) {
282  value->BeginArray(name_);
283  value->AppendDouble(count_);
284  value->AppendDouble(time_.InMicroseconds());
285  value->EndArray();
286}
287
288void RuntimeCallCounter::Add(RuntimeCallCounter* other) {
289  count_ += other->count();
290  time_ += other->time();
291}
292
293void 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
307const 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
327const int RuntimeCallStats::counters_count =
328    arraysize(RuntimeCallStats::counters);
329
330// static
331void 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
340void 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
354void 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
364void 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
372void 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
385void 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
405void 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