Skip to content

Commit 67273e9

Browse files
jacktenggCopilot
andcommitted
[fix](be) Clamp MonotonicStopWatch elapsed time to non-negative
Problem Summary: MonotonicStopWatch::elapsed_time() can return a small negative value (e.g. -203 ns) due to rare CLOCK_MONOTONIC rollbacks. When stop() accumulates this into _total_time and _fresh_profile_counter() sets it on a RuntimeProfile::Counter, the DCHECK asserting value > -1 fires and crashes the process. Stack trace: RuntimeProfile::Counter::set() at runtime_profile.h:222 PipelineTask::close() at pipeline_task.cpp:925 close_task() at task_scheduler.cpp:86 The fix clamps the running-case delta in elapsed_time() and elapsed_time_seconds() to max(0, delta). Since stop() calls elapsed_time() while _running is still true, _total_time can never accumulate a negative value, preventing the crash for all downstream callers. None - Test: No need to test (clock rollback is non-deterministic hardware behavior; the fix is a trivial arithmetic clamp) - Behavior changed: No - Does this need documentation: No Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
1 parent cb1876f commit 67273e9

File tree

1 file changed

+18
-4
lines changed

1 file changed

+18
-4
lines changed

be/src/util/stopwatch.hpp

Lines changed: 18 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -22,6 +22,8 @@
2222

2323
#include <time.h>
2424

25+
#include "util/time.h"
26+
2527
namespace doris {
2628

2729
// Stop watch for reporting elapsed time in nanosec based on CLOCK_MONOTONIC.
@@ -69,16 +71,21 @@ class CustomStopWatch {
6971
}
7072

7173
// Returns time in nanosecond.
72-
// Sometimes the time will rollback, so that the value will be negative.
74+
// Clamped to 0 to guard against rare CLOCK_MONOTONIC rollbacks.
7375
int64_t elapsed_time() const {
7476
if (!_running) {
7577
return _total_time;
7678
}
7779

7880
timespec end;
7981
clock_gettime(Clock, &end);
80-
return (end.tv_sec - _start.tv_sec) * 1000L * 1000L * 1000L +
81-
(end.tv_nsec - _start.tv_nsec);
82+
auto start_nanos = _start.tv_sec * NANOS_PER_SEC + _start.tv_nsec;
83+
auto end_nanos = end.tv_sec * NANOS_PER_SEC + end.tv_nsec;
84+
if (end_nanos < start_nanos) {
85+
LOG(INFO) << "WARNING: time went backwards from " << start_nanos << " to " << end_nanos;
86+
return 0;
87+
}
88+
return end_nanos - start_nanos;
8289
}
8390

8491
// Return time in microseconds
@@ -87,11 +94,18 @@ class CustomStopWatch {
8794
// Return time in milliseconds
8895
int64_t elapsed_time_milliseconds() const { return elapsed_time() / 1000 / 1000; }
8996

90-
// Returns time in nanosecond.
97+
// Returns time in seconds.
98+
// Clamped to 0 to guard against rare CLOCK_MONOTONIC rollbacks.
9199
int64_t elapsed_time_seconds(timespec end) const {
92100
if (!_running) {
93101
return _total_time / 1000L / 1000L / 1000L;
94102
}
103+
if (end.tv_sec < _start.tv_sec) {
104+
auto start_nanos = _start.tv_sec * NANOS_PER_SEC + _start.tv_nsec;
105+
auto end_nanos = end.tv_sec * NANOS_PER_SEC + end.tv_nsec;
106+
LOG(INFO) << "WARNING: time went backwards from " << start_nanos << " to " << end_nanos;
107+
return 0;
108+
}
95109
return end.tv_sec - _start.tv_sec;
96110
}
97111

0 commit comments

Comments
 (0)