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