[jira] [Created] (IMPALA-6735) Inconsistent query submission, start, and end times in query profile

["Alexander Behm (JIRA)" <ji...@apache.org>]

Alexander Behm created IMPALA-6735:
--------------------------------------

             Summary: Inconsistent query submission, start, and end times in query profile
                 Key: IMPALA-6735
                 URL: https://issues.apache.org/jira/browse/IMPALA-6735
             Project: IMPALA
          Issue Type: Bug
          Components: Backend
    Affects Versions: Impala 2.11.0
            Reporter: Alexander Behm


We've sometimes observed inconsistencies in the following runtime profile entrues:
* Query submitted (timeline event)
* Start Time (info string, not a timeline event)
* End Time (into string, not a timeline event)

Here is one inconsistent example:
{code}
Query submitted at	: 2018-03-22 10:27:57
Start Time	: 2018-03-22 10:28:05.883997000 
End Time	: 2018-03-22 10:28:05.915566000
{code}

Based on the backend code it should not be possible that "Start Time" happens after "Query submitted". The relevant code snipped is in impala-server.cc ImpalaServer::ExecuteInternal():
{code}
...
// Sets the Start Time
  request_state->reset(new ClientRequestState(query_ctx, exec_env_, exec_env_->frontend(),
      this, session_state));
// Sets the query submitted time
  (*request_state)->query_events()->MarkEvent("Query submitted");
...
{code}

One possible explanation could be that these events get the current time from different functions:
* The timeline events use our MonotonicStopWatch
* The "Start Time" and "End Time" use UnixMicros() from our own time.h

It's not clear that these produce consistent timings.



--
This message was sent by Atlassian JIRA
(v7.6.3#76005)