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 18 StatsTable::StatsTable(Counters* counters) 19 : lookup_function_(nullptr), 20 create_histogram_function_(nullptr), 21 add_histogram_sample_function_(nullptr) {} 22 23 void StatsTable::SetCounterFunction(CounterLookupCallback f) { 24 lookup_function_ = f; 25 } 26 27 int* StatsCounterBase::FindLocationInStatsTable() const { 28 return counters_->FindLocation(name_); 29 } 30 31 StatsCounterThreadSafe::StatsCounterThreadSafe(Counters* counters, 32 const char* name) 33 : StatsCounterBase(counters, name) {} 34 35 void StatsCounterThreadSafe::Set(int Value) { 36 if (ptr_) { 37 base::LockGuard<base::Mutex> Guard(&mutex_); 38 SetLoc(ptr_, Value); 39 } 40 } 41 42 void StatsCounterThreadSafe::Increment() { 43 if (ptr_) { 44 base::LockGuard<base::Mutex> Guard(&mutex_); 45 IncrementLoc(ptr_); 46 } 47 } 48 49 void StatsCounterThreadSafe::Increment(int value) { 50 if (ptr_) { 51 base::LockGuard<base::Mutex> Guard(&mutex_); 52 IncrementLoc(ptr_, value); 53 } 54 } 55 56 void StatsCounterThreadSafe::Decrement() { 57 if (ptr_) { 58 base::LockGuard<base::Mutex> Guard(&mutex_); 59 DecrementLoc(ptr_); 60 } 61 } 62 63 void StatsCounterThreadSafe::Decrement(int value) { 64 if (ptr_) { 65 base::LockGuard<base::Mutex> Guard(&mutex_); 66 DecrementLoc(ptr_, value); 67 } 68 } 69 70 void Histogram::AddSample(int sample) { 71 if (Enabled()) { 72 counters_->AddHistogramSample(histogram_, sample); 73 } 74 } 75 76 void* Histogram::CreateHistogram() const { 77 return counters_->CreateHistogram(name_, min_, max_, num_buckets_); 78 } 79 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 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 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 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 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 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: 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. 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: 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 351 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 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 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 391 void RuntimeCallCounter::Reset() { 392 count_ = 0; 393 time_ = 0; 394 } 395 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 403 void RuntimeCallCounter::Add(RuntimeCallCounter* other) { 404 count_ += other->count(); 405 time_ += other->time().InMicroseconds(); 406 } 407 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 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 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 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 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 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 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 491 void RuntimeCallStats::Print() { 492 StdoutStream os; 493 Print(os); 494 } 495 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 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 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
