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