IMPALA-6450: fix EventSequence::Start() It looks like this newly-added DCHECK is being hit because of the same underlying issue as IMPALA-4631. This patch loosens the DCHECK to accept time going backward 1 tick, the same as the original workaround for IMPALA-4631.
'offset_' also isn't being used, so fix that too. Change-Id: I62317149cb8428f7d29e945a538f6cc8dd45342f Reviewed-on: http://gerrit.cloudera.org:8080/9155 Reviewed-by: Tim Armstrong <tarmstr...@cloudera.com> Tested-by: Impala Public Jenkins Project: http://git-wip-us.apache.org/repos/asf/impala/repo Commit: http://git-wip-us.apache.org/repos/asf/impala/commit/489e5dc0 Tree: http://git-wip-us.apache.org/repos/asf/impala/tree/489e5dc0 Diff: http://git-wip-us.apache.org/repos/asf/impala/diff/489e5dc0 Branch: refs/heads/2.x Commit: 489e5dc0028433e17323028a5d867bcca1822bbf Parents: 5aab4d4 Author: Tim Armstrong <tarmstr...@cloudera.com> Authored: Mon Jan 29 15:52:59 2018 -0800 Committer: Impala Public Jenkins <impala-public-jenk...@gerrit.cloudera.org> Committed: Fri Feb 2 01:10:15 2018 +0000 ---------------------------------------------------------------------- be/src/util/runtime-profile-counters.h | 10 +++++++--- 1 file changed, 7 insertions(+), 3 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/impala/blob/489e5dc0/be/src/util/runtime-profile-counters.h ---------------------------------------------------------------------- diff --git a/be/src/util/runtime-profile-counters.h b/be/src/util/runtime-profile-counters.h index 62281f1..c8d8bcd 100644 --- a/be/src/util/runtime-profile-counters.h +++ b/be/src/util/runtime-profile-counters.h @@ -302,14 +302,17 @@ class RuntimeProfile::EventSequence { /// 'start_time_ns', which must have been obtained by calling MonotonicStopWatch::Now(). void Start(int64_t start_time_ns) { offset_ = MonotonicStopWatch::Now() - start_time_ns; - DCHECK_GE(offset_, 0); + // TODO: IMPALA-4631: Occasionally we see MonotonicStopWatch::Now() return + // (start_time_ns - 1), even though 'start_time_ns' was obtained using + // MonotonicStopWatch::Now(). + DCHECK_GE(offset_, -1); sw_.Start(); } /// Stores an event in sequence with the given label and the current time /// (relative to the first time Start() was called) as the timestamp. void MarkEvent(std::string label) { - Event event = make_pair(move(label), sw_.ElapsedTime()); + Event event = make_pair(move(label), sw_.ElapsedTime() + offset_); boost::lock_guard<SpinLock> event_lock(lock_); events_.emplace_back(move(event)); } @@ -334,7 +337,8 @@ class RuntimeProfile::EventSequence { } /// Adds all events from the input parameters that are newer than the last member of - /// 'events_'. The caller must make sure that 'timestamps' is sorted. + /// 'events_'. The caller must make sure that 'timestamps' is sorted. Does not adjust + /// added timestamps by 'offset_'. void AddNewerEvents( const std::vector<int64_t>& timestamps, const std::vector<std::string>& labels) { DCHECK_EQ(timestamps.size(), labels.size());