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