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 <time.h> |
24 | | |
25 | | #include <ctime> |
26 | | #include <sstream> |
27 | | #include <thread> |
28 | | |
29 | | #include "util/time.h" |
30 | | |
31 | | namespace doris { |
32 | | |
33 | | // Stop watch for reporting elapsed time in nanosec based on CLOCK_MONOTONIC. |
34 | | // It is as fast as Rdtsc. |
35 | | // It is also accurate because it not affected by cpu frequency changes and |
36 | | // it is not affected by user setting the system clock. |
37 | | // CLOCK_MONOTONIC represents monotonic time since some unspecified starting point. |
38 | | // It is good for computing elapsed time. |
39 | | template <clockid_t Clock> |
40 | | class CustomStopWatch { |
41 | | public: |
42 | 354M | CustomStopWatch(bool auto_start = false) { |
43 | 354M | _total_time = 0; |
44 | 354M | _running = false; |
45 | 354M | if (auto_start) { |
46 | 2.97k | start(); |
47 | 2.97k | } |
48 | 354M | } _ZN5doris15CustomStopWatchILi1EEC2Eb Line | Count | Source | 42 | 329M | CustomStopWatch(bool auto_start = false) { | 43 | 329M | _total_time = 0; | 44 | 329M | _running = false; | 45 | 329M | if (auto_start) { | 46 | 2.97k | start(); | 47 | 2.97k | } | 48 | 329M | } |
_ZN5doris15CustomStopWatchILi3EEC2Eb Line | Count | Source | 42 | 25.0M | CustomStopWatch(bool auto_start = false) { | 43 | 25.0M | _total_time = 0; | 44 | 25.0M | _running = false; | 45 | 25.0M | if (auto_start) { | 46 | 0 | start(); | 47 | 0 | } | 48 | 25.0M | } |
|
49 | | |
50 | | timespec start_time() const { return _start; } |
51 | | |
52 | 371M | void start() { |
53 | 371M | if (!_running) { |
54 | 355M | _record_start_thread_id(); |
55 | 355M | clock_gettime(Clock, &_start); |
56 | 355M | _running = true; |
57 | 355M | } |
58 | 371M | } _ZN5doris15CustomStopWatchILi1EE5startEv Line | Count | Source | 52 | 346M | void start() { | 53 | 346M | if (!_running) { | 54 | 330M | _record_start_thread_id(); | 55 | 330M | clock_gettime(Clock, &_start); | 56 | 330M | _running = true; | 57 | 330M | } | 58 | 346M | } |
_ZN5doris15CustomStopWatchILi3EE5startEv Line | Count | Source | 52 | 25.1M | void start() { | 53 | 25.1M | if (!_running) { | 54 | 25.1M | _record_start_thread_id(); | 55 | 25.1M | clock_gettime(Clock, &_start); | 56 | 25.1M | _running = true; | 57 | 25.1M | } | 58 | 25.1M | } |
|
59 | | |
60 | 131M | void stop() { |
61 | 131M | if (_running) { |
62 | 129M | _total_time += elapsed_time(); |
63 | 129M | _running = false; |
64 | 129M | } |
65 | 131M | } _ZN5doris15CustomStopWatchILi1EE4stopEv Line | Count | Source | 60 | 115M | void stop() { | 61 | 115M | if (_running) { | 62 | 113M | _total_time += elapsed_time(); | 63 | 113M | _running = false; | 64 | 113M | } | 65 | 115M | } |
_ZN5doris15CustomStopWatchILi3EE4stopEv Line | Count | Source | 60 | 15.3M | void stop() { | 61 | 15.3M | if (_running) { | 62 | 15.3M | _total_time += elapsed_time(); | 63 | 15.3M | _running = false; | 64 | 15.3M | } | 65 | 15.3M | } |
|
66 | | |
67 | | // Restarts the timer. Returns the elapsed time until this point. |
68 | 20.2M | int64_t reset() { |
69 | 20.2M | int64_t ret = elapsed_time(); |
70 | | |
71 | 20.2M | if (_running) { |
72 | 15.7M | _record_start_thread_id(); |
73 | 15.7M | clock_gettime(Clock, &_start); |
74 | 15.7M | } |
75 | | |
76 | 20.2M | return ret; |
77 | 20.2M | } _ZN5doris15CustomStopWatchILi3EE5resetEv Line | Count | Source | 68 | 1.38M | int64_t reset() { | 69 | 1.38M | int64_t ret = elapsed_time(); | 70 | | | 71 | 1.38M | if (_running) { | 72 | 97.6k | _record_start_thread_id(); | 73 | 97.6k | clock_gettime(Clock, &_start); | 74 | 97.6k | } | 75 | | | 76 | 1.38M | return ret; | 77 | 1.38M | } |
_ZN5doris15CustomStopWatchILi1EE5resetEv Line | Count | Source | 68 | 18.8M | int64_t reset() { | 69 | 18.8M | int64_t ret = elapsed_time(); | 70 | | | 71 | 18.8M | if (_running) { | 72 | 15.6M | _record_start_thread_id(); | 73 | 15.6M | clock_gettime(Clock, &_start); | 74 | 15.6M | } | 75 | | | 76 | 18.8M | return ret; | 77 | 18.8M | } |
|
78 | | |
79 | | // Returns time in nanosecond. |
80 | | // Clamped to 0 to guard against rare CLOCK_MONOTONIC rollbacks. |
81 | 487M | int64_t elapsed_time() const { |
82 | 487M | if (!_running) { |
83 | 132M | return _total_time; |
84 | 132M | } |
85 | | |
86 | 354M | _check_thread_id(); |
87 | 354M | timespec end; |
88 | 354M | clock_gettime(Clock, &end); |
89 | 354M | auto start_nanos = _start.tv_sec * NANOS_PER_SEC + _start.tv_nsec; |
90 | 354M | auto end_nanos = end.tv_sec * NANOS_PER_SEC + end.tv_nsec; |
91 | 354M | if (end_nanos < start_nanos) { |
92 | 17.5k | LOG(INFO) << "WARNING: time went backwards from " << start_nanos << " to " << end_nanos; |
93 | 17.5k | return 0; |
94 | 17.5k | } |
95 | 354M | return end_nanos - start_nanos; |
96 | 354M | } _ZNK5doris15CustomStopWatchILi1EE12elapsed_timeEv Line | Count | Source | 81 | 446M | int64_t elapsed_time() const { | 82 | 446M | if (!_running) { | 83 | 116M | return _total_time; | 84 | 116M | } | 85 | | | 86 | 330M | _check_thread_id(); | 87 | 330M | timespec end; | 88 | 330M | clock_gettime(Clock, &end); | 89 | 330M | auto start_nanos = _start.tv_sec * NANOS_PER_SEC + _start.tv_nsec; | 90 | 330M | auto end_nanos = end.tv_sec * NANOS_PER_SEC + end.tv_nsec; | 91 | 330M | if (end_nanos < start_nanos) { | 92 | 0 | LOG(INFO) << "WARNING: time went backwards from " << start_nanos << " to " << end_nanos; | 93 | 0 | return 0; | 94 | 0 | } | 95 | 330M | return end_nanos - start_nanos; | 96 | 330M | } |
_ZNK5doris15CustomStopWatchILi3EE12elapsed_timeEv Line | Count | Source | 81 | 40.3M | int64_t elapsed_time() const { | 82 | 40.3M | if (!_running) { | 83 | 16.6M | return _total_time; | 84 | 16.6M | } | 85 | | | 86 | 23.7M | _check_thread_id(); | 87 | 23.7M | timespec end; | 88 | 23.7M | clock_gettime(Clock, &end); | 89 | 23.7M | auto start_nanos = _start.tv_sec * NANOS_PER_SEC + _start.tv_nsec; | 90 | 23.7M | auto end_nanos = end.tv_sec * NANOS_PER_SEC + end.tv_nsec; | 91 | 23.7M | if (end_nanos < start_nanos) { | 92 | 17.5k | LOG(INFO) << "WARNING: time went backwards from " << start_nanos << " to " << end_nanos; | 93 | 17.5k | return 0; | 94 | 17.5k | } | 95 | 23.7M | return end_nanos - start_nanos; | 96 | 23.7M | } |
|
97 | | |
98 | | // Return time in microseconds |
99 | 285k | int64_t elapsed_time_microseconds() const { return elapsed_time() / 1000; } |
100 | | |
101 | | // Return time in milliseconds |
102 | 316k | int64_t elapsed_time_milliseconds() const { return elapsed_time() / 1000 / 1000; } |
103 | | |
104 | | // Returns time in seconds. |
105 | | // Clamped to 0 to guard against rare CLOCK_MONOTONIC rollbacks. |
106 | 57.7k | int64_t elapsed_time_seconds(timespec end) const { |
107 | 57.7k | if (!_running) { |
108 | 0 | return _total_time / 1000L / 1000L / 1000L; |
109 | 0 | } |
110 | 57.7k | if (end.tv_sec < _start.tv_sec) { |
111 | 11 | auto start_nanos = _start.tv_sec * NANOS_PER_SEC + _start.tv_nsec; |
112 | 11 | auto end_nanos = end.tv_sec * NANOS_PER_SEC + end.tv_nsec; |
113 | 11 | LOG(INFO) << "WARNING: time went backwards from " << start_nanos << " to " << end_nanos; |
114 | 11 | return 0; |
115 | 11 | } |
116 | 57.7k | return end.tv_sec - _start.tv_sec; |
117 | 57.7k | } |
118 | | |
119 | | private: |
120 | 48.8M | static std::string _get_thread_id() { |
121 | 48.8M | std::stringstream ss; |
122 | 48.8M | ss << std::this_thread::get_id(); |
123 | 48.8M | return ss.str(); |
124 | 48.8M | } |
125 | 370M | void _record_start_thread_id() { |
126 | 370M | #ifndef NDEBUG |
127 | 370M | if constexpr (Clock == CLOCK_THREAD_CPUTIME_ID) { |
128 | | // CLOCK_THREAD_CPUTIME_ID is not supported on some platforms, e.g. macOS. |
129 | | // So that we need to check it at runtime and fallback to CLOCK_MONOTONIC if it is not supported. |
130 | 25.1M | _start_thread_id = _get_thread_id(); |
131 | 25.1M | } |
132 | 370M | #endif |
133 | 370M | } _ZN5doris15CustomStopWatchILi1EE23_record_start_thread_idEv Line | Count | Source | 125 | 345M | void _record_start_thread_id() { | 126 | 345M | #ifndef NDEBUG | 127 | | if constexpr (Clock == CLOCK_THREAD_CPUTIME_ID) { | 128 | | // CLOCK_THREAD_CPUTIME_ID is not supported on some platforms, e.g. macOS. | 129 | | // So that we need to check it at runtime and fallback to CLOCK_MONOTONIC if it is not supported. | 130 | | _start_thread_id = _get_thread_id(); | 131 | | } | 132 | 345M | #endif | 133 | 345M | } |
_ZN5doris15CustomStopWatchILi3EE23_record_start_thread_idEv Line | Count | Source | 125 | 25.1M | void _record_start_thread_id() { | 126 | 25.1M | #ifndef NDEBUG | 127 | 25.1M | if constexpr (Clock == CLOCK_THREAD_CPUTIME_ID) { | 128 | | // CLOCK_THREAD_CPUTIME_ID is not supported on some platforms, e.g. macOS. | 129 | | // So that we need to check it at runtime and fallback to CLOCK_MONOTONIC if it is not supported. | 130 | 25.1M | _start_thread_id = _get_thread_id(); | 131 | 25.1M | } | 132 | 25.1M | #endif | 133 | 25.1M | } |
|
134 | | |
135 | 360M | void _check_thread_id() const { |
136 | 360M | #ifndef NDEBUG |
137 | 360M | if constexpr (Clock == CLOCK_THREAD_CPUTIME_ID) { |
138 | 23.9M | auto current_thread_id = _get_thread_id(); |
139 | 23.9M | if (current_thread_id != _start_thread_id) { |
140 | | LOG(WARNING) << "StopWatch started in thread " << _start_thread_id |
141 | 35.3k | << " but stopped in thread " << current_thread_id; |
142 | 35.3k | } |
143 | 23.9M | } |
144 | 360M | #endif |
145 | 360M | } _ZNK5doris15CustomStopWatchILi1EE16_check_thread_idEv Line | Count | Source | 135 | 336M | void _check_thread_id() const { | 136 | 336M | #ifndef NDEBUG | 137 | | if constexpr (Clock == CLOCK_THREAD_CPUTIME_ID) { | 138 | | auto current_thread_id = _get_thread_id(); | 139 | | if (current_thread_id != _start_thread_id) { | 140 | | LOG(WARNING) << "StopWatch started in thread " << _start_thread_id | 141 | | << " but stopped in thread " << current_thread_id; | 142 | | } | 143 | | } | 144 | 336M | #endif | 145 | 336M | } |
_ZNK5doris15CustomStopWatchILi3EE16_check_thread_idEv Line | Count | Source | 135 | 23.9M | void _check_thread_id() const { | 136 | 23.9M | #ifndef NDEBUG | 137 | 23.9M | if constexpr (Clock == CLOCK_THREAD_CPUTIME_ID) { | 138 | 23.9M | auto current_thread_id = _get_thread_id(); | 139 | 23.9M | if (current_thread_id != _start_thread_id) { | 140 | | LOG(WARNING) << "StopWatch started in thread " << _start_thread_id | 141 | 35.3k | << " but stopped in thread " << current_thread_id; | 142 | 35.3k | } | 143 | 23.9M | } | 144 | 23.9M | #endif | 145 | 23.9M | } |
|
146 | | |
147 | | timespec _start; |
148 | | int64_t _total_time; // in nanosec |
149 | | bool _running; |
150 | | #ifndef NDEBUG |
151 | | std::string _start_thread_id; |
152 | | #endif |
153 | | }; |
154 | | |
155 | | // Stop watch for reporting elapsed time in nanosec based on CLOCK_MONOTONIC. |
156 | | // It is as fast as Rdtsc. |
157 | | // It is also accurate because it not affected by cpu frequency changes and |
158 | | // it is not affected by user setting the system clock. |
159 | | // CLOCK_MONOTONIC represents monotonic time since some unspecified starting point. |
160 | | // It is good for computing elapsed time. |
161 | | using MonotonicStopWatch = CustomStopWatch<CLOCK_MONOTONIC>; |
162 | | |
163 | | // Stop watch for reporting elapsed nanosec based on CLOCK_THREAD_CPUTIME_ID. |
164 | | using ThreadCpuStopWatch = CustomStopWatch<CLOCK_THREAD_CPUTIME_ID>; |
165 | | |
166 | | } // namespace doris |