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 #define ATRACE_TAG ATRACE_TAG_DALVIK 19 #include <stdio.h> 20 #include <cutils/trace.h> 21 22 #include "timing_logger.h" 23 24 #include "base/logging.h" 25 #include "thread.h" 26 #include "base/stl_util.h" 27 #include "base/histogram-inl.h" 28 29 #include <cmath> 30 #include <iomanip> 31 32 namespace art { 33 34 CumulativeLogger::CumulativeLogger(const std::string& name) 35 : name_(name), 36 lock_name_("CumulativeLoggerLock" + name), 37 lock_(lock_name_.c_str(), kDefaultMutexLevel, true) { 38 Reset(); 39 } 40 41 CumulativeLogger::~CumulativeLogger() { 42 STLDeleteValues(&histograms_); 43 } 44 45 void CumulativeLogger::SetName(const std::string& name) { 46 name_.assign(name); 47 } 48 49 void CumulativeLogger::Start() { 50 } 51 52 void CumulativeLogger::End() { 53 MutexLock mu(Thread::Current(), lock_); 54 iterations_++; 55 } 56 57 void CumulativeLogger::Reset() { 58 MutexLock mu(Thread::Current(), lock_); 59 iterations_ = 0; 60 STLDeleteValues(&histograms_); 61 } 62 63 uint64_t CumulativeLogger::GetTotalNs() const { 64 return GetTotalTime() * kAdjust; 65 } 66 67 uint64_t CumulativeLogger::GetTotalTime() const { 68 MutexLock mu(Thread::Current(), lock_); 69 uint64_t total = 0; 70 for (CumulativeLogger::HistogramsIterator it = histograms_.begin(), end = histograms_.end(); 71 it != end; ++it) { 72 total += it->second->Sum(); 73 } 74 return total; 75 } 76 77 void CumulativeLogger::AddLogger(const base::TimingLogger &logger) { 78 MutexLock mu(Thread::Current(), lock_); 79 const base::TimingLogger::SplitTimings& splits = logger.GetSplits(); 80 for (base::TimingLogger::SplitTimingsIterator it = splits.begin(), end = splits.end(); 81 it != end; ++it) { 82 base::TimingLogger::SplitTiming split = *it; 83 uint64_t split_time = split.first; 84 const char* split_name = split.second; 85 AddPair(split_name, split_time); 86 } 87 } 88 89 void CumulativeLogger::Dump(std::ostream &os) { 90 MutexLock mu(Thread::Current(), lock_); 91 DumpHistogram(os); 92 } 93 94 void CumulativeLogger::AddPair(const std::string &label, uint64_t delta_time) { 95 // Convert delta time to microseconds so that we don't overflow our counters. 96 delta_time /= kAdjust; 97 98 if (histograms_.find(label) == histograms_.end()) { 99 // TODO: Shoud this be a defined constant so we we know out of which orifice 16 and 100 were picked? 100 const size_t max_buckets = Runtime::Current()->GetHeap()->IsLowMemoryMode() ? 16 : 100; 101 // TODO: Should this be a defined constant so we know 50 of WTF? 102 histograms_[label] = new Histogram<uint64_t>(label.c_str(), 50, max_buckets); 103 } 104 histograms_[label]->AddValue(delta_time); 105 } 106 107 void CumulativeLogger::DumpHistogram(std::ostream &os) { 108 os << "Start Dumping histograms for " << iterations_ << " iterations" 109 << " for " << name_ << "\n"; 110 for (CumulativeLogger::HistogramsIterator it = histograms_.begin(), end = histograms_.end(); 111 it != end; ++it) { 112 Histogram<uint64_t>::CumulativeData cumulative_data; 113 it->second->CreateHistogram(cumulative_data); 114 it->second->PrintConfidenceIntervals(os, 0.99, cumulative_data); 115 // Reset cumulative values to save memory. We don't expect DumpHistogram to be called often, so 116 // it is not performance critical. 117 } 118 os << "Done Dumping histograms \n"; 119 } 120 121 122 namespace base { 123 124 TimingLogger::TimingLogger(const char* name, bool precise, bool verbose) 125 : name_(name), precise_(precise), verbose_(verbose), current_split_(NULL) { 126 } 127 128 void TimingLogger::Reset() { 129 current_split_ = NULL; 130 splits_.clear(); 131 } 132 133 void TimingLogger::StartSplit(const char* new_split_label) { 134 DCHECK(new_split_label != NULL) << "Starting split (" << new_split_label << ") with null label."; 135 TimingLogger::ScopedSplit* explicit_scoped_split = new TimingLogger::ScopedSplit(new_split_label, this); 136 explicit_scoped_split->explicit_ = true; 137 } 138 139 void TimingLogger::EndSplit() { 140 CHECK(current_split_ != NULL) << "Ending a non-existent split."; 141 DCHECK(current_split_->label_ != NULL); 142 DCHECK(current_split_->explicit_ == true) << "Explicitly ending scoped split: " << current_split_->label_; 143 144 delete current_split_; 145 } 146 147 // Ends the current split and starts the one given by the label. 148 void TimingLogger::NewSplit(const char* new_split_label) { 149 CHECK(current_split_ != NULL) << "Inserting a new split (" << new_split_label 150 << ") into a non-existent split."; 151 DCHECK(new_split_label != NULL) << "New split (" << new_split_label << ") with null label."; 152 153 current_split_->TailInsertSplit(new_split_label); 154 } 155 156 uint64_t TimingLogger::GetTotalNs() const { 157 uint64_t total_ns = 0; 158 for (base::TimingLogger::SplitTimingsIterator it = splits_.begin(), end = splits_.end(); 159 it != end; ++it) { 160 base::TimingLogger::SplitTiming split = *it; 161 total_ns += split.first; 162 } 163 return total_ns; 164 } 165 166 void TimingLogger::Dump(std::ostream &os) const { 167 uint64_t longest_split = 0; 168 uint64_t total_ns = 0; 169 for (base::TimingLogger::SplitTimingsIterator it = splits_.begin(), end = splits_.end(); 170 it != end; ++it) { 171 base::TimingLogger::SplitTiming split = *it; 172 uint64_t split_time = split.first; 173 longest_split = std::max(longest_split, split_time); 174 total_ns += split_time; 175 } 176 // Compute which type of unit we will use for printing the timings. 177 TimeUnit tu = GetAppropriateTimeUnit(longest_split); 178 uint64_t divisor = GetNsToTimeUnitDivisor(tu); 179 // Print formatted splits. 180 for (base::TimingLogger::SplitTimingsIterator it = splits_.begin(), end = splits_.end(); 181 it != end; ++it) { 182 base::TimingLogger::SplitTiming split = *it; 183 uint64_t split_time = split.first; 184 if (!precise_ && divisor >= 1000) { 185 // Make the fractional part 0. 186 split_time -= split_time % (divisor / 1000); 187 } 188 os << name_ << ": " << std::setw(8) << FormatDuration(split_time, tu) << " " 189 << split.second << "\n"; 190 } 191 os << name_ << ": end, " << NsToMs(total_ns) << " ms\n"; 192 } 193 194 195 TimingLogger::ScopedSplit::ScopedSplit(const char* label, TimingLogger* timing_logger) { 196 DCHECK(label != NULL) << "New scoped split (" << label << ") with null label."; 197 CHECK(timing_logger != NULL) << "New scoped split (" << label << ") without TimingLogger."; 198 timing_logger_ = timing_logger; 199 label_ = label; 200 running_ns_ = 0; 201 explicit_ = false; 202 203 // Stash away the current split and pause it. 204 enclosing_split_ = timing_logger->current_split_; 205 if (enclosing_split_ != NULL) { 206 enclosing_split_->Pause(); 207 } 208 209 timing_logger_->current_split_ = this; 210 211 ATRACE_BEGIN(label_); 212 213 start_ns_ = NanoTime(); 214 if (timing_logger_->verbose_) { 215 LOG(INFO) << "Begin: " << label_; 216 } 217 } 218 219 TimingLogger::ScopedSplit::~ScopedSplit() { 220 uint64_t current_time = NanoTime(); 221 uint64_t split_time = current_time - start_ns_; 222 running_ns_ += split_time; 223 ATRACE_END(); 224 225 if (timing_logger_->verbose_) { 226 LOG(INFO) << "End: " << label_ << " " << PrettyDuration(split_time); 227 } 228 229 // If one or more enclosed explcitly started splits are not terminated we can 230 // either fail or "unwind" the stack of splits in the timing logger to 'this' 231 // (by deleting the intervening scoped splits). This implements the latter. 232 TimingLogger::ScopedSplit* current = timing_logger_->current_split_; 233 while ((current != NULL) && (current != this)) { 234 delete current; 235 current = timing_logger_->current_split_; 236 } 237 238 CHECK(current != NULL) << "Missing scoped split (" << this->label_ 239 << ") in timing logger (" << timing_logger_->name_ << ")."; 240 CHECK(timing_logger_->current_split_ == this); 241 242 timing_logger_->splits_.push_back(SplitTiming(running_ns_, label_)); 243 244 timing_logger_->current_split_ = enclosing_split_; 245 if (enclosing_split_ != NULL) { 246 enclosing_split_->Resume(); 247 } 248 } 249 250 251 void TimingLogger::ScopedSplit::TailInsertSplit(const char* label) { 252 // Sleight of hand here: Rather than embedding a new scoped split, we're updating the current 253 // scoped split in place. Basically, it's one way to make explicit and scoped splits compose 254 // well while maintaining the current semantics of NewSplit. An alternative is to push a new split 255 // since we unwind the stack of scoped splits in the scoped split destructor. However, this implies 256 // that the current split is not ended by NewSplit (which calls TailInsertSplit), which would 257 // be different from what we had before. 258 259 uint64_t current_time = NanoTime(); 260 uint64_t split_time = current_time - start_ns_; 261 ATRACE_END(); 262 timing_logger_->splits_.push_back(std::pair<uint64_t, const char*>(split_time, label_)); 263 264 if (timing_logger_->verbose_) { 265 LOG(INFO) << "End: " << label_ << " " << PrettyDuration(split_time) << "\n" 266 << "Begin: " << label; 267 } 268 269 label_ = label; 270 start_ns_ = current_time; 271 running_ns_ = 0; 272 273 ATRACE_BEGIN(label); 274 } 275 276 void TimingLogger::ScopedSplit::Pause() { 277 uint64_t current_time = NanoTime(); 278 uint64_t split_time = current_time - start_ns_; 279 running_ns_ += split_time; 280 ATRACE_END(); 281 } 282 283 284 void TimingLogger::ScopedSplit::Resume() { 285 uint64_t current_time = NanoTime(); 286 287 start_ns_ = current_time; 288 ATRACE_BEGIN(label_); 289 } 290 291 } // namespace base 292 } // namespace art 293
