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