[IMPALA-6735] Inconsistent query submission, start, and end times in query profile

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Not A Bug
• Affects Version/s: Impala 2.11.0
• Component/s: Backend
• Labels: supportability
• Epic Link: SupportabilityRoadMap
• Epic Color: ghx-label-3
• Assignee: Unassigned
• Reporter: Alexander Behm
• Created: 24/Mar/18 20:35
• Updated: 04/Apr/18 23:58
• Resolved: 04/Apr/18 23:58

Description

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:

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

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():

...
// 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");
...

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.