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 #ifndef ART_RUNTIME_BASE_TIMING_LOGGER_H_
18 #define ART_RUNTIME_BASE_TIMING_LOGGER_H_
19 
20 #include "base/histogram.h"
21 #include "base/locks.h"
22 #include "base/macros.h"
23 #include "base/time_utils.h"
24 
25 #include <memory>
26 #include <set>
27 #include <string>
28 #include <vector>
29 
30 namespace art {
31 class TimingLogger;
32 
33 class CumulativeLogger {
34  public:
35   explicit CumulativeLogger(const std::string& name);
36   ~CumulativeLogger();
37   void Start();
38   void End() REQUIRES(!GetLock());
39   void Reset() REQUIRES(!GetLock());
40   void Dump(std::ostream& os) const REQUIRES(!GetLock());
GetTotalNs()41   uint64_t GetTotalNs() const {
42     return GetTotalTime() * kAdjust;
43   }
44   // Allow the name to be modified, particularly when the cumulative logger is a field within a
45   // parent class that is unable to determine the "name" of a sub-class.
46   void SetName(const std::string& name) REQUIRES(!GetLock());
47   void AddLogger(const TimingLogger& logger) REQUIRES(!GetLock());
48   size_t GetIterations() const REQUIRES(!GetLock());
49 
50  private:
51   class HistogramComparator {
52    public:
operator()53     bool operator()(const Histogram<uint64_t>* a, const Histogram<uint64_t>* b) const {
54       return a->Name() < b->Name();
55     }
56   };
57 
58   static constexpr size_t kLowMemoryBucketCount = 16;
59   static constexpr size_t kDefaultBucketCount = 100;
60   static constexpr size_t kInitialBucketSize = 50;  // 50 microseconds.
61 
62   void AddPair(const std::string &label, uint64_t delta_time) REQUIRES(GetLock());
63   void DumpHistogram(std::ostream &os) const REQUIRES(GetLock());
GetTotalTime()64   uint64_t GetTotalTime() const {
65     return total_time_;
66   }
67 
GetLock()68   Mutex* GetLock() const {
69     return lock_.get();
70   }
71 
72   static const uint64_t kAdjust = 1000;
73   std::set<Histogram<uint64_t>*, HistogramComparator> histograms_ GUARDED_BY(GetLock());
74   std::string name_;
75   const std::string lock_name_;
76   mutable std::unique_ptr<Mutex> lock_ DEFAULT_MUTEX_ACQUIRED_AFTER;
77   size_t iterations_ GUARDED_BY(GetLock());
78   uint64_t total_time_;
79 
80   DISALLOW_COPY_AND_ASSIGN(CumulativeLogger);
81 };
82 
83 // A timing logger that knows when a split starts for the purposes of logging tools, like systrace.
84 class TimingLogger {
85  public:
86   static constexpr size_t kIndexNotFound = static_cast<size_t>(-1);
87 
88   // Kind of timing we are going to do. We collect time at the nano second.
89   enum class TimingKind {
90     kMonotonic,
91     kThreadCpu,
92   };
93 
94   class Timing {
95    public:
Timing(TimingKind kind,const char * name)96     Timing(TimingKind kind, const char* name) : name_(name) {
97        switch (kind) {
98         case TimingKind::kMonotonic:
99           time_ = NanoTime();
100           break;
101         case TimingKind::kThreadCpu:
102           time_ = ThreadCpuNanoTime();
103           break;
104        }
105     }
IsStartTiming()106     bool IsStartTiming() const {
107       return !IsEndTiming();
108     }
IsEndTiming()109     bool IsEndTiming() const {
110       return name_ == nullptr;
111     }
GetTime()112     uint64_t GetTime() const {
113       return time_;
114     }
GetName()115     const char* GetName() const {
116       return name_;
117     }
118 
119    private:
120     uint64_t time_;
121     const char* name_;
122   };
123 
124   // Extra data that is only calculated when you call dump to prevent excess allocation.
125   class TimingData {
126    public:
127     TimingData() = default;
TimingData(TimingData && other)128     TimingData(TimingData&& other) {
129       std::swap(data_, other.data_);
130     }
131     TimingData& operator=(TimingData&& other) {
132       std::swap(data_, other.data_);
133       return *this;
134     }
GetTotalTime(size_t idx)135     uint64_t GetTotalTime(size_t idx) {
136       return data_[idx].total_time;
137     }
GetExclusiveTime(size_t idx)138     uint64_t GetExclusiveTime(size_t idx) {
139       return data_[idx].exclusive_time;
140     }
141 
142    private:
143     // Each begin split has a total time and exclusive time. Exclusive time is total time - total
144     // time of children nodes.
145     struct CalculatedDataPoint {
CalculatedDataPointCalculatedDataPoint146       CalculatedDataPoint() : total_time(0), exclusive_time(0) {}
147       uint64_t total_time;
148       uint64_t exclusive_time;
149     };
150     std::vector<CalculatedDataPoint> data_;
151     friend class TimingLogger;
152   };
153 
154   TimingLogger(const char* name,
155                bool precise,
156                bool verbose,
157                TimingKind kind = TimingKind::kMonotonic);
158   ~TimingLogger();
159   // Verify that all open timings have related closed timings.
160   void Verify();
161   // Clears current timings and labels.
162   void Reset();
163   // Starts a timing.
164   void StartTiming(const char* new_split_label);
165   // Ends the current timing.
166   void EndTiming();
167   // End the current timing and start a new timing. Usage not recommended.
NewTiming(const char * new_split_label)168   void NewTiming(const char* new_split_label) {
169     EndTiming();
170     StartTiming(new_split_label);
171   }
172   // Returns the total duration of the timings (sum of total times).
173   uint64_t GetTotalNs() const;
174   // Find the index of a timing by name.
175   size_t FindTimingIndex(const char* name, size_t start_idx) const;
176   void Dump(std::ostream& os, const char* indent_string = "  ") const;
177 
178   // Scoped timing splits that can be nested and composed with the explicit split
179   // starts and ends.
180   class ScopedTiming {
181    public:
ScopedTiming(const char * label,TimingLogger * logger)182     ScopedTiming(const char* label, TimingLogger* logger) : logger_(logger) {
183       logger_->StartTiming(label);
184     }
~ScopedTiming()185     ~ScopedTiming() {
186       logger_->EndTiming();
187     }
188     // Closes the current timing and opens a new timing.
NewTiming(const char * label)189     void NewTiming(const char* label) {
190       logger_->NewTiming(label);
191     }
192 
193    private:
194     TimingLogger* const logger_;  // The timing logger which the scoped timing is associated with.
195     DISALLOW_COPY_AND_ASSIGN(ScopedTiming);
196   };
197 
198   // Return the time points of when each start / end timings start and finish.
GetTimings()199   const std::vector<Timing>& GetTimings() const {
200     return timings_;
201   }
202 
203   TimingData CalculateTimingData() const;
204 
205  protected:
206   // The name of the timing logger.
207   const char* const name_;
208   // Do we want to print the exactly recorded split (true) or round down to the time unit being
209   // used (false).
210   const bool precise_;
211   // Verbose logging.
212   const bool verbose_;
213   // The kind of timing we want.
214   const TimingKind kind_;
215   // Timing points that are either start or end points. For each starting point ret[i] = location
216   // of end split associated with i. If it is and end split ret[i] = i.
217   std::vector<Timing> timings_;
218 
219  private:
220   DISALLOW_COPY_AND_ASSIGN(TimingLogger);
221 };
222 
223 }  // namespace art
224 
225 #endif  // ART_RUNTIME_BASE_TIMING_LOGGER_H_
226