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