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 
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_(new Mutex(lock_name_.c_str(), kDefaultMutexLevel, true)) {
42   Reset();
43 }
44 
~CumulativeLogger()45 CumulativeLogger::~CumulativeLogger() {
46   cumulative_timers_.clear();
47 }
48 
SetName(const std::string & name)49 void CumulativeLogger::SetName(const std::string& name) {
50   MutexLock mu(Thread::Current(), *GetLock());
51   name_.assign(name);
52 }
53 
Start()54 void CumulativeLogger::Start() {
55 }
56 
End()57 void CumulativeLogger::End() {
58   MutexLock mu(Thread::Current(), *GetLock());
59   ++iterations_;
60 }
61 
Reset()62 void CumulativeLogger::Reset() {
63   MutexLock mu(Thread::Current(), *GetLock());
64   iterations_ = 0;
65   total_time_ = 0;
66   cumulative_timers_.clear();
67 }
68 
AddLogger(const TimingLogger & logger)69 void CumulativeLogger::AddLogger(const TimingLogger &logger) {
70   MutexLock mu(Thread::Current(), *GetLock());
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(), *GetLock());
83   return iterations_;
84 }
85 
Dump(std::ostream & os) const86 void CumulativeLogger::Dump(std::ostream &os) const {
87   MutexLock mu(Thread::Current(), *GetLock());
88   DumpAverages(os);
89 }
90 
AddPair(const char * label,uint64_t delta_time)91 void CumulativeLogger::AddPair(const char* 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   CumulativeTime candidate(label, delta_time);
96   auto it = std::lower_bound(cumulative_timers_.begin(), cumulative_timers_.end(), candidate);
97   // Maintain the vector sorted so that lookup above, which is more frequent can
98   // happen in log(n).
99   if (it == cumulative_timers_.end() || it->Name() != label) {
100     cumulative_timers_.insert(it, candidate);
101   } else {
102     it->Add(delta_time);
103   }
104 }
105 
DumpAverages(std::ostream & os) const106 void CumulativeLogger::DumpAverages(std::ostream &os) const {
107   os << "Start Dumping Averages for " << iterations_ << " iterations"
108      << " for " << name_ << "\n";
109   const size_t timers_sz = cumulative_timers_.size();
110   // Create an array of pointers to cumulative timers on stack and sort it in
111   // decreasing order of accumulated timer so that the most time consuming
112   // timer is printed first.
113   const CumulativeTime* sorted_timers[timers_sz];
114   for (size_t i = 0; i < timers_sz; i++) {
115     sorted_timers[i] = cumulative_timers_.data() + i;
116   }
117   std::sort(sorted_timers,
118             sorted_timers + timers_sz,
119             [](const CumulativeTime* a, const CumulativeTime* b) { return a->Sum() > b->Sum(); });
120   for (size_t i = 0; i < timers_sz; i++) {
121     const CumulativeTime *timer = sorted_timers[i];
122     uint64_t total_time_ns = timer->Sum() * kAdjust;
123     os << timer->Name()
124        << ":\tSum: " << PrettyDuration(total_time_ns)
125        << " Avg: " << PrettyDuration(total_time_ns / iterations_) << "\n";
126   }
127   os << "Done Dumping Averages\n";
128 }
129 
TimingLogger(const char * name,bool precise,bool verbose,TimingLogger::TimingKind kind)130 TimingLogger::TimingLogger(const char* name,
131                            bool precise,
132                            bool verbose,
133                            TimingLogger::TimingKind kind)
134     : name_(name), precise_(precise), verbose_(verbose), kind_(kind) {
135 }
136 
Reset()137 void TimingLogger::Reset() {
138   timings_.clear();
139 }
140 
StartTiming(const char * label)141 void TimingLogger::StartTiming(const char* label) {
142   DCHECK(label != nullptr);
143   timings_.push_back(Timing(kind_, label));
144   ATraceBegin(label);
145 }
146 
EndTiming()147 void TimingLogger::EndTiming() {
148   timings_.push_back(Timing(kind_, nullptr));
149   ATraceEnd();
150 }
151 
GetTotalNs() const152 uint64_t TimingLogger::GetTotalNs() const {
153   if (timings_.size() < 2) {
154     return 0;
155   }
156   return timings_.back().GetTime() - timings_.front().GetTime();
157 }
158 
FindTimingIndex(const char * name,size_t start_idx) const159 size_t TimingLogger::FindTimingIndex(const char* name, size_t start_idx) const {
160   DCHECK_LT(start_idx, timings_.size());
161   for (size_t i = start_idx; i < timings_.size(); ++i) {
162     if (timings_[i].IsStartTiming() && strcmp(timings_[i].GetName(), name) == 0) {
163       return i;
164     }
165   }
166   return kIndexNotFound;
167 }
168 
CalculateTimingData() const169 TimingLogger::TimingData TimingLogger::CalculateTimingData() const {
170   TimingLogger::TimingData ret;
171   ret.data_.resize(timings_.size());
172   std::vector<size_t> open_stack;
173   for (size_t i = 0; i < timings_.size(); ++i) {
174     if (timings_[i].IsEndTiming()) {
175       CHECK(!open_stack.empty()) << "No starting split for ending split at index " << i;
176       size_t open_idx = open_stack.back();
177       uint64_t time = timings_[i].GetTime() - timings_[open_idx].GetTime();
178       ret.data_[open_idx].exclusive_time += time;
179       DCHECK_EQ(ret.data_[open_idx].total_time, 0U);
180       ret.data_[open_idx].total_time += time;
181       // Each open split has exactly one end.
182       open_stack.pop_back();
183       // If there is a parent node, subtract from the exclusive time.
184       if (!open_stack.empty()) {
185         // Note this may go negative, but will work due to 2s complement when we add the value
186         // total time value later.
187         ret.data_[open_stack.back()].exclusive_time -= time;
188       }
189     } else {
190       open_stack.push_back(i);
191     }
192   }
193   CHECK(open_stack.empty()) << "Missing ending for timing "
194       << timings_[open_stack.back()].GetName() << " at index " << open_stack.back();
195   return ret;  // No need to fear, C++11 move semantics are here.
196 }
197 
Dump(std::ostream & os,const char * indent_string) const198 void TimingLogger::Dump(std::ostream &os, const char* indent_string) const {
199   static constexpr size_t kFractionalDigits = 3;
200   TimingLogger::TimingData timing_data(CalculateTimingData());
201   uint64_t longest_split = 0;
202   for (size_t i = 0; i < timings_.size(); ++i) {
203     longest_split = std::max(longest_split, timing_data.GetTotalTime(i));
204   }
205   // Compute which type of unit we will use for printing the timings.
206   TimeUnit tu = GetAppropriateTimeUnit(longest_split);
207   uint64_t divisor = GetNsToTimeUnitDivisor(tu);
208   uint64_t mod_fraction = divisor >= 1000 ? divisor / 1000 : 1;
209   // Print formatted splits.
210   size_t tab_count = 1;
211   os << name_ << " [Exclusive time] [Total time]\n";
212   for (size_t i = 0; i < timings_.size(); ++i) {
213     if (timings_[i].IsStartTiming()) {
214       uint64_t exclusive_time = timing_data.GetExclusiveTime(i);
215       uint64_t total_time = timing_data.GetTotalTime(i);
216       if (!precise_) {
217         // Make the fractional part 0.
218         exclusive_time -= exclusive_time % mod_fraction;
219         total_time -= total_time % mod_fraction;
220       }
221       for (size_t j = 0; j < tab_count; ++j) {
222         os << indent_string;
223       }
224       os << FormatDuration(exclusive_time, tu, kFractionalDigits);
225       // If they are the same, just print one value to prevent spam.
226       if (exclusive_time != total_time) {
227         os << "/" << FormatDuration(total_time, tu, kFractionalDigits);
228       }
229       os << " " << timings_[i].GetName() << "\n";
230       ++tab_count;
231     } else {
232       --tab_count;
233     }
234   }
235   os << name_ << ": end, " << PrettyDuration(GetTotalNs()) << "\n";
236 }
237 
Verify()238 void TimingLogger::Verify() {
239   size_t counts[2] = { 0 };
240   for (size_t i = 0; i < timings_.size(); ++i) {
241     if (i > 0) {
242       CHECK_LE(timings_[i - 1].GetTime(), timings_[i].GetTime());
243     }
244     ++counts[timings_[i].IsStartTiming() ? 0 : 1];
245   }
246   CHECK_EQ(counts[0], counts[1]) << "Number of StartTiming and EndTiming doesn't match";
247 }
248 
~TimingLogger()249 TimingLogger::~TimingLogger() {
250   if (kIsDebugBuild) {
251     Verify();
252   }
253 }
254 
255 }  // namespace art
256