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