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; |
Mathieu Chartier | e5426c9 | 2013-08-01 13:55:42 -0700 | [diff] [blame] | 82 | // The first time this is run, the histograms array will be empty. |
| 83 | if (kIsDebugBuild && !histograms_.empty() && splits.size() != histograms_.size()) { |
Ian Rogers | 1d54e73 | 2013-05-02 21:10:01 -0700 | [diff] [blame] | 84 | LOG(ERROR) << "Mismatch in splits."; |
| 85 | typedef std::vector<Histogram<uint64_t> *>::const_iterator It2; |
| 86 | It it = splits.begin(); |
| 87 | It2 it2 = histograms_.begin(); |
| 88 | while ((it != splits.end()) && (it2 != histograms_.end())) { |
| 89 | if (it != splits.end()) { |
| 90 | LOG(ERROR) << "\tsplit: " << it->second; |
| 91 | ++it; |
| 92 | } |
| 93 | if (it2 != histograms_.end()) { |
| 94 | LOG(ERROR) << "\tpreviously record: " << (*it2)->Name(); |
| 95 | ++it2; |
| 96 | } |
| 97 | } |
| 98 | } |
| 99 | for (It it = splits.begin(), end = splits.end(); it != end; ++it) { |
| 100 | std::pair<uint64_t, const char*> split = *it; |
| 101 | uint64_t split_time = split.first; |
| 102 | const char* split_name = split.second; |
| 103 | AddPair(split_name, split_time); |
| 104 | } |
| 105 | } |
| 106 | |
Sameer Abu Asal | a843954 | 2013-02-14 16:06:42 -0800 | [diff] [blame] | 107 | void CumulativeLogger::Dump(std::ostream &os) { |
| 108 | MutexLock mu(Thread::Current(), lock_); |
| 109 | DumpHistogram(os); |
| 110 | } |
| 111 | |
| 112 | void CumulativeLogger::AddPair(const std::string &label, uint64_t delta_time) { |
Sameer Abu Asal | a843954 | 2013-02-14 16:06:42 -0800 | [diff] [blame] | 113 | // Convert delta time to microseconds so that we don't overflow our counters. |
| 114 | delta_time /= kAdjust; |
Mathieu Chartier | e5426c9 | 2013-08-01 13:55:42 -0700 | [diff] [blame] | 115 | if (histograms_.size() <= index_) { |
Mathieu Chartier | e0a53e9 | 2013-08-05 10:17:40 -0700 | [diff] [blame^] | 116 | const size_t max_buckets = Runtime::Current()->GetHeap()->IsLowMemoryMode() ? 16 : 100; |
| 117 | histograms_.push_back(new Histogram<uint64_t>(label.c_str(), 50, max_buckets)); |
Mathieu Chartier | e5426c9 | 2013-08-01 13:55:42 -0700 | [diff] [blame] | 118 | DCHECK_GT(histograms_.size(), index_); |
Sameer Abu Asal | a843954 | 2013-02-14 16:06:42 -0800 | [diff] [blame] | 119 | } |
Mathieu Chartier | e5426c9 | 2013-08-01 13:55:42 -0700 | [diff] [blame] | 120 | histograms_[index_]->AddValue(delta_time); |
| 121 | DCHECK_EQ(label, histograms_[index_]->Name()); |
| 122 | ++index_; |
Sameer Abu Asal | a843954 | 2013-02-14 16:06:42 -0800 | [diff] [blame] | 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++) { |
Mathieu Chartier | e5426c9 | 2013-08-01 13:55:42 -0700 | [diff] [blame] | 129 | Histogram<uint64_t>::CumulativeData cumulative_data; |
| 130 | histograms_[Idx]->CreateHistogram(cumulative_data); |
| 131 | histograms_[Idx]->PrintConfidenceIntervals(os, 0.99, cumulative_data); |
| 132 | // Reset cumulative values to save memory. We don't expect DumpHistogram to be called often, so |
| 133 | // it is not performance critical. |
Sameer Abu Asal | a843954 | 2013-02-14 16:06:42 -0800 | [diff] [blame] | 134 | } |
| 135 | os << "Done Dumping histograms \n"; |
| 136 | } |
| 137 | |
Ian Rogers | 1d54e73 | 2013-05-02 21:10:01 -0700 | [diff] [blame] | 138 | |
| 139 | namespace base { |
| 140 | |
Anwar Ghuloum | 6f28d91 | 2013-07-24 15:02:53 -0700 | [diff] [blame] | 141 | TimingLogger::TimingLogger(const char* name, bool precise, bool verbose) |
Ian Rogers | 1d54e73 | 2013-05-02 21:10:01 -0700 | [diff] [blame] | 142 | : name_(name), precise_(precise), verbose_(verbose), |
| 143 | current_split_(NULL), current_split_start_ns_(0) { |
| 144 | } |
| 145 | |
Anwar Ghuloum | 6f28d91 | 2013-07-24 15:02:53 -0700 | [diff] [blame] | 146 | void TimingLogger::Reset() { |
Ian Rogers | 1d54e73 | 2013-05-02 21:10:01 -0700 | [diff] [blame] | 147 | current_split_ = NULL; |
| 148 | current_split_start_ns_ = 0; |
| 149 | splits_.clear(); |
| 150 | } |
| 151 | |
Anwar Ghuloum | 6f28d91 | 2013-07-24 15:02:53 -0700 | [diff] [blame] | 152 | void TimingLogger::StartSplit(const char* new_split_label) { |
Ian Rogers | 1d54e73 | 2013-05-02 21:10:01 -0700 | [diff] [blame] | 153 | DCHECK(current_split_ == NULL); |
| 154 | if (verbose_) { |
| 155 | LOG(INFO) << "Begin: " << new_split_label; |
| 156 | } |
| 157 | current_split_ = new_split_label; |
Anwar Ghuloum | 6f28d91 | 2013-07-24 15:02:53 -0700 | [diff] [blame] | 158 | ATRACE_BEGIN(current_split_); |
Ian Rogers | 1d54e73 | 2013-05-02 21:10:01 -0700 | [diff] [blame] | 159 | current_split_start_ns_ = NanoTime(); |
| 160 | } |
| 161 | |
| 162 | // Ends the current split and starts the one given by the label. |
Anwar Ghuloum | 6f28d91 | 2013-07-24 15:02:53 -0700 | [diff] [blame] | 163 | void TimingLogger::NewSplit(const char* new_split_label) { |
Ian Rogers | 1d54e73 | 2013-05-02 21:10:01 -0700 | [diff] [blame] | 164 | DCHECK(current_split_ != NULL); |
| 165 | uint64_t current_time = NanoTime(); |
| 166 | uint64_t split_time = current_time - current_split_start_ns_; |
Anwar Ghuloum | 6f28d91 | 2013-07-24 15:02:53 -0700 | [diff] [blame] | 167 | ATRACE_END(); |
Ian Rogers | 1d54e73 | 2013-05-02 21:10:01 -0700 | [diff] [blame] | 168 | splits_.push_back(std::pair<uint64_t, const char*>(split_time, current_split_)); |
| 169 | if (verbose_) { |
| 170 | LOG(INFO) << "End: " << current_split_ << " " << PrettyDuration(split_time) << "\n" |
| 171 | << "Begin: " << new_split_label; |
| 172 | } |
| 173 | current_split_ = new_split_label; |
Anwar Ghuloum | 6f28d91 | 2013-07-24 15:02:53 -0700 | [diff] [blame] | 174 | ATRACE_BEGIN(current_split_); |
Ian Rogers | 1d54e73 | 2013-05-02 21:10:01 -0700 | [diff] [blame] | 175 | current_split_start_ns_ = current_time; |
| 176 | } |
| 177 | |
Anwar Ghuloum | 6f28d91 | 2013-07-24 15:02:53 -0700 | [diff] [blame] | 178 | void TimingLogger::EndSplit() { |
Ian Rogers | 1d54e73 | 2013-05-02 21:10:01 -0700 | [diff] [blame] | 179 | DCHECK(current_split_ != NULL); |
| 180 | uint64_t current_time = NanoTime(); |
| 181 | uint64_t split_time = current_time - current_split_start_ns_; |
Anwar Ghuloum | 6f28d91 | 2013-07-24 15:02:53 -0700 | [diff] [blame] | 182 | ATRACE_END(); |
Ian Rogers | 1d54e73 | 2013-05-02 21:10:01 -0700 | [diff] [blame] | 183 | if (verbose_) { |
| 184 | LOG(INFO) << "End: " << current_split_ << " " << PrettyDuration(split_time); |
| 185 | } |
| 186 | splits_.push_back(std::pair<uint64_t, const char*>(split_time, current_split_)); |
| 187 | } |
| 188 | |
Anwar Ghuloum | 6f28d91 | 2013-07-24 15:02:53 -0700 | [diff] [blame] | 189 | uint64_t TimingLogger::GetTotalNs() const { |
Ian Rogers | 1d54e73 | 2013-05-02 21:10:01 -0700 | [diff] [blame] | 190 | uint64_t total_ns = 0; |
| 191 | typedef std::vector<std::pair<uint64_t, const char*> >::const_iterator It; |
| 192 | for (It it = splits_.begin(), end = splits_.end(); it != end; ++it) { |
| 193 | std::pair<uint64_t, const char*> split = *it; |
| 194 | total_ns += split.first; |
| 195 | } |
| 196 | return total_ns; |
| 197 | } |
| 198 | |
Anwar Ghuloum | 6f28d91 | 2013-07-24 15:02:53 -0700 | [diff] [blame] | 199 | void TimingLogger::Dump(std::ostream &os) const { |
Ian Rogers | 1d54e73 | 2013-05-02 21:10:01 -0700 | [diff] [blame] | 200 | uint64_t longest_split = 0; |
| 201 | uint64_t total_ns = 0; |
| 202 | typedef std::vector<std::pair<uint64_t, const char*> >::const_iterator It; |
| 203 | for (It it = splits_.begin(), end = splits_.end(); it != end; ++it) { |
| 204 | std::pair<uint64_t, const char*> split = *it; |
| 205 | uint64_t split_time = split.first; |
| 206 | longest_split = std::max(longest_split, split_time); |
| 207 | total_ns += split_time; |
| 208 | } |
| 209 | // Compute which type of unit we will use for printing the timings. |
| 210 | TimeUnit tu = GetAppropriateTimeUnit(longest_split); |
| 211 | uint64_t divisor = GetNsToTimeUnitDivisor(tu); |
| 212 | // Print formatted splits. |
| 213 | for (It it = splits_.begin(), end = splits_.end(); it != end; ++it) { |
| 214 | std::pair<uint64_t, const char*> split = *it; |
| 215 | uint64_t split_time = split.first; |
| 216 | if (!precise_ && divisor >= 1000) { |
| 217 | // Make the fractional part 0. |
| 218 | split_time -= split_time % (divisor / 1000); |
| 219 | } |
| 220 | os << name_ << ": " << std::setw(8) << FormatDuration(split_time, tu) << " " |
| 221 | << split.second << "\n"; |
| 222 | } |
| 223 | os << name_ << ": end, " << NsToMs(total_ns) << " ms\n"; |
| 224 | } |
| 225 | |
| 226 | } // namespace base |
Sameer Abu Asal | a843954 | 2013-02-14 16:06:42 -0800 | [diff] [blame] | 227 | } // namespace art |