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/mutex.h"
24 #include "base/stl_util.h"
25 #include "base/systrace.h"
26 #include "base/time_utils.h"
27 #include "gc/heap.h"
28 #include "runtime.h"
29 #include "thread-current-inl.h"
30
31 #include <cmath>
32 #include <iomanip>
33
34 namespace art {
35
CumulativeLogger(const std::string & name)36 CumulativeLogger::CumulativeLogger(const std::string& name)
37 : name_(name),
38 lock_name_("CumulativeLoggerLock" + name),
39 lock_(new Mutex(lock_name_.c_str(), kDefaultMutexLevel, true)) {
40 Reset();
41 }
42
~CumulativeLogger()43 CumulativeLogger::~CumulativeLogger() {
44 cumulative_timers_.clear();
45 }
46
SetName(const std::string & name)47 void CumulativeLogger::SetName(const std::string& name) {
48 MutexLock mu(Thread::Current(), *GetLock());
49 name_.assign(name);
50 }
51
Start()52 void CumulativeLogger::Start() {
53 }
54
End()55 void CumulativeLogger::End() {
56 MutexLock mu(Thread::Current(), *GetLock());
57 ++iterations_;
58 }
59
Reset()60 void CumulativeLogger::Reset() {
61 MutexLock mu(Thread::Current(), *GetLock());
62 iterations_ = 0;
63 total_time_ = 0;
64 cumulative_timers_.clear();
65 }
66
AddLogger(const TimingLogger & logger)67 void CumulativeLogger::AddLogger(const TimingLogger &logger) {
68 MutexLock mu(Thread::Current(), *GetLock());
69 TimingLogger::TimingData timing_data(logger.CalculateTimingData());
70 const std::vector<TimingLogger::Timing>& timings = logger.GetTimings();
71 for (size_t i = 0; i < timings.size(); ++i) {
72 if (timings[i].IsStartTiming()) {
73 AddPair(timings[i].GetName(), timing_data.GetExclusiveTime(i));
74 }
75 }
76 ++iterations_;
77 }
78
GetIterations() const79 size_t CumulativeLogger::GetIterations() const {
80 MutexLock mu(Thread::Current(), *GetLock());
81 return iterations_;
82 }
83
Dump(std::ostream & os) const84 void CumulativeLogger::Dump(std::ostream &os) const {
85 MutexLock mu(Thread::Current(), *GetLock());
86 DumpAverages(os);
87 }
88
AddPair(const char * label,uint64_t delta_time)89 void CumulativeLogger::AddPair(const char* label, uint64_t delta_time) {
90 // Convert delta time to microseconds so that we don't overflow our counters.
91 delta_time /= kAdjust;
92 total_time_ += delta_time;
93 CumulativeTime candidate(label, delta_time);
94 auto it = std::lower_bound(cumulative_timers_.begin(), cumulative_timers_.end(), candidate);
95 // Maintain the vector sorted so that lookup above, which is more frequent can
96 // happen in log(n).
97 if (it == cumulative_timers_.end() || it->Name() != label) {
98 cumulative_timers_.insert(it, candidate);
99 } else {
100 it->Add(delta_time);
101 }
102 }
103
DumpAverages(std::ostream & os) const104 void CumulativeLogger::DumpAverages(std::ostream &os) const {
105 os << "Start Dumping Averages for " << iterations_ << " iterations"
106 << " for " << name_ << "\n";
107 const size_t timers_sz = cumulative_timers_.size();
108 // Create an array of pointers to cumulative timers on stack and sort it in
109 // decreasing order of accumulated timer so that the most time consuming
110 // timer is printed first.
111 const CumulativeTime* sorted_timers[timers_sz];
112 for (size_t i = 0; i < timers_sz; i++) {
113 sorted_timers[i] = cumulative_timers_.data() + i;
114 }
115 std::sort(sorted_timers,
116 sorted_timers + timers_sz,
117 [](const CumulativeTime* a, const CumulativeTime* b) { return a->Sum() > b->Sum(); });
118 for (size_t i = 0; i < timers_sz; i++) {
119 const CumulativeTime *timer = sorted_timers[i];
120 uint64_t total_time_ns = timer->Sum() * kAdjust;
121 os << timer->Name()
122 << ":\tSum: " << PrettyDuration(total_time_ns)
123 << " Avg: " << PrettyDuration(total_time_ns / iterations_) << "\n";
124 }
125 os << "Done Dumping Averages\n";
126 }
127
TimingLogger(const char * name,bool precise,bool verbose,TimingLogger::TimingKind kind)128 TimingLogger::TimingLogger(const char* name,
129 bool precise,
130 bool verbose,
131 TimingLogger::TimingKind kind)
132 : name_(name), precise_(precise), verbose_(verbose), kind_(kind) {
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(kind_, label));
142 ATraceBegin(label);
143 }
144
EndTiming()145 void TimingLogger::EndTiming() {
146 timings_.push_back(Timing(kind_, nullptr));
147 ATraceEnd();
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