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