Sameer Abu Asal | a843954 | 2013-02-14 16:06:42 -0800 | [diff] [blame] | 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 | |
Brian Carlstrom | fc0e321 | 2013-07-17 14:40:12 -0700 | [diff] [blame] | 17 | #ifndef ART_RUNTIME_BASE_TIMING_LOGGER_H_ |
| 18 | #define ART_RUNTIME_BASE_TIMING_LOGGER_H_ |
Sameer Abu Asal | a843954 | 2013-02-14 16:06:42 -0800 | [diff] [blame] | 19 | |
| 20 | #include "base/histogram.h" |
Andreas Gampe | 0bbac30 | 2018-11-30 09:44:12 -0800 | [diff] [blame] | 21 | #include "base/locks.h" |
Sameer Abu Asal | a843954 | 2013-02-14 16:06:42 -0800 | [diff] [blame] | 22 | #include "base/macros.h" |
Nicolas Geoffray | 3d69922 | 2017-09-20 15:15:20 +0100 | [diff] [blame] | 23 | #include "base/time_utils.h" |
Sameer Abu Asal | a843954 | 2013-02-14 16:06:42 -0800 | [diff] [blame] | 24 | |
Andreas Gampe | 0bbac30 | 2018-11-30 09:44:12 -0800 | [diff] [blame] | 25 | #include <memory> |
Mathieu Chartier | 19b0a91 | 2013-11-20 14:07:54 -0800 | [diff] [blame] | 26 | #include <set> |
Sameer Abu Asal | a843954 | 2013-02-14 16:06:42 -0800 | [diff] [blame] | 27 | #include <string> |
| 28 | #include <vector> |
| 29 | |
| 30 | namespace art { |
Ian Rogers | 5fe9af7 | 2013-11-14 00:17:20 -0800 | [diff] [blame] | 31 | class TimingLogger; |
Ian Rogers | 1d54e73 | 2013-05-02 21:10:01 -0700 | [diff] [blame] | 32 | |
Sameer Abu Asal | a843954 | 2013-02-14 16:06:42 -0800 | [diff] [blame] | 33 | class CumulativeLogger { |
Sameer Abu Asal | a843954 | 2013-02-14 16:06:42 -0800 | [diff] [blame] | 34 | public: |
Ian Rogers | 4535705 | 2013-04-18 20:49:43 -0700 | [diff] [blame] | 35 | explicit CumulativeLogger(const std::string& name); |
Sameer Abu Asal | a843954 | 2013-02-14 16:06:42 -0800 | [diff] [blame] | 36 | ~CumulativeLogger(); |
| 37 | void Start(); |
Andreas Gampe | 0bbac30 | 2018-11-30 09:44:12 -0800 | [diff] [blame] | 38 | void End() REQUIRES(!GetLock()); |
| 39 | void Reset() REQUIRES(!GetLock()); |
| 40 | void Dump(std::ostream& os) const REQUIRES(!GetLock()); |
Mathieu Chartier | afe4998 | 2014-03-27 10:55:04 -0700 | [diff] [blame] | 41 | uint64_t GetTotalNs() const { |
| 42 | return GetTotalTime() * kAdjust; |
| 43 | } |
Ian Rogers | 4535705 | 2013-04-18 20:49:43 -0700 | [diff] [blame] | 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. |
Andreas Gampe | 0bbac30 | 2018-11-30 09:44:12 -0800 | [diff] [blame] | 46 | void SetName(const std::string& name) REQUIRES(!GetLock()); |
| 47 | void AddLogger(const TimingLogger& logger) REQUIRES(!GetLock()); |
| 48 | size_t GetIterations() const REQUIRES(!GetLock()); |
Sameer Abu Asal | a843954 | 2013-02-14 16:06:42 -0800 | [diff] [blame] | 49 | |
| 50 | private: |
Mathieu Chartier | 19b0a91 | 2013-11-20 14:07:54 -0800 | [diff] [blame] | 51 | class HistogramComparator { |
| 52 | public: |
| 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. |
Anwar Ghuloum | 67f9941 | 2013-08-12 14:19:48 -0700 | [diff] [blame] | 61 | |
Andreas Gampe | 0bbac30 | 2018-11-30 09:44:12 -0800 | [diff] [blame] | 62 | void AddPair(const std::string &label, uint64_t delta_time) REQUIRES(GetLock()); |
| 63 | void DumpHistogram(std::ostream &os) const REQUIRES(GetLock()); |
Mathieu Chartier | afe4998 | 2014-03-27 10:55:04 -0700 | [diff] [blame] | 64 | uint64_t GetTotalTime() const { |
| 65 | return total_time_; |
| 66 | } |
Andreas Gampe | 0bbac30 | 2018-11-30 09:44:12 -0800 | [diff] [blame] | 67 | |
| 68 | Mutex* GetLock() const { |
| 69 | return lock_.get(); |
| 70 | } |
| 71 | |
Sameer Abu Asal | a843954 | 2013-02-14 16:06:42 -0800 | [diff] [blame] | 72 | static const uint64_t kAdjust = 1000; |
Andreas Gampe | 0bbac30 | 2018-11-30 09:44:12 -0800 | [diff] [blame] | 73 | std::set<Histogram<uint64_t>*, HistogramComparator> histograms_ GUARDED_BY(GetLock()); |
Sameer Abu Asal | a843954 | 2013-02-14 16:06:42 -0800 | [diff] [blame] | 74 | std::string name_; |
Ian Rogers | 4535705 | 2013-04-18 20:49:43 -0700 | [diff] [blame] | 75 | const std::string lock_name_; |
Andreas Gampe | 0bbac30 | 2018-11-30 09:44:12 -0800 | [diff] [blame] | 76 | mutable std::unique_ptr<Mutex> lock_ DEFAULT_MUTEX_ACQUIRED_AFTER; |
| 77 | size_t iterations_ GUARDED_BY(GetLock()); |
Mathieu Chartier | afe4998 | 2014-03-27 10:55:04 -0700 | [diff] [blame] | 78 | uint64_t total_time_; |
Sameer Abu Asal | a843954 | 2013-02-14 16:06:42 -0800 | [diff] [blame] | 79 | |
| 80 | DISALLOW_COPY_AND_ASSIGN(CumulativeLogger); |
| 81 | }; |
| 82 | |
Anwar Ghuloum | 4446ab9 | 2013-08-09 21:17:25 -0700 | [diff] [blame] | 83 | // A timing logger that knows when a split starts for the purposes of logging tools, like systrace. |
Anwar Ghuloum | 6f28d91 | 2013-07-24 15:02:53 -0700 | [diff] [blame] | 84 | class TimingLogger { |
Ian Rogers | 1d54e73 | 2013-05-02 21:10:01 -0700 | [diff] [blame] | 85 | public: |
Mathieu Chartier | f5997b4 | 2014-06-20 10:37:54 -0700 | [diff] [blame] | 86 | static constexpr size_t kIndexNotFound = static_cast<size_t>(-1); |
| 87 | |
Nicolas Geoffray | 3d69922 | 2017-09-20 15:15:20 +0100 | [diff] [blame] | 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 | |
Mathieu Chartier | f5997b4 | 2014-06-20 10:37:54 -0700 | [diff] [blame] | 94 | class Timing { |
| 95 | public: |
Nicolas Geoffray | 3d69922 | 2017-09-20 15:15:20 +0100 | [diff] [blame] | 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 | } |
Mathieu Chartier | f5997b4 | 2014-06-20 10:37:54 -0700 | [diff] [blame] | 105 | } |
| 106 | bool IsStartTiming() const { |
| 107 | return !IsEndTiming(); |
| 108 | } |
| 109 | bool IsEndTiming() const { |
| 110 | return name_ == nullptr; |
| 111 | } |
| 112 | uint64_t GetTime() const { |
| 113 | return time_; |
| 114 | } |
| 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; |
| 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 | } |
| 135 | uint64_t GetTotalTime(size_t idx) { |
| 136 | return data_[idx].total_time; |
| 137 | } |
| 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 { |
| 146 | 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 | }; |
Anwar Ghuloum | 4446ab9 | 2013-08-09 21:17:25 -0700 | [diff] [blame] | 153 | |
Nicolas Geoffray | 3d69922 | 2017-09-20 15:15:20 +0100 | [diff] [blame] | 154 | TimingLogger(const char* name, |
| 155 | bool precise, |
| 156 | bool verbose, |
| 157 | TimingKind kind = TimingKind::kMonotonic); |
Mathieu Chartier | f5997b4 | 2014-06-20 10:37:54 -0700 | [diff] [blame] | 158 | ~TimingLogger(); |
| 159 | // Verify that all open timings have related closed timings. |
| 160 | void Verify(); |
| 161 | // Clears current timings and labels. |
Ian Rogers | 1d54e73 | 2013-05-02 21:10:01 -0700 | [diff] [blame] | 162 | void Reset(); |
Mathieu Chartier | f5997b4 | 2014-06-20 10:37:54 -0700 | [diff] [blame] | 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. |
| 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). |
Ian Rogers | 1d54e73 | 2013-05-02 21:10:01 -0700 | [diff] [blame] | 173 | uint64_t GetTotalNs() const; |
Mathieu Chartier | f5997b4 | 2014-06-20 10:37:54 -0700 | [diff] [blame] | 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; |
Ian Rogers | 1d54e73 | 2013-05-02 21:10:01 -0700 | [diff] [blame] | 177 | |
Anwar Ghuloum | 4446ab9 | 2013-08-09 21:17:25 -0700 | [diff] [blame] | 178 | // Scoped timing splits that can be nested and composed with the explicit split |
| 179 | // starts and ends. |
Mathieu Chartier | f5997b4 | 2014-06-20 10:37:54 -0700 | [diff] [blame] | 180 | class ScopedTiming { |
| 181 | public: |
Roland Levillain | 3887c46 | 2015-08-12 18:15:42 +0100 | [diff] [blame] | 182 | ScopedTiming(const char* label, TimingLogger* logger) : logger_(logger) { |
Mathieu Chartier | f5997b4 | 2014-06-20 10:37:54 -0700 | [diff] [blame] | 183 | logger_->StartTiming(label); |
| 184 | } |
| 185 | ~ScopedTiming() { |
| 186 | logger_->EndTiming(); |
| 187 | } |
| 188 | // Closes the current timing and opens a new timing. |
| 189 | void NewTiming(const char* label) { |
| 190 | logger_->NewTiming(label); |
| 191 | } |
Anwar Ghuloum | 4446ab9 | 2013-08-09 21:17:25 -0700 | [diff] [blame] | 192 | |
Mathieu Chartier | f5997b4 | 2014-06-20 10:37:54 -0700 | [diff] [blame] | 193 | private: |
| 194 | TimingLogger* const logger_; // The timing logger which the scoped timing is associated with. |
| 195 | DISALLOW_COPY_AND_ASSIGN(ScopedTiming); |
Anwar Ghuloum | 4446ab9 | 2013-08-09 21:17:25 -0700 | [diff] [blame] | 196 | }; |
| 197 | |
Mathieu Chartier | f5997b4 | 2014-06-20 10:37:54 -0700 | [diff] [blame] | 198 | // Return the time points of when each start / end timings start and finish. |
| 199 | const std::vector<Timing>& GetTimings() const { |
| 200 | return timings_; |
Ian Rogers | 1d54e73 | 2013-05-02 21:10:01 -0700 | [diff] [blame] | 201 | } |
| 202 | |
Mathieu Chartier | f5997b4 | 2014-06-20 10:37:54 -0700 | [diff] [blame] | 203 | TimingData CalculateTimingData() const; |
| 204 | |
Ian Rogers | 1d54e73 | 2013-05-02 21:10:01 -0700 | [diff] [blame] | 205 | protected: |
| 206 | // The name of the timing logger. |
Ian Rogers | 5fe9af7 | 2013-11-14 00:17:20 -0800 | [diff] [blame] | 207 | const char* const name_; |
Ian Rogers | 1d54e73 | 2013-05-02 21:10:01 -0700 | [diff] [blame] | 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_; |
Ian Rogers | 1d54e73 | 2013-05-02 21:10:01 -0700 | [diff] [blame] | 211 | // Verbose logging. |
| 212 | const bool verbose_; |
Nicolas Geoffray | 3d69922 | 2017-09-20 15:15:20 +0100 | [diff] [blame] | 213 | // The kind of timing we want. |
| 214 | const TimingKind kind_; |
Mathieu Chartier | f5997b4 | 2014-06-20 10:37:54 -0700 | [diff] [blame] | 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_; |
Ian Rogers | 1d54e73 | 2013-05-02 21:10:01 -0700 | [diff] [blame] | 218 | |
| 219 | private: |
Anwar Ghuloum | 6f28d91 | 2013-07-24 15:02:53 -0700 | [diff] [blame] | 220 | DISALLOW_COPY_AND_ASSIGN(TimingLogger); |
Ian Rogers | 1d54e73 | 2013-05-02 21:10:01 -0700 | [diff] [blame] | 221 | }; |
| 222 | |
Sameer Abu Asal | a843954 | 2013-02-14 16:06:42 -0800 | [diff] [blame] | 223 | } // namespace art |
| 224 | |
Brian Carlstrom | fc0e321 | 2013-07-17 14:40:12 -0700 | [diff] [blame] | 225 | #endif // ART_RUNTIME_BASE_TIMING_LOGGER_H_ |