IMPALA-6136: Part 1: Query duration should not be normally negative. The second commit for IMPALA-5599, 1640aa97, introduced a regression where calculating the duration of an in-progress query can result in negative values. This can happen for two reasons:
1. The value of ClientRequestState::end_time_us_ is not initialized in the constructor, and may have some random value until ClientRequestState::Done() is called. 2. If ClientRequestState::end_time_us_ happens to have a positive value less than ClientRequestState::start_time_us_, the query duration will be negative. Here, since the query is still in flight, we need to use the local current time as the end time. The fix has been manually verified by executing long-running queries and checking the query profiles to ensure the durations are not some random junks. A new test case will be added to check for sane time values in a follow-on commit. Since we are using Unix time (system clock) for time stamps, it is still possible for end_time_us_ to be less than start_time_us_ if the system clock gets reset while the query is executing. If there are clients that assume that a query duration is never negative, we really should switch to a monotonic clock to time queries. Change-Id: Ib6f971ebd5f0f00f3e38df0495692ffe9d52ef90 Reviewed-on: http://gerrit.cloudera.org:8080/8430 Reviewed-by: Michael Ho <[email protected]> Tested-by: Impala Public Jenkins Project: http://git-wip-us.apache.org/repos/asf/incubator-impala/repo Commit: http://git-wip-us.apache.org/repos/asf/incubator-impala/commit/3cea0e9d Tree: http://git-wip-us.apache.org/repos/asf/incubator-impala/tree/3cea0e9d Diff: http://git-wip-us.apache.org/repos/asf/incubator-impala/diff/3cea0e9d Branch: refs/heads/master Commit: 3cea0e9dbbf842b8eb3a377f881c9a116b97eed5 Parents: 5edbb15 Author: Zoram Thanga <[email protected]> Authored: Tue Oct 31 12:12:28 2017 -0700 Committer: Impala Public Jenkins <[email protected]> Committed: Fri Nov 3 02:22:21 2017 +0000 ---------------------------------------------------------------------- be/src/service/client-request-state.cc | 3 ++- be/src/service/client-request-state.h | 3 +++ be/src/service/impala-http-handler.cc | 6 +++++- be/src/service/impala-server.h | 3 +++ 4 files changed, 13 insertions(+), 2 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/incubator-impala/blob/3cea0e9d/be/src/service/client-request-state.cc ---------------------------------------------------------------------- diff --git a/be/src/service/client-request-state.cc b/be/src/service/client-request-state.cc index e6fd618..918fc03 100644 --- a/be/src/service/client-request-state.cc +++ b/be/src/service/client-request-state.cc @@ -88,7 +88,8 @@ ClientRequestState::ClientRequestState( fetched_rows_(false), frontend_(frontend), parent_server_(server), - start_time_us_(UnixMicros()) { + start_time_us_(UnixMicros()), + end_time_us_(0LL) { #ifndef NDEBUG profile_->AddInfoString("DEBUG MODE WARNING", "Query profile created while running a " "DEBUG build of Impala. Use RELEASE builds to measure query performance."); http://git-wip-us.apache.org/repos/asf/incubator-impala/blob/3cea0e9d/be/src/service/client-request-state.h ---------------------------------------------------------------------- diff --git a/be/src/service/client-request-state.h b/be/src/service/client-request-state.h index 0ebdda9..a5c03f5 100644 --- a/be/src/service/client-request-state.h +++ b/be/src/service/client-request-state.h @@ -339,6 +339,9 @@ class ClientRequestState { ImpalaServer* parent_server_; /// Start/end time of the query, in Unix microseconds. + /// end_time_us_ is initialized to 0 in the constructor, which is used to indicate + /// that the query is not yet done. It is assinged the final value in + /// ClientRequestState::Done(). int64_t start_time_us_, end_time_us_; /// Executes a local catalog operation (an operation that does not need to execute http://git-wip-us.apache.org/repos/asf/incubator-impala/blob/3cea0e9d/be/src/service/impala-http-handler.cc ---------------------------------------------------------------------- diff --git a/be/src/service/impala-http-handler.cc b/be/src/service/impala-http-handler.cc index d4ef52f..d746ff2 100644 --- a/be/src/service/impala-http-handler.cc +++ b/be/src/service/impala-http-handler.cc @@ -300,7 +300,11 @@ void ImpalaHttpHandler::QueryStateToJson(const ImpalaServer::QueryStateRecord& r document->GetAllocator()); value->AddMember("end_time", end_time, document->GetAllocator()); - int64_t duration_us = record.end_time_us - record.start_time_us; + // record.end_time_us might still be zero if the query is not yet done + // Use the current Unix time in that case. Note that the duration can be + // negative if a system clock reset happened after the query was initiated. + int64_t end_time_us = record.end_time_us > 0LL ? record.end_time_us : UnixMicros(); + int64_t duration_us = end_time_us - record.start_time_us; const string& printed_duration = PrettyPrinter::Print(duration_us * NANOS_PER_MICRO, TUnit::TIME_NS); Value val_duration(printed_duration.c_str(), document->GetAllocator()); http://git-wip-us.apache.org/repos/asf/incubator-impala/blob/3cea0e9d/be/src/service/impala-server.h ---------------------------------------------------------------------- diff --git a/be/src/service/impala-server.h b/be/src/service/impala-server.h index 1653765..f0dfa06 100644 --- a/be/src/service/impala-server.h +++ b/be/src/service/impala-server.h @@ -620,6 +620,9 @@ class ImpalaServer : public ImpalaServiceIf, beeswax::QueryState::type query_state; /// Start and end time of the query, in Unix microseconds. + /// A query whose end_time_us is 0 indicates that it is an in-flight query. + /// These two variables are initialized with the corresponding values from + /// ClientRequestState. int64_t start_time_us, end_time_us; /// Summary of execution for this query.
