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 | 373M | CustomStopWatch(bool auto_start = false) { |
44 | 373M | _total_time = 0; |
45 | 373M | _running = false; |
46 | 373M | if (auto_start) { |
47 | 3.18k | start(); |
48 | 3.18k | } |
49 | 373M | } _ZN5doris15CustomStopWatchILi1EEC2Eb Line | Count | Source | 43 | 345M | CustomStopWatch(bool auto_start = false) { | 44 | 345M | _total_time = 0; | 45 | 345M | _running = false; | 46 | 345M | if (auto_start) { | 47 | 3.18k | start(); | 48 | 3.18k | } | 49 | 345M | } |
_ZN5doris15CustomStopWatchILi3EEC2Eb Line | Count | Source | 43 | 28.1M | CustomStopWatch(bool auto_start = false) { | 44 | 28.1M | _total_time = 0; | 45 | 28.1M | _running = false; | 46 | 28.1M | if (auto_start) { | 47 | 0 | start(); | 48 | 0 | } | 49 | 28.1M | } |
|
50 | | |
51 | | timespec start_time() const { return _start; } |
52 | | |
53 | 391M | void start() { |
54 | 391M | if (!_running) { |
55 | 373M | _record_start_thread_id(); |
56 | 373M | clock_gettime(Clock, &_start); |
57 | 373M | _running = true; |
58 | 373M | } |
59 | 391M | } _ZN5doris15CustomStopWatchILi1EE5startEv Line | Count | Source | 53 | 363M | void start() { | 54 | 363M | if (!_running) { | 55 | 345M | _record_start_thread_id(); | 56 | 345M | clock_gettime(Clock, &_start); | 57 | 345M | _running = true; | 58 | 345M | } | 59 | 363M | } |
_ZN5doris15CustomStopWatchILi3EE5startEv Line | Count | Source | 53 | 28.1M | void start() { | 54 | 28.1M | if (!_running) { | 55 | 28.0M | _record_start_thread_id(); | 56 | 28.0M | clock_gettime(Clock, &_start); | 57 | 28.0M | _running = true; | 58 | 28.0M | } | 59 | 28.1M | } |
|
60 | | |
61 | 144M | void stop() { |
62 | 144M | if (_running) { |
63 | 142M | _total_time += elapsed_time(); |
64 | 142M | _running = false; |
65 | 142M | } |
66 | 144M | } _ZN5doris15CustomStopWatchILi1EE4stopEv Line | Count | Source | 61 | 126M | void stop() { | 62 | 126M | if (_running) { | 63 | 124M | _total_time += elapsed_time(); | 64 | 124M | _running = false; | 65 | 124M | } | 66 | 126M | } |
_ZN5doris15CustomStopWatchILi3EE4stopEv Line | Count | Source | 61 | 17.3M | void stop() { | 62 | 17.3M | if (_running) { | 63 | 17.3M | _total_time += elapsed_time(); | 64 | 17.3M | _running = false; | 65 | 17.3M | } | 66 | 17.3M | } |
|
67 | | |
68 | | // Restarts the timer. Returns the elapsed time until this point. |
69 | 22.3M | int64_t reset() { |
70 | 22.3M | int64_t ret = elapsed_time(); |
71 | | |
72 | 22.3M | if (_running) { |
73 | 17.6M | _record_start_thread_id(); |
74 | 17.6M | clock_gettime(Clock, &_start); |
75 | 17.6M | } |
76 | | |
77 | 22.3M | return ret; |
78 | 22.3M | } _ZN5doris15CustomStopWatchILi3EE5resetEv Line | Count | Source | 69 | 1.42M | int64_t reset() { | 70 | 1.42M | int64_t ret = elapsed_time(); | 71 | | | 72 | 1.42M | if (_running) { | 73 | 103k | _record_start_thread_id(); | 74 | 103k | clock_gettime(Clock, &_start); | 75 | 103k | } | 76 | | | 77 | 1.42M | return ret; | 78 | 1.42M | } |
_ZN5doris15CustomStopWatchILi1EE5resetEv Line | Count | Source | 69 | 20.9M | int64_t reset() { | 70 | 20.9M | int64_t ret = elapsed_time(); | 71 | | | 72 | 20.9M | if (_running) { | 73 | 17.5M | _record_start_thread_id(); | 74 | 17.5M | clock_gettime(Clock, &_start); | 75 | 17.5M | } | 76 | | | 77 | 20.9M | return ret; | 78 | 20.9M | } |
|
79 | | |
80 | | // Returns time in nanosecond. |
81 | | // Clamped to 0 to guard against rare CLOCK_MONOTONIC rollbacks. |
82 | 521M | int64_t elapsed_time() const { |
83 | 521M | if (!_running) { |
84 | 144M | return _total_time; |
85 | 144M | } |
86 | | |
87 | 376M | _check_thread_id(); |
88 | 376M | timespec end; |
89 | 376M | clock_gettime(Clock, &end); |
90 | 376M | auto start_nanos = _start.tv_sec * NANOS_PER_SEC + _start.tv_nsec; |
91 | 376M | auto end_nanos = end.tv_sec * NANOS_PER_SEC + end.tv_nsec; |
92 | 376M | if (end_nanos < start_nanos) { |
93 | 19.7k | LOG_EVERY_T(WARNING, 1) |
94 | 3.08k | << "time went backwards from " << start_nanos << " to " << end_nanos; |
95 | 19.7k | return 0; |
96 | 19.7k | } |
97 | 376M | return end_nanos - start_nanos; |
98 | 376M | } _ZNK5doris15CustomStopWatchILi1EE12elapsed_timeEv Line | Count | Source | 82 | 475M | int64_t elapsed_time() const { | 83 | 475M | if (!_running) { | 84 | 125M | return _total_time; | 85 | 125M | } | 86 | | | 87 | 349M | _check_thread_id(); | 88 | 349M | timespec end; | 89 | 349M | clock_gettime(Clock, &end); | 90 | 349M | auto start_nanos = _start.tv_sec * NANOS_PER_SEC + _start.tv_nsec; | 91 | 349M | auto end_nanos = end.tv_sec * NANOS_PER_SEC + end.tv_nsec; | 92 | 349M | if (end_nanos < start_nanos) { | 93 | 1 | LOG_EVERY_T(WARNING, 1) | 94 | 1 | << "time went backwards from " << start_nanos << " to " << end_nanos; | 95 | 1 | return 0; | 96 | 1 | } | 97 | 349M | return end_nanos - start_nanos; | 98 | 349M | } |
_ZNK5doris15CustomStopWatchILi3EE12elapsed_timeEv Line | Count | Source | 82 | 45.5M | int64_t elapsed_time() const { | 83 | 45.5M | if (!_running) { | 84 | 18.7M | return _total_time; | 85 | 18.7M | } | 86 | | | 87 | 26.8M | _check_thread_id(); | 88 | 26.8M | timespec end; | 89 | 26.8M | clock_gettime(Clock, &end); | 90 | 26.8M | auto start_nanos = _start.tv_sec * NANOS_PER_SEC + _start.tv_nsec; | 91 | 26.8M | auto end_nanos = end.tv_sec * NANOS_PER_SEC + end.tv_nsec; | 92 | 26.8M | if (end_nanos < start_nanos) { | 93 | 19.7k | LOG_EVERY_T(WARNING, 1) | 94 | 3.08k | << "time went backwards from " << start_nanos << " to " << end_nanos; | 95 | 19.7k | return 0; | 96 | 19.7k | } | 97 | 26.8M | return end_nanos - start_nanos; | 98 | 26.8M | } |
|
99 | | |
100 | | // Return time in microseconds |
101 | 245k | int64_t elapsed_time_microseconds() const { return elapsed_time() / 1000; } |
102 | | |
103 | | // Return time in milliseconds |
104 | 375k | 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 | 61.6k | int64_t elapsed_time_seconds(timespec end) const { |
109 | 61.6k | if (!_running) { |
110 | 0 | return _total_time / 1000L / 1000L / 1000L; |
111 | 0 | } |
112 | 61.6k | if (end.tv_sec < _start.tv_sec) { |
113 | 76 | auto start_nanos = _start.tv_sec * NANOS_PER_SEC + _start.tv_nsec; |
114 | 76 | auto end_nanos = end.tv_sec * NANOS_PER_SEC + end.tv_nsec; |
115 | 76 | LOG_EVERY_T(WARNING, 1) |
116 | 11 | << "time went backwards from " << start_nanos << " to " << end_nanos; |
117 | 76 | return 0; |
118 | 76 | } |
119 | 61.5k | return end.tv_sec - _start.tv_sec; |
120 | 61.6k | } |
121 | | |
122 | | private: |
123 | 54.8M | static std::string _get_thread_id() { |
124 | 54.8M | std::stringstream ss; |
125 | 54.8M | ss << std::this_thread::get_id(); |
126 | 54.8M | return ss.str(); |
127 | 54.8M | } |
128 | 390M | void _record_start_thread_id() { |
129 | 390M | #ifndef NDEBUG |
130 | 390M | 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 | 28.1M | _start_thread_id = _get_thread_id(); |
134 | 28.1M | } |
135 | 390M | #endif |
136 | 390M | } _ZN5doris15CustomStopWatchILi1EE23_record_start_thread_idEv Line | Count | Source | 128 | 361M | void _record_start_thread_id() { | 129 | 361M | #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 | 361M | #endif | 136 | 361M | } |
_ZN5doris15CustomStopWatchILi3EE23_record_start_thread_idEv Line | Count | Source | 128 | 28.1M | void _record_start_thread_id() { | 129 | 28.1M | #ifndef NDEBUG | 130 | 28.1M | 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 | 28.1M | _start_thread_id = _get_thread_id(); | 134 | 28.1M | } | 135 | 28.1M | #endif | 136 | 28.1M | } |
|
137 | | |
138 | 381M | void _check_thread_id() const { |
139 | 381M | #ifndef NDEBUG |
140 | 381M | if constexpr (Clock == CLOCK_THREAD_CPUTIME_ID) { |
141 | 27.0M | auto current_thread_id = _get_thread_id(); |
142 | 27.0M | if (current_thread_id != _start_thread_id) { |
143 | | LOG(WARNING) << "StopWatch started in thread " << _start_thread_id |
144 | 39.3k | << " but stopped in thread " << current_thread_id; |
145 | 39.3k | } |
146 | 27.0M | } |
147 | 381M | #endif |
148 | 381M | } _ZNK5doris15CustomStopWatchILi1EE16_check_thread_idEv Line | Count | Source | 138 | 354M | void _check_thread_id() const { | 139 | 354M | #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 | 354M | #endif | 148 | 354M | } |
_ZNK5doris15CustomStopWatchILi3EE16_check_thread_idEv Line | Count | Source | 138 | 27.0M | void _check_thread_id() const { | 139 | 27.0M | #ifndef NDEBUG | 140 | 27.0M | if constexpr (Clock == CLOCK_THREAD_CPUTIME_ID) { | 141 | 27.0M | auto current_thread_id = _get_thread_id(); | 142 | 27.0M | if (current_thread_id != _start_thread_id) { | 143 | | LOG(WARNING) << "StopWatch started in thread " << _start_thread_id | 144 | 39.3k | << " but stopped in thread " << current_thread_id; | 145 | 39.3k | } | 146 | 27.0M | } | 147 | 27.0M | #endif | 148 | 27.0M | } |
|
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 |