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