• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
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   // clang-format off
219   static const struct {
220     StatsCounter Counters::*member;
221     const char* caption;
222   } kStatsCounters[] = {
223 #define SC(name, caption) {&Counters::name##_, "c:" #caption},
224       STATS_COUNTER_LIST_1(SC) STATS_COUNTER_LIST_2(SC)
225 #undef SC
226 #define SC(name)                                             \
227   {&Counters::count_of_##name##_, "c:" "V8.CountOf_" #name}, \
228   {&Counters::size_of_##name##_, "c:" "V8.SizeOf_" #name},
229       INSTANCE_TYPE_LIST(SC)
230 #undef SC
231 #define SC(name)                            \
232   {&Counters::count_of_CODE_TYPE_##name##_, \
233     "c:" "V8.CountOf_CODE_TYPE-" #name},     \
234   {&Counters::size_of_CODE_TYPE_##name##_,  \
235     "c:" "V8.SizeOf_CODE_TYPE-" #name},
236       CODE_KIND_LIST(SC)
237 #undef SC
238 #define SC(name)                              \
239   {&Counters::count_of_FIXED_ARRAY_##name##_, \
240     "c:" "V8.CountOf_FIXED_ARRAY-" #name},     \
241   {&Counters::size_of_FIXED_ARRAY_##name##_,  \
242     "c:" "V8.SizeOf_FIXED_ARRAY-" #name},
243       FIXED_ARRAY_SUB_INSTANCE_TYPE_LIST(SC)
244 #undef SC
245   };
246   // clang-format on
247   for (const auto& counter : kStatsCounters) {
248     this->*counter.member = StatsCounter(this, counter.caption);
249   }
250 }
251 
ResetCounterFunction(CounterLookupCallback f)252 void Counters::ResetCounterFunction(CounterLookupCallback f) {
253   stats_table_.SetCounterFunction(f);
254 
255 #define SC(name, caption) name##_.Reset();
256   STATS_COUNTER_LIST_1(SC)
257   STATS_COUNTER_LIST_2(SC)
258 #undef SC
259 
260 #define SC(name, caption) name##_.Reset();
261   STATS_COUNTER_TS_LIST(SC)
262 #undef SC
263 
264 #define SC(name)              \
265   count_of_##name##_.Reset(); \
266   size_of_##name##_.Reset();
267   INSTANCE_TYPE_LIST(SC)
268 #undef SC
269 
270 #define SC(name)                        \
271   count_of_CODE_TYPE_##name##_.Reset(); \
272   size_of_CODE_TYPE_##name##_.Reset();
273   CODE_KIND_LIST(SC)
274 #undef SC
275 
276 #define SC(name)                          \
277   count_of_FIXED_ARRAY_##name##_.Reset(); \
278   size_of_FIXED_ARRAY_##name##_.Reset();
279   FIXED_ARRAY_SUB_INSTANCE_TYPE_LIST(SC)
280 #undef SC
281 }
282 
ResetCreateHistogramFunction(CreateHistogramCallback f)283 void Counters::ResetCreateHistogramFunction(CreateHistogramCallback f) {
284   stats_table_.SetCreateHistogramFunction(f);
285 
286 #define HR(name, caption, min, max, num_buckets) name##_.Reset();
287   HISTOGRAM_RANGE_LIST(HR)
288 #undef HR
289 
290 #define HT(name, caption, max, res) name##_.Reset();
291     HISTOGRAM_TIMER_LIST(HT)
292 #undef HT
293 
294 #define HT(name, caption, max, res) name##_.Reset();
295     TIMED_HISTOGRAM_LIST(HT)
296 #undef HT
297 
298 #define AHT(name, caption) name##_.Reset();
299     AGGREGATABLE_HISTOGRAM_TIMER_LIST(AHT)
300 #undef AHT
301 
302 #define HP(name, caption) name##_.Reset();
303     HISTOGRAM_PERCENTAGE_LIST(HP)
304 #undef HP
305 
306 #define HM(name, caption) name##_.Reset();
307     HISTOGRAM_LEGACY_MEMORY_LIST(HM)
308 #undef HM
309 }
310 
311 base::TimeTicks (*RuntimeCallTimer::Now)() =
312     &base::TimeTicks::HighResolutionNow;
313 
314 class RuntimeCallStatEntries {
315  public:
Print(std::ostream & os)316   void Print(std::ostream& os) {
317     if (total_call_count == 0) return;
318     std::sort(entries.rbegin(), entries.rend());
319     os << std::setw(50) << "Runtime Function/C++ Builtin" << std::setw(12)
320        << "Time" << std::setw(18) << "Count" << std::endl
321        << std::string(88, '=') << std::endl;
322     for (Entry& entry : entries) {
323       entry.SetTotal(total_time, total_call_count);
324       entry.Print(os);
325     }
326     os << std::string(88, '-') << std::endl;
327     Entry("Total", total_time, total_call_count).Print(os);
328   }
329 
330   // By default, the compiler will usually inline this, which results in a large
331   // binary size increase: std::vector::push_back expands to a large amount of
332   // instructions, and this function is invoked repeatedly by macros.
Add(RuntimeCallCounter * counter)333   V8_NOINLINE void Add(RuntimeCallCounter* counter) {
334     if (counter->count() == 0) return;
335     entries.push_back(
336         Entry(counter->name(), counter->time(), counter->count()));
337     total_time += counter->time();
338     total_call_count += counter->count();
339   }
340 
341  private:
342   class Entry {
343    public:
Entry(const char * name,base::TimeDelta time,uint64_t count)344     Entry(const char* name, base::TimeDelta time, uint64_t count)
345         : name_(name),
346           time_(time.InMicroseconds()),
347           count_(count),
348           time_percent_(100),
349           count_percent_(100) {}
350 
operator <(const Entry & other) const351     bool operator<(const Entry& other) const {
352       if (time_ < other.time_) return true;
353       if (time_ > other.time_) return false;
354       return count_ < other.count_;
355     }
356 
Print(std::ostream & os)357     V8_NOINLINE void Print(std::ostream& os) {
358       os.precision(2);
359       os << std::fixed << std::setprecision(2);
360       os << std::setw(50) << name_;
361       os << std::setw(10) << static_cast<double>(time_) / 1000 << "ms ";
362       os << std::setw(6) << time_percent_ << "%";
363       os << std::setw(10) << count_ << " ";
364       os << std::setw(6) << count_percent_ << "%";
365       os << std::endl;
366     }
367 
SetTotal(base::TimeDelta total_time,uint64_t total_count)368     V8_NOINLINE void SetTotal(base::TimeDelta total_time,
369                               uint64_t total_count) {
370       if (total_time.InMicroseconds() == 0) {
371         time_percent_ = 0;
372       } else {
373         time_percent_ = 100.0 * time_ / total_time.InMicroseconds();
374       }
375       count_percent_ = 100.0 * count_ / total_count;
376     }
377 
378    private:
379     const char* name_;
380     int64_t time_;
381     uint64_t count_;
382     double time_percent_;
383     double count_percent_;
384   };
385 
386   uint64_t total_call_count = 0;
387   base::TimeDelta total_time;
388   std::vector<Entry> entries;
389 };
390 
Reset()391 void RuntimeCallCounter::Reset() {
392   count_ = 0;
393   time_ = 0;
394 }
395 
Dump(v8::tracing::TracedValue * value)396 void RuntimeCallCounter::Dump(v8::tracing::TracedValue* value) {
397   value->BeginArray(name_);
398   value->AppendDouble(count_);
399   value->AppendDouble(time_);
400   value->EndArray();
401 }
402 
Add(RuntimeCallCounter * other)403 void RuntimeCallCounter::Add(RuntimeCallCounter* other) {
404   count_ += other->count();
405   time_ += other->time().InMicroseconds();
406 }
407 
Snapshot()408 void RuntimeCallTimer::Snapshot() {
409   base::TimeTicks now = Now();
410   // Pause only / topmost timer in the timer stack.
411   Pause(now);
412   // Commit all the timer's elapsed time to the counters.
413   RuntimeCallTimer* timer = this;
414   while (timer != nullptr) {
415     timer->CommitTimeToCounter();
416     timer = timer->parent();
417   }
418   Resume(now);
419 }
420 
RuntimeCallStats()421 RuntimeCallStats::RuntimeCallStats() : in_use_(false) {
422   static const char* const kNames[] = {
423 #define CALL_BUILTIN_COUNTER(name) "GC_" #name,
424       FOR_EACH_GC_COUNTER(CALL_BUILTIN_COUNTER)  //
425 #undef CALL_BUILTIN_COUNTER
426 #define CALL_RUNTIME_COUNTER(name) #name,
427       FOR_EACH_MANUAL_COUNTER(CALL_RUNTIME_COUNTER)  //
428 #undef CALL_RUNTIME_COUNTER
429 #define CALL_RUNTIME_COUNTER(name, nargs, ressize) #name,
430       FOR_EACH_INTRINSIC(CALL_RUNTIME_COUNTER)  //
431 #undef CALL_RUNTIME_COUNTER
432 #define CALL_BUILTIN_COUNTER(name) #name,
433       BUILTIN_LIST_C(CALL_BUILTIN_COUNTER)  //
434 #undef CALL_BUILTIN_COUNTER
435 #define CALL_BUILTIN_COUNTER(name) "API_" #name,
436       FOR_EACH_API_COUNTER(CALL_BUILTIN_COUNTER)  //
437 #undef CALL_BUILTIN_COUNTER
438 #define CALL_BUILTIN_COUNTER(name) #name,
439       FOR_EACH_HANDLER_COUNTER(CALL_BUILTIN_COUNTER)  //
440 #undef CALL_BUILTIN_COUNTER
441   };
442   for (int i = 0; i < kNumberOfCounters; i++) {
443     this->counters_[i] = RuntimeCallCounter(kNames[i]);
444   }
445 }
446 
Enter(RuntimeCallTimer * timer,RuntimeCallCounterId counter_id)447 void RuntimeCallStats::Enter(RuntimeCallTimer* timer,
448                              RuntimeCallCounterId counter_id) {
449   DCHECK(IsCalledOnTheSameThread());
450   RuntimeCallCounter* counter = GetCounter(counter_id);
451   DCHECK_NOT_NULL(counter->name());
452   timer->Start(counter, current_timer());
453   current_timer_.SetValue(timer);
454   current_counter_.SetValue(counter);
455 }
456 
Leave(RuntimeCallTimer * timer)457 void RuntimeCallStats::Leave(RuntimeCallTimer* timer) {
458   DCHECK(IsCalledOnTheSameThread());
459   RuntimeCallTimer* stack_top = current_timer();
460   if (stack_top == nullptr) return;  // Missing timer is a result of Reset().
461   CHECK(stack_top == timer);
462   current_timer_.SetValue(timer->Stop());
463   RuntimeCallTimer* cur_timer = current_timer();
464   current_counter_.SetValue(cur_timer ? cur_timer->counter() : nullptr);
465 }
466 
Add(RuntimeCallStats * other)467 void RuntimeCallStats::Add(RuntimeCallStats* other) {
468   for (int i = 0; i < kNumberOfCounters; i++) {
469     GetCounter(i)->Add(other->GetCounter(i));
470   }
471 }
472 
473 // static
CorrectCurrentCounterId(RuntimeCallCounterId counter_id)474 void RuntimeCallStats::CorrectCurrentCounterId(
475     RuntimeCallCounterId counter_id) {
476   DCHECK(IsCalledOnTheSameThread());
477   RuntimeCallTimer* timer = current_timer();
478   if (timer == nullptr) return;
479   RuntimeCallCounter* counter = GetCounter(counter_id);
480   timer->set_counter(counter);
481   current_counter_.SetValue(counter);
482 }
483 
IsCalledOnTheSameThread()484 bool RuntimeCallStats::IsCalledOnTheSameThread() {
485   if (!thread_id_.Equals(ThreadId::Invalid()))
486     return thread_id_.Equals(ThreadId::Current());
487   thread_id_ = ThreadId::Current();
488   return true;
489 }
490 
Print()491 void RuntimeCallStats::Print() {
492   StdoutStream os;
493   Print(os);
494 }
495 
Print(std::ostream & os)496 void RuntimeCallStats::Print(std::ostream& os) {
497   RuntimeCallStatEntries entries;
498   if (current_timer_.Value() != nullptr) {
499     current_timer_.Value()->Snapshot();
500   }
501   for (int i = 0; i < kNumberOfCounters; i++) {
502     entries.Add(GetCounter(i));
503   }
504   entries.Print(os);
505 }
506 
Reset()507 void RuntimeCallStats::Reset() {
508   if (V8_LIKELY(FLAG_runtime_stats == 0)) return;
509 
510   // In tracing, we only what to trace the time spent on top level trace events,
511   // if runtime counter stack is not empty, we should clear the whole runtime
512   // counter stack, and then reset counters so that we can dump counters into
513   // top level trace events accurately.
514   while (current_timer_.Value()) {
515     current_timer_.SetValue(current_timer_.Value()->Stop());
516   }
517 
518   for (int i = 0; i < kNumberOfCounters; i++) {
519     GetCounter(i)->Reset();
520   }
521 
522   in_use_ = true;
523 }
524 
Dump(v8::tracing::TracedValue * value)525 void RuntimeCallStats::Dump(v8::tracing::TracedValue* value) {
526   for (int i = 0; i < kNumberOfCounters; i++) {
527     if (GetCounter(i)->count() > 0) GetCounter(i)->Dump(value);
528   }
529   in_use_ = false;
530 }
531 
532 }  // namespace internal
533 }  // namespace v8
534