Sameer Abu Asal | a843954 | 2013-02-14 16:06:42 -0800 | [diff] [blame] | 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 | |
Anwar Ghuloum | 6f28d91 | 2013-07-24 15:02:53 -0700 | [diff] [blame^] | 17 | |
| 18 | #define ATRACE_TAG ATRACE_TAG_DALVIK |
| 19 | #include <stdio.h> |
| 20 | #include <cutils/trace.h> |
| 21 | |
Sameer Abu Asal | a843954 | 2013-02-14 16:06:42 -0800 | [diff] [blame] | 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 | |
Ian Rogers | 4535705 | 2013-04-18 20:49:43 -0700 | [diff] [blame] | 34 | CumulativeLogger::CumulativeLogger(const std::string& name) |
Sameer Abu Asal | a843954 | 2013-02-14 16:06:42 -0800 | [diff] [blame] | 35 | : name_(name), |
Ian Rogers | 4535705 | 2013-04-18 20:49:43 -0700 | [diff] [blame] | 36 | lock_name_("CumulativeLoggerLock" + name), |
| 37 | lock_(lock_name_.c_str(), kDefaultMutexLevel, true) { |
Sameer Abu Asal | a843954 | 2013-02-14 16:06:42 -0800 | [diff] [blame] | 38 | Reset(); |
| 39 | } |
| 40 | |
Ian Rogers | 4535705 | 2013-04-18 20:49:43 -0700 | [diff] [blame] | 41 | CumulativeLogger::~CumulativeLogger() { |
| 42 | STLDeleteElements(&histograms_); |
| 43 | } |
Sameer Abu Asal | a843954 | 2013-02-14 16:06:42 -0800 | [diff] [blame] | 44 | |
Ian Rogers | 4535705 | 2013-04-18 20:49:43 -0700 | [diff] [blame] | 45 | void CumulativeLogger::SetName(const std::string& name) { |
Ian Rogers | 1d54e73 | 2013-05-02 21:10:01 -0700 | [diff] [blame] | 46 | name_.assign(name); |
Ian Rogers | 4535705 | 2013-04-18 20:49:43 -0700 | [diff] [blame] | 47 | } |
Sameer Abu Asal | a843954 | 2013-02-14 16:06:42 -0800 | [diff] [blame] | 48 | |
| 49 | void CumulativeLogger::Start() { |
| 50 | MutexLock mu(Thread::Current(), lock_); |
| 51 | index_ = 0; |
| 52 | } |
| 53 | |
| 54 | void CumulativeLogger::End() { |
| 55 | MutexLock mu(Thread::Current(), lock_); |
| 56 | iterations_++; |
| 57 | } |
| 58 | void CumulativeLogger::Reset() { |
| 59 | MutexLock mu(Thread::Current(), lock_); |
| 60 | iterations_ = 0; |
| 61 | STLDeleteElements(&histograms_); |
| 62 | } |
| 63 | |
| 64 | uint64_t CumulativeLogger::GetTotalNs() const { |
| 65 | return GetTotalTime() * kAdjust; |
| 66 | } |
| 67 | |
| 68 | uint64_t CumulativeLogger::GetTotalTime() const { |
| 69 | MutexLock mu(Thread::Current(), lock_); |
| 70 | uint64_t total = 0; |
| 71 | for (size_t i = 0; i < histograms_.size(); ++i) { |
| 72 | total += histograms_[i]->Sum(); |
| 73 | } |
| 74 | return total; |
| 75 | } |
| 76 | |
Sameer Abu Asal | a843954 | 2013-02-14 16:06:42 -0800 | [diff] [blame] | 77 | |
Anwar Ghuloum | 6f28d91 | 2013-07-24 15:02:53 -0700 | [diff] [blame^] | 78 | void CumulativeLogger::AddLogger(const base::TimingLogger &logger) { |
Ian Rogers | 1d54e73 | 2013-05-02 21:10:01 -0700 | [diff] [blame] | 79 | MutexLock mu(Thread::Current(), lock_); |
| 80 | const std::vector<std::pair<uint64_t, const char*> >& splits = logger.GetSplits(); |
| 81 | typedef std::vector<std::pair<uint64_t, const char*> >::const_iterator It; |
| 82 | if (kIsDebugBuild && splits.size() != histograms_.size()) { |
| 83 | LOG(ERROR) << "Mismatch in splits."; |
| 84 | typedef std::vector<Histogram<uint64_t> *>::const_iterator It2; |
| 85 | It it = splits.begin(); |
| 86 | It2 it2 = histograms_.begin(); |
| 87 | while ((it != splits.end()) && (it2 != histograms_.end())) { |
| 88 | if (it != splits.end()) { |
| 89 | LOG(ERROR) << "\tsplit: " << it->second; |
| 90 | ++it; |
| 91 | } |
| 92 | if (it2 != histograms_.end()) { |
| 93 | LOG(ERROR) << "\tpreviously record: " << (*it2)->Name(); |
| 94 | ++it2; |
| 95 | } |
| 96 | } |
| 97 | } |
| 98 | for (It it = splits.begin(), end = splits.end(); it != end; ++it) { |
| 99 | std::pair<uint64_t, const char*> split = *it; |
| 100 | uint64_t split_time = split.first; |
| 101 | const char* split_name = split.second; |
| 102 | AddPair(split_name, split_time); |
| 103 | } |
| 104 | } |
| 105 | |
Sameer Abu Asal | a843954 | 2013-02-14 16:06:42 -0800 | [diff] [blame] | 106 | void CumulativeLogger::Dump(std::ostream &os) { |
| 107 | MutexLock mu(Thread::Current(), lock_); |
| 108 | DumpHistogram(os); |
| 109 | } |
| 110 | |
| 111 | void CumulativeLogger::AddPair(const std::string &label, uint64_t delta_time) { |
Sameer Abu Asal | a843954 | 2013-02-14 16:06:42 -0800 | [diff] [blame] | 112 | // Convert delta time to microseconds so that we don't overflow our counters. |
| 113 | delta_time /= kAdjust; |
| 114 | if (index_ >= histograms_.size()) { |
| 115 | Histogram<uint64_t> *tmp_hist = new Histogram<uint64_t>(label); |
| 116 | tmp_hist->AddValue(delta_time); |
| 117 | histograms_.push_back(tmp_hist); |
| 118 | } else { |
| 119 | histograms_[index_]->AddValue(delta_time); |
| 120 | DCHECK_EQ(label, histograms_[index_]->Name()); |
| 121 | } |
| 122 | index_++; |
| 123 | } |
| 124 | |
| 125 | void CumulativeLogger::DumpHistogram(std::ostream &os) { |
| 126 | os << "Start Dumping histograms for " << iterations_ << " iterations" |
| 127 | << " for " << name_ << "\n"; |
| 128 | for (size_t Idx = 0; Idx < histograms_.size(); Idx++) { |
| 129 | Histogram<uint64_t> &hist = *(histograms_[Idx]); |
| 130 | hist.CreateHistogram(); |
| 131 | hist.PrintConfidenceIntervals(os, 0.99); |
| 132 | } |
| 133 | os << "Done Dumping histograms \n"; |
| 134 | } |
| 135 | |
Ian Rogers | 1d54e73 | 2013-05-02 21:10:01 -0700 | [diff] [blame] | 136 | |
| 137 | namespace base { |
| 138 | |
Anwar Ghuloum | 6f28d91 | 2013-07-24 15:02:53 -0700 | [diff] [blame^] | 139 | TimingLogger::TimingLogger(const char* name, bool precise, bool verbose) |
Ian Rogers | 1d54e73 | 2013-05-02 21:10:01 -0700 | [diff] [blame] | 140 | : name_(name), precise_(precise), verbose_(verbose), |
| 141 | current_split_(NULL), current_split_start_ns_(0) { |
| 142 | } |
| 143 | |
Anwar Ghuloum | 6f28d91 | 2013-07-24 15:02:53 -0700 | [diff] [blame^] | 144 | void TimingLogger::Reset() { |
Ian Rogers | 1d54e73 | 2013-05-02 21:10:01 -0700 | [diff] [blame] | 145 | current_split_ = NULL; |
| 146 | current_split_start_ns_ = 0; |
| 147 | splits_.clear(); |
| 148 | } |
| 149 | |
Anwar Ghuloum | 6f28d91 | 2013-07-24 15:02:53 -0700 | [diff] [blame^] | 150 | void TimingLogger::StartSplit(const char* new_split_label) { |
Ian Rogers | 1d54e73 | 2013-05-02 21:10:01 -0700 | [diff] [blame] | 151 | DCHECK(current_split_ == NULL); |
| 152 | if (verbose_) { |
| 153 | LOG(INFO) << "Begin: " << new_split_label; |
| 154 | } |
| 155 | current_split_ = new_split_label; |
Anwar Ghuloum | 6f28d91 | 2013-07-24 15:02:53 -0700 | [diff] [blame^] | 156 | ATRACE_BEGIN(current_split_); |
Ian Rogers | 1d54e73 | 2013-05-02 21:10:01 -0700 | [diff] [blame] | 157 | current_split_start_ns_ = NanoTime(); |
| 158 | } |
| 159 | |
| 160 | // Ends the current split and starts the one given by the label. |
Anwar Ghuloum | 6f28d91 | 2013-07-24 15:02:53 -0700 | [diff] [blame^] | 161 | void TimingLogger::NewSplit(const char* new_split_label) { |
Ian Rogers | 1d54e73 | 2013-05-02 21:10:01 -0700 | [diff] [blame] | 162 | DCHECK(current_split_ != NULL); |
| 163 | uint64_t current_time = NanoTime(); |
| 164 | uint64_t split_time = current_time - current_split_start_ns_; |
Anwar Ghuloum | 6f28d91 | 2013-07-24 15:02:53 -0700 | [diff] [blame^] | 165 | ATRACE_END(); |
Ian Rogers | 1d54e73 | 2013-05-02 21:10:01 -0700 | [diff] [blame] | 166 | splits_.push_back(std::pair<uint64_t, const char*>(split_time, current_split_)); |
| 167 | if (verbose_) { |
| 168 | LOG(INFO) << "End: " << current_split_ << " " << PrettyDuration(split_time) << "\n" |
| 169 | << "Begin: " << new_split_label; |
| 170 | } |
| 171 | current_split_ = new_split_label; |
Anwar Ghuloum | 6f28d91 | 2013-07-24 15:02:53 -0700 | [diff] [blame^] | 172 | ATRACE_BEGIN(current_split_); |
Ian Rogers | 1d54e73 | 2013-05-02 21:10:01 -0700 | [diff] [blame] | 173 | current_split_start_ns_ = current_time; |
| 174 | } |
| 175 | |
Anwar Ghuloum | 6f28d91 | 2013-07-24 15:02:53 -0700 | [diff] [blame^] | 176 | void TimingLogger::EndSplit() { |
Ian Rogers | 1d54e73 | 2013-05-02 21:10:01 -0700 | [diff] [blame] | 177 | DCHECK(current_split_ != NULL); |
| 178 | uint64_t current_time = NanoTime(); |
| 179 | uint64_t split_time = current_time - current_split_start_ns_; |
Anwar Ghuloum | 6f28d91 | 2013-07-24 15:02:53 -0700 | [diff] [blame^] | 180 | ATRACE_END(); |
Ian Rogers | 1d54e73 | 2013-05-02 21:10:01 -0700 | [diff] [blame] | 181 | if (verbose_) { |
| 182 | LOG(INFO) << "End: " << current_split_ << " " << PrettyDuration(split_time); |
| 183 | } |
| 184 | splits_.push_back(std::pair<uint64_t, const char*>(split_time, current_split_)); |
| 185 | } |
| 186 | |
Anwar Ghuloum | 6f28d91 | 2013-07-24 15:02:53 -0700 | [diff] [blame^] | 187 | uint64_t TimingLogger::GetTotalNs() const { |
Ian Rogers | 1d54e73 | 2013-05-02 21:10:01 -0700 | [diff] [blame] | 188 | uint64_t total_ns = 0; |
| 189 | typedef std::vector<std::pair<uint64_t, const char*> >::const_iterator It; |
| 190 | for (It it = splits_.begin(), end = splits_.end(); it != end; ++it) { |
| 191 | std::pair<uint64_t, const char*> split = *it; |
| 192 | total_ns += split.first; |
| 193 | } |
| 194 | return total_ns; |
| 195 | } |
| 196 | |
Anwar Ghuloum | 6f28d91 | 2013-07-24 15:02:53 -0700 | [diff] [blame^] | 197 | void TimingLogger::Dump(std::ostream &os) const { |
Ian Rogers | 1d54e73 | 2013-05-02 21:10:01 -0700 | [diff] [blame] | 198 | uint64_t longest_split = 0; |
| 199 | uint64_t total_ns = 0; |
| 200 | typedef std::vector<std::pair<uint64_t, const char*> >::const_iterator It; |
| 201 | for (It it = splits_.begin(), end = splits_.end(); it != end; ++it) { |
| 202 | std::pair<uint64_t, const char*> split = *it; |
| 203 | uint64_t split_time = split.first; |
| 204 | longest_split = std::max(longest_split, split_time); |
| 205 | total_ns += split_time; |
| 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 | // Print formatted splits. |
| 211 | for (It it = splits_.begin(), end = splits_.end(); it != end; ++it) { |
| 212 | std::pair<uint64_t, const char*> split = *it; |
| 213 | uint64_t split_time = split.first; |
| 214 | if (!precise_ && divisor >= 1000) { |
| 215 | // Make the fractional part 0. |
| 216 | split_time -= split_time % (divisor / 1000); |
| 217 | } |
| 218 | os << name_ << ": " << std::setw(8) << FormatDuration(split_time, tu) << " " |
| 219 | << split.second << "\n"; |
| 220 | } |
| 221 | os << name_ << ": end, " << NsToMs(total_ns) << " ms\n"; |
| 222 | } |
| 223 | |
| 224 | } // namespace base |
Sameer Abu Asal | a843954 | 2013-02-14 16:06:42 -0800 | [diff] [blame] | 225 | } // namespace art |