be/src/util/stopwatch.hpp
Line | Count | Source |
1 | | // Licensed to the Apache Software Foundation (ASF) under one |
2 | | // or more contributor license agreements. See the NOTICE file |
3 | | // distributed with this work for additional information |
4 | | // regarding copyright ownership. The ASF licenses this file |
5 | | // to you under the Apache License, Version 2.0 (the |
6 | | // "License"); you may not use this file except in compliance |
7 | | // with the License. You may obtain a copy of the License at |
8 | | // |
9 | | // http://www.apache.org/licenses/LICENSE-2.0 |
10 | | // |
11 | | // Unless required by applicable law or agreed to in writing, |
12 | | // software distributed under the License is distributed on an |
13 | | // "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY |
14 | | // KIND, either express or implied. See the License for the |
15 | | // specific language governing permissions and limitations |
16 | | // under the License. |
17 | | // This file is copied from |
18 | | // https://github.com/apache/impala/blob/branch-2.9.0/be/src/util/stopwatch.hpp |
19 | | // and modified by Doris |
20 | | |
21 | | #pragma once |
22 | | |
23 | | #include <glog/logging.h> |
24 | | #include <time.h> |
25 | | |
26 | | #include <ctime> |
27 | | #include <sstream> |
28 | | #include <thread> |
29 | | |
30 | | #include "util/time.h" |
31 | | |
32 | | namespace doris { |
33 | | |
34 | | // Stop watch for reporting elapsed time in nanosec based on CLOCK_MONOTONIC. |
35 | | // It is as fast as Rdtsc. |
36 | | // It is also accurate because it not affected by cpu frequency changes and |
37 | | // it is not affected by user setting the system clock. |
38 | | // CLOCK_MONOTONIC represents monotonic time since some unspecified starting point. |
39 | | // It is good for computing elapsed time. |
40 | | template <clockid_t Clock> |
41 | | class CustomStopWatch { |
42 | | public: |
43 | 79.3M | CustomStopWatch(bool auto_start = false) { |
44 | 79.3M | _total_time = 0; |
45 | 79.3M | _running = false; |
46 | 79.3M | if (auto_start) { |
47 | 704 | start(); |
48 | 704 | } |
49 | 79.3M | } _ZN5doris15CustomStopWatchILi1EEC2Eb Line | Count | Source | 43 | 75.2M | CustomStopWatch(bool auto_start = false) { | 44 | 75.2M | _total_time = 0; | 45 | 75.2M | _running = false; | 46 | 75.2M | if (auto_start) { | 47 | 704 | start(); | 48 | 704 | } | 49 | 75.2M | } |
_ZN5doris15CustomStopWatchILi3EEC2Eb Line | Count | Source | 43 | 4.10M | CustomStopWatch(bool auto_start = false) { | 44 | 4.10M | _total_time = 0; | 45 | 4.10M | _running = false; | 46 | 4.10M | if (auto_start) { | 47 | 0 | start(); | 48 | 0 | } | 49 | 4.10M | } |
|
50 | | |
51 | | timespec start_time() const { return _start; } |
52 | | |
53 | 81.4M | void start() { |
54 | 81.4M | if (!_running) { |
55 | 78.7M | _record_start_thread_id(); |
56 | 78.7M | clock_gettime(Clock, &_start); |
57 | 78.7M | _running = true; |
58 | 78.7M | } |
59 | 81.4M | } _ZN5doris15CustomStopWatchILi1EE5startEv Line | Count | Source | 53 | 77.2M | void start() { | 54 | 77.2M | if (!_running) { | 55 | 74.6M | _record_start_thread_id(); | 56 | 74.6M | clock_gettime(Clock, &_start); | 57 | 74.6M | _running = true; | 58 | 74.6M | } | 59 | 77.2M | } |
_ZN5doris15CustomStopWatchILi3EE5startEv Line | Count | Source | 53 | 4.12M | void start() { | 54 | 4.12M | if (!_running) { | 55 | 4.11M | _record_start_thread_id(); | 56 | 4.11M | clock_gettime(Clock, &_start); | 57 | 4.11M | _running = true; | 58 | 4.11M | } | 59 | 4.12M | } |
|
60 | | |
61 | 24.0M | void stop() { |
62 | 24.0M | if (_running) { |
63 | 23.7M | _total_time += elapsed_time(); |
64 | 23.7M | _running = false; |
65 | 23.7M | } |
66 | 24.0M | } _ZN5doris15CustomStopWatchILi1EE4stopEv Line | Count | Source | 61 | 21.4M | void stop() { | 62 | 21.4M | if (_running) { | 63 | 21.1M | _total_time += elapsed_time(); | 64 | 21.1M | _running = false; | 65 | 21.1M | } | 66 | 21.4M | } |
_ZN5doris15CustomStopWatchILi3EE4stopEv Line | Count | Source | 61 | 2.55M | void stop() { | 62 | 2.55M | if (_running) { | 63 | 2.55M | _total_time += elapsed_time(); | 64 | 2.55M | _running = false; | 65 | 2.55M | } | 66 | 2.55M | } |
|
67 | | |
68 | | // Restarts the timer. Returns the elapsed time until this point. |
69 | 3.76M | int64_t reset() { |
70 | 3.76M | int64_t ret = elapsed_time(); |
71 | | |
72 | 3.76M | if (_running) { |
73 | 2.89M | _record_start_thread_id(); |
74 | 2.89M | clock_gettime(Clock, &_start); |
75 | 2.89M | } |
76 | | |
77 | 3.76M | return ret; |
78 | 3.76M | } _ZN5doris15CustomStopWatchILi3EE5resetEv Line | Count | Source | 69 | 304k | int64_t reset() { | 70 | 304k | int64_t ret = elapsed_time(); | 71 | | | 72 | 304k | if (_running) { | 73 | 16.8k | _record_start_thread_id(); | 74 | 16.8k | clock_gettime(Clock, &_start); | 75 | 16.8k | } | 76 | | | 77 | 304k | return ret; | 78 | 304k | } |
_ZN5doris15CustomStopWatchILi1EE5resetEv Line | Count | Source | 69 | 3.46M | int64_t reset() { | 70 | 3.46M | int64_t ret = elapsed_time(); | 71 | | | 72 | 3.46M | if (_running) { | 73 | 2.88M | _record_start_thread_id(); | 74 | 2.88M | clock_gettime(Clock, &_start); | 75 | 2.88M | } | 76 | | | 77 | 3.46M | return ret; | 78 | 3.46M | } |
|
79 | | |
80 | | // Returns time in nanosecond. |
81 | | // Clamped to 0 to guard against rare CLOCK_MONOTONIC rollbacks. |
82 | 102M | int64_t elapsed_time() const { |
83 | 102M | if (!_running) { |
84 | 24.3M | return _total_time; |
85 | 24.3M | } |
86 | | |
87 | 78.0M | _check_thread_id(); |
88 | 78.0M | timespec end; |
89 | 78.0M | clock_gettime(Clock, &end); |
90 | 78.0M | auto start_nanos = _start.tv_sec * NANOS_PER_SEC + _start.tv_nsec; |
91 | 78.0M | auto end_nanos = end.tv_sec * NANOS_PER_SEC + end.tv_nsec; |
92 | 78.0M | if (end_nanos < start_nanos) { |
93 | 4.08k | LOG_EVERY_T(WARNING, 1) |
94 | 593 | << "time went backwards from " << start_nanos << " to " << end_nanos; |
95 | 4.08k | return 0; |
96 | 4.08k | } |
97 | 78.0M | return end_nanos - start_nanos; |
98 | 78.0M | } _ZNK5doris15CustomStopWatchILi1EE12elapsed_timeEv Line | Count | Source | 82 | 95.5M | int64_t elapsed_time() const { | 83 | 95.5M | if (!_running) { | 84 | 21.4M | return _total_time; | 85 | 21.4M | } | 86 | | | 87 | 74.0M | _check_thread_id(); | 88 | 74.0M | timespec end; | 89 | 74.0M | clock_gettime(Clock, &end); | 90 | 74.0M | auto start_nanos = _start.tv_sec * NANOS_PER_SEC + _start.tv_nsec; | 91 | 74.0M | auto end_nanos = end.tv_sec * NANOS_PER_SEC + end.tv_nsec; | 92 | 74.0M | if (end_nanos < start_nanos) { | 93 | 0 | LOG_EVERY_T(WARNING, 1) | 94 | 0 | << "time went backwards from " << start_nanos << " to " << end_nanos; | 95 | 0 | return 0; | 96 | 0 | } | 97 | 74.0M | return end_nanos - start_nanos; | 98 | 74.0M | } |
_ZNK5doris15CustomStopWatchILi3EE12elapsed_timeEv Line | Count | Source | 82 | 6.88M | int64_t elapsed_time() const { | 83 | 6.88M | if (!_running) { | 84 | 2.84M | return _total_time; | 85 | 2.84M | } | 86 | | | 87 | 4.04M | _check_thread_id(); | 88 | 4.04M | timespec end; | 89 | 4.04M | clock_gettime(Clock, &end); | 90 | 4.04M | auto start_nanos = _start.tv_sec * NANOS_PER_SEC + _start.tv_nsec; | 91 | 4.04M | auto end_nanos = end.tv_sec * NANOS_PER_SEC + end.tv_nsec; | 92 | 4.04M | if (end_nanos < start_nanos) { | 93 | 4.08k | LOG_EVERY_T(WARNING, 1) | 94 | 593 | << "time went backwards from " << start_nanos << " to " << end_nanos; | 95 | 4.08k | return 0; | 96 | 4.08k | } | 97 | 4.04M | return end_nanos - start_nanos; | 98 | 4.04M | } |
|
99 | | |
100 | | // Return time in microseconds |
101 | 69.0k | int64_t elapsed_time_microseconds() const { return elapsed_time() / 1000; } |
102 | | |
103 | | // Return time in milliseconds |
104 | 113k | int64_t elapsed_time_milliseconds() const { return elapsed_time() / 1000 / 1000; } |
105 | | |
106 | | // Returns time in seconds. |
107 | | // Clamped to 0 to guard against rare CLOCK_MONOTONIC rollbacks. |
108 | 16.7k | int64_t elapsed_time_seconds(timespec end) const { |
109 | 16.7k | if (!_running) { |
110 | 0 | return _total_time / 1000L / 1000L / 1000L; |
111 | 0 | } |
112 | 16.7k | if (end.tv_sec < _start.tv_sec) { |
113 | 30 | auto start_nanos = _start.tv_sec * NANOS_PER_SEC + _start.tv_nsec; |
114 | 30 | auto end_nanos = end.tv_sec * NANOS_PER_SEC + end.tv_nsec; |
115 | 30 | LOG_EVERY_T(WARNING, 1) |
116 | 5 | << "time went backwards from " << start_nanos << " to " << end_nanos; |
117 | 30 | return 0; |
118 | 30 | } |
119 | 16.6k | return end.tv_sec - _start.tv_sec; |
120 | 16.7k | } |
121 | | |
122 | | private: |
123 | 8.15M | static std::string _get_thread_id() { |
124 | 8.15M | std::stringstream ss; |
125 | 8.15M | ss << std::this_thread::get_id(); |
126 | 8.15M | return ss.str(); |
127 | 8.15M | } |
128 | 81.4M | void _record_start_thread_id() { |
129 | 81.4M | #ifndef NDEBUG |
130 | 81.4M | if constexpr (Clock == CLOCK_THREAD_CPUTIME_ID) { |
131 | | // CLOCK_THREAD_CPUTIME_ID is not supported on some platforms, e.g. macOS. |
132 | | // So that we need to check it at runtime and fallback to CLOCK_MONOTONIC if it is not supported. |
133 | 4.12M | _start_thread_id = _get_thread_id(); |
134 | 4.12M | } |
135 | 81.4M | #endif |
136 | 81.4M | } _ZN5doris15CustomStopWatchILi1EE23_record_start_thread_idEv Line | Count | Source | 128 | 77.3M | void _record_start_thread_id() { | 129 | 77.3M | #ifndef NDEBUG | 130 | | if constexpr (Clock == CLOCK_THREAD_CPUTIME_ID) { | 131 | | // CLOCK_THREAD_CPUTIME_ID is not supported on some platforms, e.g. macOS. | 132 | | // So that we need to check it at runtime and fallback to CLOCK_MONOTONIC if it is not supported. | 133 | | _start_thread_id = _get_thread_id(); | 134 | | } | 135 | 77.3M | #endif | 136 | 77.3M | } |
_ZN5doris15CustomStopWatchILi3EE23_record_start_thread_idEv Line | Count | Source | 128 | 4.12M | void _record_start_thread_id() { | 129 | 4.12M | #ifndef NDEBUG | 130 | 4.12M | if constexpr (Clock == CLOCK_THREAD_CPUTIME_ID) { | 131 | | // CLOCK_THREAD_CPUTIME_ID is not supported on some platforms, e.g. macOS. | 132 | | // So that we need to check it at runtime and fallback to CLOCK_MONOTONIC if it is not supported. | 133 | 4.12M | _start_thread_id = _get_thread_id(); | 134 | 4.12M | } | 135 | 4.12M | #endif | 136 | 4.12M | } |
|
137 | | |
138 | 78.9M | void _check_thread_id() const { |
139 | 78.9M | #ifndef NDEBUG |
140 | 78.9M | if constexpr (Clock == CLOCK_THREAD_CPUTIME_ID) { |
141 | 4.07M | auto current_thread_id = _get_thread_id(); |
142 | 4.07M | if (current_thread_id != _start_thread_id) { |
143 | | LOG(WARNING) << "StopWatch started in thread " << _start_thread_id |
144 | 8.27k | << " but stopped in thread " << current_thread_id; |
145 | 8.27k | } |
146 | 4.07M | } |
147 | 78.9M | #endif |
148 | 78.9M | } _ZNK5doris15CustomStopWatchILi1EE16_check_thread_idEv Line | Count | Source | 138 | 74.8M | void _check_thread_id() const { | 139 | 74.8M | #ifndef NDEBUG | 140 | | if constexpr (Clock == CLOCK_THREAD_CPUTIME_ID) { | 141 | | auto current_thread_id = _get_thread_id(); | 142 | | if (current_thread_id != _start_thread_id) { | 143 | | LOG(WARNING) << "StopWatch started in thread " << _start_thread_id | 144 | | << " but stopped in thread " << current_thread_id; | 145 | | } | 146 | | } | 147 | 74.8M | #endif | 148 | 74.8M | } |
_ZNK5doris15CustomStopWatchILi3EE16_check_thread_idEv Line | Count | Source | 138 | 4.07M | void _check_thread_id() const { | 139 | 4.07M | #ifndef NDEBUG | 140 | 4.07M | if constexpr (Clock == CLOCK_THREAD_CPUTIME_ID) { | 141 | 4.07M | auto current_thread_id = _get_thread_id(); | 142 | 4.07M | if (current_thread_id != _start_thread_id) { | 143 | | LOG(WARNING) << "StopWatch started in thread " << _start_thread_id | 144 | 8.27k | << " but stopped in thread " << current_thread_id; | 145 | 8.27k | } | 146 | 4.07M | } | 147 | 4.07M | #endif | 148 | 4.07M | } |
|
149 | | |
150 | | timespec _start; |
151 | | int64_t _total_time; // in nanosec |
152 | | bool _running; |
153 | | #ifndef NDEBUG |
154 | | std::string _start_thread_id; |
155 | | #endif |
156 | | }; |
157 | | |
158 | | // Stop watch for reporting elapsed time in nanosec based on CLOCK_MONOTONIC. |
159 | | // It is as fast as Rdtsc. |
160 | | // It is also accurate because it not affected by cpu frequency changes and |
161 | | // it is not affected by user setting the system clock. |
162 | | // CLOCK_MONOTONIC represents monotonic time since some unspecified starting point. |
163 | | // It is good for computing elapsed time. |
164 | | using MonotonicStopWatch = CustomStopWatch<CLOCK_MONOTONIC>; |
165 | | |
166 | | // Stop watch for reporting elapsed nanosec based on CLOCK_THREAD_CPUTIME_ID. |
167 | | using ThreadCpuStopWatch = CustomStopWatch<CLOCK_THREAD_CPUTIME_ID>; |
168 | | |
169 | | } // namespace doris |