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 #include <stdio.h> 18 19 #include "timing_logger.h" 20 21 #include <android-base/logging.h> 22 23 #include "base/histogram-inl.h" 24 #include "base/stl_util.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, 133 bool precise, 134 bool verbose, 135 TimingLogger::TimingKind kind) 136 : name_(name), precise_(precise), verbose_(verbose), kind_(kind) { 137 } 138 139 void TimingLogger::Reset() { 140 timings_.clear(); 141 } 142 143 void TimingLogger::StartTiming(const char* label) { 144 DCHECK(label != nullptr); 145 timings_.push_back(Timing(kind_, label)); 146 ATRACE_BEGIN(label); 147 } 148 149 void TimingLogger::EndTiming() { 150 timings_.push_back(Timing(kind_, nullptr)); 151 ATRACE_END(); 152 } 153 154 uint64_t TimingLogger::GetTotalNs() const { 155 if (timings_.size() < 2) { 156 return 0; 157 } 158 return timings_.back().GetTime() - timings_.front().GetTime(); 159 } 160 161 size_t TimingLogger::FindTimingIndex(const char* name, size_t start_idx) const { 162 DCHECK_LT(start_idx, timings_.size()); 163 for (size_t i = start_idx; i < timings_.size(); ++i) { 164 if (timings_[i].IsStartTiming() && strcmp(timings_[i].GetName(), name) == 0) { 165 return i; 166 } 167 } 168 return kIndexNotFound; 169 } 170 171 TimingLogger::TimingData TimingLogger::CalculateTimingData() const { 172 TimingLogger::TimingData ret; 173 ret.data_.resize(timings_.size()); 174 std::vector<size_t> open_stack; 175 for (size_t i = 0; i < timings_.size(); ++i) { 176 if (timings_[i].IsEndTiming()) { 177 CHECK(!open_stack.empty()) << "No starting split for ending split at index " << i; 178 size_t open_idx = open_stack.back(); 179 uint64_t time = timings_[i].GetTime() - timings_[open_idx].GetTime(); 180 ret.data_[open_idx].exclusive_time += time; 181 DCHECK_EQ(ret.data_[open_idx].total_time, 0U); 182 ret.data_[open_idx].total_time += time; 183 // Each open split has exactly one end. 184 open_stack.pop_back(); 185 // If there is a parent node, subtract from the exclusive time. 186 if (!open_stack.empty()) { 187 // Note this may go negative, but will work due to 2s complement when we add the value 188 // total time value later. 189 ret.data_[open_stack.back()].exclusive_time -= time; 190 } 191 } else { 192 open_stack.push_back(i); 193 } 194 } 195 CHECK(open_stack.empty()) << "Missing ending for timing " 196 << timings_[open_stack.back()].GetName() << " at index " << open_stack.back(); 197 return ret; // No need to fear, C++11 move semantics are here. 198 } 199 200 void TimingLogger::Dump(std::ostream &os, const char* indent_string) const { 201 static constexpr size_t kFractionalDigits = 3; 202 TimingLogger::TimingData timing_data(CalculateTimingData()); 203 uint64_t longest_split = 0; 204 for (size_t i = 0; i < timings_.size(); ++i) { 205 longest_split = std::max(longest_split, timing_data.GetTotalTime(i)); 206 } 207 // Compute which type of unit we will use for printing the timings. 208 TimeUnit tu = GetAppropriateTimeUnit(longest_split); 209 uint64_t divisor = GetNsToTimeUnitDivisor(tu); 210 uint64_t mod_fraction = divisor >= 1000 ? divisor / 1000 : 1; 211 // Print formatted splits. 212 size_t tab_count = 1; 213 os << name_ << " [Exclusive time] [Total time]\n"; 214 for (size_t i = 0; i < timings_.size(); ++i) { 215 if (timings_[i].IsStartTiming()) { 216 uint64_t exclusive_time = timing_data.GetExclusiveTime(i); 217 uint64_t total_time = timing_data.GetTotalTime(i); 218 if (!precise_) { 219 // Make the fractional part 0. 220 exclusive_time -= exclusive_time % mod_fraction; 221 total_time -= total_time % mod_fraction; 222 } 223 for (size_t j = 0; j < tab_count; ++j) { 224 os << indent_string; 225 } 226 os << FormatDuration(exclusive_time, tu, kFractionalDigits); 227 // If they are the same, just print one value to prevent spam. 228 if (exclusive_time != total_time) { 229 os << "/" << FormatDuration(total_time, tu, kFractionalDigits); 230 } 231 os << " " << timings_[i].GetName() << "\n"; 232 ++tab_count; 233 } else { 234 --tab_count; 235 } 236 } 237 os << name_ << ": end, " << PrettyDuration(GetTotalNs()) << "\n"; 238 } 239 240 void TimingLogger::Verify() { 241 size_t counts[2] = { 0 }; 242 for (size_t i = 0; i < timings_.size(); ++i) { 243 if (i > 0) { 244 CHECK_LE(timings_[i - 1].GetTime(), timings_[i].GetTime()); 245 } 246 ++counts[timings_[i].IsStartTiming() ? 0 : 1]; 247 } 248 CHECK_EQ(counts[0], counts[1]) << "Number of StartTiming and EndTiming doesn't match"; 249 } 250 251 TimingLogger::~TimingLogger() { 252 if (kIsDebugBuild) { 253 Verify(); 254 } 255 } 256 257 } // namespace art 258
