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