counters.cc 12.3 KB
Newer Older
1
// Copyright 2012 the V8 project authors. All rights reserved.
2 3
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.
4

5
#include "src/counters.h"
6

7 8
#include <iomanip>

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 15
namespace v8 {
namespace internal {
16

17 18 19 20 21 22 23
StatsTable::StatsTable()
    : lookup_function_(NULL),
      create_histogram_function_(NULL),
      add_histogram_sample_function_(NULL) {}


int* StatsCounter::FindLocationInStatsTable() const {
24
  return isolate_->stats_table()->FindLocation(name_);
25 26
}

27

28 29
void Histogram::AddSample(int sample) {
  if (Enabled()) {
30
    isolate()->stats_table()->AddHistogramSample(histogram_, sample);
31 32 33 34
  }
}

void* Histogram::CreateHistogram() const {
35
  return isolate()->stats_table()->
36 37 38
      CreateHistogram(name_, min_, max_, num_buckets_);
}

39

40 41
// Start the timer.
void HistogramTimer::Start() {
42
  if (Enabled()) {
43
    timer_.Start();
44
  }
45
  Logger::CallEventLogger(isolate(), name(), Logger::START, true);
46 47
}

48

49 50
// Stop the timer and record the results.
void HistogramTimer::Stop() {
51
  if (Enabled()) {
yangguo's avatar
yangguo committed
52 53 54 55 56
    int64_t sample = resolution_ == MICROSECOND
                         ? timer_.Elapsed().InMicroseconds()
                         : timer_.Elapsed().InMilliseconds();
    // Compute the delta between start and stop, in microseconds.
    AddSample(static_cast<int>(sample));
57
    timer_.Stop();
58
  }
59
  Logger::CallEventLogger(isolate(), name(), Logger::END, true);
60 61
}

62 63

Counters::Counters(Isolate* isolate) {
64 65 66 67 68
#define HR(name, caption, min, max, num_buckets) \
  name##_ = Histogram(#caption, min, max, num_buckets, isolate);
  HISTOGRAM_RANGE_LIST(HR)
#undef HR

yangguo's avatar
yangguo committed
69 70
#define HT(name, caption, max, res) \
  name##_ = HistogramTimer(#caption, 0, max, HistogramTimer::res, 50, isolate);
71 72 73
    HISTOGRAM_TIMER_LIST(HT)
#undef HT

74
#define AHT(name, caption) \
yangguo's avatar
yangguo committed
75
  name##_ = AggregatableHistogramTimer(#caption, 0, 10000000, 50, isolate);
76 77 78
    AGGREGATABLE_HISTOGRAM_TIMER_LIST(AHT)
#undef AHT

79 80 81 82 83
#define HP(name, caption) \
    name##_ = Histogram(#caption, 0, 101, 100, isolate);
    HISTOGRAM_PERCENTAGE_LIST(HP)
#undef HP

84 85 86 87 88 89 90

// Exponential histogram assigns bucket limits to points
// p[1], p[2], ... p[n] such that p[i+1] / p[i] = constant.
// The constant factor is equal to the n-th root of (high / low),
// where the n is the number of buckets, the low is the lower limit,
// the high is the upper limit.
// For n = 50, low = 1000, high = 500000: the factor = 1.13.
91 92
#define HM(name, caption) \
    name##_ = Histogram(#caption, 1000, 500000, 50, isolate);
93 94 95 96 97 98 99 100 101 102
  HISTOGRAM_LEGACY_MEMORY_LIST(HM)
#undef HM
// For n = 100, low = 4000, high = 2000000: the factor = 1.06.
#define HM(name, caption) \
  name##_ = Histogram(#caption, 4000, 2000000, 100, isolate);
  HISTOGRAM_MEMORY_LIST(HM)
#undef HM

#define HM(name, caption) \
  aggregated_##name##_ = AggregatedMemoryHistogram<Histogram>(&name##_);
103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144
    HISTOGRAM_MEMORY_LIST(HM)
#undef HM

#define SC(name, caption) \
    name##_ = StatsCounter(isolate, "c:" #caption);

    STATS_COUNTER_LIST_1(SC)
    STATS_COUNTER_LIST_2(SC)
#undef SC

#define SC(name) \
    count_of_##name##_ = StatsCounter(isolate, "c:" "V8.CountOf_" #name); \
    size_of_##name##_ = StatsCounter(isolate, "c:" "V8.SizeOf_" #name);
    INSTANCE_TYPE_LIST(SC)
#undef SC

#define SC(name) \
    count_of_CODE_TYPE_##name##_ = \
        StatsCounter(isolate, "c:" "V8.CountOf_CODE_TYPE-" #name); \
    size_of_CODE_TYPE_##name##_ = \
        StatsCounter(isolate, "c:" "V8.SizeOf_CODE_TYPE-" #name);
    CODE_KIND_LIST(SC)
#undef SC

#define SC(name) \
    count_of_FIXED_ARRAY_##name##_ = \
        StatsCounter(isolate, "c:" "V8.CountOf_FIXED_ARRAY-" #name); \
    size_of_FIXED_ARRAY_##name##_ = \
        StatsCounter(isolate, "c:" "V8.SizeOf_FIXED_ARRAY-" #name);
    FIXED_ARRAY_SUB_INSTANCE_TYPE_LIST(SC)
#undef SC

#define SC(name) \
    count_of_CODE_AGE_##name##_ = \
        StatsCounter(isolate, "c:" "V8.CountOf_CODE_AGE-" #name); \
    size_of_CODE_AGE_##name##_ = \
        StatsCounter(isolate, "c:" "V8.SizeOf_CODE_AGE-" #name);
    CODE_AGE_LIST_COMPLETE(SC)
#undef SC
}


145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176
void Counters::ResetCounters() {
#define SC(name, caption) name##_.Reset();
  STATS_COUNTER_LIST_1(SC)
  STATS_COUNTER_LIST_2(SC)
#undef SC

#define SC(name)              \
  count_of_##name##_.Reset(); \
  size_of_##name##_.Reset();
  INSTANCE_TYPE_LIST(SC)
#undef SC

#define SC(name)                        \
  count_of_CODE_TYPE_##name##_.Reset(); \
  size_of_CODE_TYPE_##name##_.Reset();
  CODE_KIND_LIST(SC)
#undef SC

#define SC(name)                          \
  count_of_FIXED_ARRAY_##name##_.Reset(); \
  size_of_FIXED_ARRAY_##name##_.Reset();
  FIXED_ARRAY_SUB_INSTANCE_TYPE_LIST(SC)
#undef SC

#define SC(name)                       \
  count_of_CODE_AGE_##name##_.Reset(); \
  size_of_CODE_AGE_##name##_.Reset();
  CODE_AGE_LIST_COMPLETE(SC)
#undef SC
}


177
void Counters::ResetHistograms() {
178 179 180 181
#define HR(name, caption, min, max, num_buckets) name##_.Reset();
  HISTOGRAM_RANGE_LIST(HR)
#undef HR

yangguo's avatar
yangguo committed
182
#define HT(name, caption, max, res) name##_.Reset();
183 184 185
    HISTOGRAM_TIMER_LIST(HT)
#undef HT

186 187 188 189
#define AHT(name, caption) name##_.Reset();
    AGGREGATABLE_HISTOGRAM_TIMER_LIST(AHT)
#undef AHT

190 191 192 193 194
#define HP(name, caption) name##_.Reset();
    HISTOGRAM_PERCENTAGE_LIST(HP)
#undef HP

#define HM(name, caption) name##_.Reset();
195
    HISTOGRAM_LEGACY_MEMORY_LIST(HM)
196 197 198
#undef HM
}

199 200 201
class RuntimeCallStatEntries {
 public:
  void Print(std::ostream& os) {
202 203
    if (total_call_count == 0) return;
    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 208 209
    for (Entry& entry : entries) {
      entry.SetTotal(total_time, total_call_count);
      entry.Print(os);
210
    }
211
    os << std::string(88, '-') << std::endl;
212
    Entry("Total", total_time, total_call_count).Print(os);
213 214
  }

215 216 217 218
  // By default, the compiler will usually inline this, which results in a large
  // binary size increase: std::vector::push_back expands to a large amount of
  // instructions, and this function is invoked repeatedly by macros.
  V8_NOINLINE void Add(RuntimeCallCounter* counter) {
219 220 221 222 223
    if (counter->count() == 0) return;
    entries.push_back(
        Entry(counter->name(), counter->time(), counter->count()));
    total_time += counter->time();
    total_call_count += counter->count();
224 225 226 227 228 229 230
  }

 private:
  class Entry {
   public:
    Entry(const char* name, base::TimeDelta time, uint64_t count)
        : name_(name),
231
          time_(time.InMicroseconds()),
232 233 234 235 236 237 238 239 240 241
          count_(count),
          time_percent_(100),
          count_percent_(100) {}

    bool operator<(const Entry& other) const {
      if (time_ < other.time_) return true;
      if (time_ > other.time_) return false;
      return count_ < other.count_;
    }

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 248 249 250 251 252
      os << std::setw(6) << time_percent_ << "%";
      os << std::setw(10) << count_ << " ";
      os << std::setw(6) << count_percent_ << "%";
      os << std::endl;
    }

253 254
    V8_NOINLINE void SetTotal(base::TimeDelta total_time,
                              uint64_t total_count) {
255
      if (total_time.InMicroseconds() == 0) {
256 257
        time_percent_ = 0;
      } else {
258
        time_percent_ = 100.0 * time_ / total_time.InMicroseconds();
259
      }
260 261 262 263 264 265 266 267 268 269 270 271 272 273 274 275
      count_percent_ = 100.0 * count_ / total_count;
    }

   private:
    const char* name_;
    int64_t time_;
    uint64_t count_;
    double time_percent_;
    double count_percent_;
  };

  uint64_t total_call_count = 0;
  base::TimeDelta total_time;
  std::vector<Entry> entries;
};

276
void RuntimeCallCounter::Reset() {
277 278
  count_ = 0;
  time_ = base::TimeDelta();
279 280
}

281
void RuntimeCallCounter::Dump(v8::tracing::TracedValue* value) {
282
  value->BeginArray(name_);
283 284
  value->AppendDouble(count_);
  value->AppendDouble(time_.InMicroseconds());
285
  value->EndArray();
286 287
}

288
void RuntimeCallCounter::Add(RuntimeCallCounter* other) {
289 290 291 292 293 294 295 296 297 298 299 300 301 302 303
  count_ += other->count();
  time_ += other->time();
}

void RuntimeCallTimer::Snapshot() {
  base::TimeTicks now = Now();
  // Pause only / topmost timer in the timer stack.
  Pause(now);
  // Commit all the timer's elapsed time to the counters.
  RuntimeCallTimer* timer = this;
  while (timer != nullptr) {
    timer->CommitTimeToCounter();
    timer = timer->parent();
  }
  Resume(now);
304 305 306 307 308 309 310 311 312 313 314 315 316 317 318 319 320 321 322 323 324 325
}

// static
const RuntimeCallStats::CounterId RuntimeCallStats::counters[] = {
#define CALL_RUNTIME_COUNTER(name) &RuntimeCallStats::name,
    FOR_EACH_MANUAL_COUNTER(CALL_RUNTIME_COUNTER)  //
#undef CALL_RUNTIME_COUNTER
#define CALL_RUNTIME_COUNTER(name, nargs, ressize) \
  &RuntimeCallStats::Runtime_##name,          //
    FOR_EACH_INTRINSIC(CALL_RUNTIME_COUNTER)  //
#undef CALL_RUNTIME_COUNTER
#define CALL_BUILTIN_COUNTER(name) &RuntimeCallStats::Builtin_##name,
    BUILTIN_LIST_C(CALL_BUILTIN_COUNTER)  //
#undef CALL_BUILTIN_COUNTER
#define CALL_BUILTIN_COUNTER(name) &RuntimeCallStats::API_##name,
    FOR_EACH_API_COUNTER(CALL_BUILTIN_COUNTER)  //
#undef CALL_BUILTIN_COUNTER
#define CALL_BUILTIN_COUNTER(name) &RuntimeCallStats::Handler_##name,
    FOR_EACH_HANDLER_COUNTER(CALL_BUILTIN_COUNTER)
#undef CALL_BUILTIN_COUNTER
};

326 327 328 329
// static
const int RuntimeCallStats::counters_count =
    arraysize(RuntimeCallStats::counters);

330
// static
331
void RuntimeCallStats::Enter(RuntimeCallStats* stats, RuntimeCallTimer* timer,
332 333
                             CounterId counter_id) {
  RuntimeCallCounter* counter = &(stats->*counter_id);
334
  DCHECK(counter->name() != nullptr);
335 336
  timer->Start(counter, stats->current_timer_.Value());
  stats->current_timer_.SetValue(timer);
337 338
}

339
// static
340
void RuntimeCallStats::Leave(RuntimeCallStats* stats, RuntimeCallTimer* timer) {
341 342
  if (stats->current_timer_.Value() == timer) {
    stats->current_timer_.SetValue(timer->Stop());
343 344 345 346
  } else {
    // Must be a Threading cctest. Walk the chain of Timers to find the
    // buried one that's leaving. We don't care about keeping nested timings
    // accurate, just avoid crashing by keeping the chain intact.
347
    RuntimeCallTimer* next = stats->current_timer_.Value();
348 349
    while (next && next->parent() != timer) next = next->parent();
    if (next == nullptr) return;
350
    next->set_parent(timer->Stop());
351
  }
352 353
}

354 355 356 357 358 359 360 361 362
void RuntimeCallStats::Add(RuntimeCallStats* other) {
  for (const RuntimeCallStats::CounterId counter_id :
       RuntimeCallStats::counters) {
    RuntimeCallCounter* counter = &(this->*counter_id);
    RuntimeCallCounter* other_counter = &(other->*counter_id);
    counter->Add(other_counter);
  }
}

363
// static
364
void RuntimeCallStats::CorrectCurrentCounterId(RuntimeCallStats* stats,
365
                                               CounterId counter_id) {
366 367 368
  RuntimeCallTimer* timer = stats->current_timer_.Value();
  // When RCS are enabled dynamically there might be no current timer set up.
  if (timer == nullptr) return;
369
  timer->set_counter(&(stats->*counter_id));
370 371
}

372 373
void RuntimeCallStats::Print(std::ostream& os) {
  RuntimeCallStatEntries entries;
374
  if (current_timer_.Value() != nullptr) {
375
    current_timer_.Value()->Snapshot();
376
  }
377 378 379 380 381
  for (const RuntimeCallStats::CounterId counter_id :
       RuntimeCallStats::counters) {
    RuntimeCallCounter* counter = &(this->*counter_id);
    entries.Add(counter);
  }
382 383 384 385
  entries.Print(os);
}

void RuntimeCallStats::Reset() {
386 387
  if (V8_LIKELY(FLAG_runtime_stats == 0)) return;

388 389 390 391 392 393 394 395
  // In tracing, we only what to trace the time spent on top level trace events,
  // if runtime counter stack is not empty, we should clear the whole runtime
  // counter stack, and then reset counters so that we can dump counters into
  // top level trace events accurately.
  while (current_timer_.Value()) {
    current_timer_.SetValue(current_timer_.Value()->Stop());
  }

396 397 398 399 400
  for (const RuntimeCallStats::CounterId counter_id :
       RuntimeCallStats::counters) {
    RuntimeCallCounter* counter = &(this->*counter_id);
    counter->Reset();
  }
401 402

  in_use_ = true;
403 404
}

405
void RuntimeCallStats::Dump(v8::tracing::TracedValue* value) {
406 407 408
  for (const RuntimeCallStats::CounterId counter_id :
       RuntimeCallStats::counters) {
    RuntimeCallCounter* counter = &(this->*counter_id);
409
    if (counter->count() > 0) counter->Dump(value);
410
  }
411

412 413 414
  in_use_ = false;
}

415 416
}  // namespace internal
}  // namespace v8