1 /* 2 * Copyright (C) 2011 The Android Open Source Project 3 * 4 * Licensed under the Apache License, Version 2.0 (the "License"); 5 * you may not use this file except in compliance with the License. 6 * You may obtain a copy of the License at 7 * 8 * http://www.apache.org/licenses/LICENSE-2.0 9 * 10 * Unless required by applicable law or agreed to in writing, software 11 * distributed under the License is distributed on an "AS IS" BASIS, 12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 13 * See the License for the specific language governing permissions and 14 * limitations under the License. 15 */ 16 17 18 #include <stdio.h> 19 20 #include "timing_logger.h" 21 22 #include "base/logging.h" 23 #include "base/stl_util.h" 24 #include "base/histogram-inl.h" 25 #include "base/systrace.h" 26 #include "base/time_utils.h" 27 #include "gc/heap.h" 28 #include "runtime.h" 29 #include "thread-current-inl.h" 30 31 #include <cmath> 32 #include <iomanip> 33 34 namespace art { 35 36 constexpr size_t CumulativeLogger::kLowMemoryBucketCount; 37 constexpr size_t CumulativeLogger::kDefaultBucketCount; 38 constexpr size_t TimingLogger::kIndexNotFound; 39 40 CumulativeLogger::CumulativeLogger(const std::string& name) 41 : name_(name), 42 lock_name_("CumulativeLoggerLock" + name), 43 lock_(lock_name_.c_str(), kDefaultMutexLevel, true) { 44 Reset(); 45 } 46 47 CumulativeLogger::~CumulativeLogger() { 48 STLDeleteElements(&histograms_); 49 } 50 51 void CumulativeLogger::SetName(const std::string& name) { 52 MutexLock mu(Thread::Current(), lock_); 53 name_.assign(name); 54 } 55 56 void CumulativeLogger::Start() { 57 } 58 59 void CumulativeLogger::End() { 60 MutexLock mu(Thread::Current(), lock_); 61 ++iterations_; 62 } 63 64 void CumulativeLogger::Reset() { 65 MutexLock mu(Thread::Current(), lock_); 66 iterations_ = 0; 67 total_time_ = 0; 68 STLDeleteElements(&histograms_); 69 } 70 71 void CumulativeLogger::AddLogger(const TimingLogger &logger) { 72 MutexLock mu(Thread::Current(), lock_); 73 TimingLogger::TimingData timing_data(logger.CalculateTimingData()); 74 const std::vector<TimingLogger::Timing>& timings = logger.GetTimings(); 75 for (size_t i = 0; i < timings.size(); ++i) { 76 if (timings[i].IsStartTiming()) { 77 AddPair(timings[i].GetName(), timing_data.GetExclusiveTime(i)); 78 } 79 } 80 ++iterations_; 81 } 82 83 size_t CumulativeLogger::GetIterations() const { 84 MutexLock mu(Thread::Current(), lock_); 85 return iterations_; 86 } 87 88 void CumulativeLogger::Dump(std::ostream &os) const { 89 MutexLock mu(Thread::Current(), lock_); 90 DumpHistogram(os); 91 } 92 93 void CumulativeLogger::AddPair(const std::string& label, uint64_t delta_time) { 94 // Convert delta time to microseconds so that we don't overflow our counters. 95 delta_time /= kAdjust; 96 total_time_ += delta_time; 97 Histogram<uint64_t>* histogram; 98 Histogram<uint64_t> dummy(label.c_str()); 99 auto it = histograms_.find(&dummy); 100 if (it == histograms_.end()) { 101 const size_t max_buckets = Runtime::Current()->GetHeap()->IsLowMemoryMode() ? 102 kLowMemoryBucketCount : kDefaultBucketCount; 103 histogram = new Histogram<uint64_t>(label.c_str(), kInitialBucketSize, max_buckets); 104 histograms_.insert(histogram); 105 } else { 106 histogram = *it; 107 } 108 histogram->AddValue(delta_time); 109 } 110 111 class CompareHistorgramByTimeSpentDeclining { 112 public: 113 bool operator()(const Histogram<uint64_t>* a, const Histogram<uint64_t>* b) const { 114 return a->Sum() > b->Sum(); 115 } 116 }; 117 118 void CumulativeLogger::DumpHistogram(std::ostream &os) const { 119 os << "Start Dumping histograms for " << iterations_ << " iterations" 120 << " for " << name_ << "\n"; 121 std::set<Histogram<uint64_t>*, CompareHistorgramByTimeSpentDeclining> 122 sorted_histograms(histograms_.begin(), histograms_.end()); 123 for (Histogram<uint64_t>* histogram : sorted_histograms) { 124 Histogram<uint64_t>::CumulativeData cumulative_data; 125 // We don't expect DumpHistogram to be called often, so it is not performance critical. 126 histogram->CreateHistogram(&cumulative_data); 127 histogram->PrintConfidenceIntervals(os, 0.99, cumulative_data); 128 } 129 os << "Done Dumping histograms\n"; 130 } 131 132 TimingLogger::TimingLogger(const char* name, bool precise, bool verbose) 133 : name_(name), precise_(precise), verbose_(verbose) { 134 } 135 136 void TimingLogger::Reset() { 137 timings_.clear(); 138 } 139 140 void TimingLogger::StartTiming(const char* label) { 141 DCHECK(label != nullptr); 142 timings_.push_back(Timing(NanoTime(), label)); 143 ATRACE_BEGIN(label); 144 } 145 146 void TimingLogger::EndTiming() { 147 timings_.push_back(Timing(NanoTime(), nullptr)); 148 ATRACE_END(); 149 } 150 151 uint64_t TimingLogger::GetTotalNs() const { 152 if (timings_.size() < 2) { 153 return 0; 154 } 155 return timings_.back().GetTime() - timings_.front().GetTime(); 156 } 157 158 size_t TimingLogger::FindTimingIndex(const char* name, size_t start_idx) const { 159 DCHECK_LT(start_idx, timings_.size()); 160 for (size_t i = start_idx; i < timings_.size(); ++i) { 161 if (timings_[i].IsStartTiming() && strcmp(timings_[i].GetName(), name) == 0) { 162 return i; 163 } 164 } 165 return kIndexNotFound; 166 } 167 168 TimingLogger::TimingData TimingLogger::CalculateTimingData() const { 169 TimingLogger::TimingData ret; 170 ret.data_.resize(timings_.size()); 171 std::vector<size_t> open_stack; 172 for (size_t i = 0; i < timings_.size(); ++i) { 173 if (timings_[i].IsEndTiming()) { 174 CHECK(!open_stack.empty()) << "No starting split for ending split at index " << i; 175 size_t open_idx = open_stack.back(); 176 uint64_t time = timings_[i].GetTime() - timings_[open_idx].GetTime(); 177 ret.data_[open_idx].exclusive_time += time; 178 DCHECK_EQ(ret.data_[open_idx].total_time, 0U); 179 ret.data_[open_idx].total_time += time; 180 // Each open split has exactly one end. 181 open_stack.pop_back(); 182 // If there is a parent node, subtract from the exclusive time. 183 if (!open_stack.empty()) { 184 // Note this may go negative, but will work due to 2s complement when we add the value 185 // total time value later. 186 ret.data_[open_stack.back()].exclusive_time -= time; 187 } 188 } else { 189 open_stack.push_back(i); 190 } 191 } 192 CHECK(open_stack.empty()) << "Missing ending for timing " 193 << timings_[open_stack.back()].GetName() << " at index " << open_stack.back(); 194 return ret; // No need to fear, C++11 move semantics are here. 195 } 196 197 void TimingLogger::Dump(std::ostream &os, const char* indent_string) const { 198 static constexpr size_t kFractionalDigits = 3; 199 TimingLogger::TimingData timing_data(CalculateTimingData()); 200 uint64_t longest_split = 0; 201 for (size_t i = 0; i < timings_.size(); ++i) { 202 longest_split = std::max(longest_split, timing_data.GetTotalTime(i)); 203 } 204 // Compute which type of unit we will use for printing the timings. 205 TimeUnit tu = GetAppropriateTimeUnit(longest_split); 206 uint64_t divisor = GetNsToTimeUnitDivisor(tu); 207 uint64_t mod_fraction = divisor >= 1000 ? divisor / 1000 : 1; 208 // Print formatted splits. 209 size_t tab_count = 1; 210 os << name_ << " [Exclusive time] [Total time]\n"; 211 for (size_t i = 0; i < timings_.size(); ++i) { 212 if (timings_[i].IsStartTiming()) { 213 uint64_t exclusive_time = timing_data.GetExclusiveTime(i); 214 uint64_t total_time = timing_data.GetTotalTime(i); 215 if (!precise_) { 216 // Make the fractional part 0. 217 exclusive_time -= exclusive_time % mod_fraction; 218 total_time -= total_time % mod_fraction; 219 } 220 for (size_t j = 0; j < tab_count; ++j) { 221 os << indent_string; 222 } 223 os << FormatDuration(exclusive_time, tu, kFractionalDigits); 224 // If they are the same, just print one value to prevent spam. 225 if (exclusive_time != total_time) { 226 os << "/" << FormatDuration(total_time, tu, kFractionalDigits); 227 } 228 os << " " << timings_[i].GetName() << "\n"; 229 ++tab_count; 230 } else { 231 --tab_count; 232 } 233 } 234 os << name_ << ": end, " << PrettyDuration(GetTotalNs()) << "\n"; 235 } 236 237 void TimingLogger::Verify() { 238 size_t counts[2] = { 0 }; 239 for (size_t i = 0; i < timings_.size(); ++i) { 240 if (i > 0) { 241 CHECK_LE(timings_[i - 1].GetTime(), timings_[i].GetTime()); 242 } 243 ++counts[timings_[i].IsStartTiming() ? 0 : 1]; 244 } 245 CHECK_EQ(counts[0], counts[1]) << "Number of StartTiming and EndTiming doesn't match"; 246 } 247 248 TimingLogger::~TimingLogger() { 249 if (kIsDebugBuild) { 250 Verify(); 251 } 252 } 253 254 } // namespace art 255
