public void completionEvent(QueryInfo queryInfo) {
try {
QueryStats queryStats = queryInfo.getQueryStats();
FailureInfo failureInfo = queryInfo.getFailureInfo();
String failureType = failureInfo == null ? null : failureInfo.getType();
String failureMessage = failureInfo == null ? null : failureInfo.getMessage();
eventClient.post(
new QueryCompletionEvent(
queryInfo.getQueryId(),
queryInfo.getSession().getUser(),
queryInfo.getSession().getSource(),
environment,
queryInfo.getSession().getCatalog(),
queryInfo.getSession().getSchema(),
queryInfo.getSession().getRemoteUserAddress(),
queryInfo.getSession().getUserAgent(),
queryInfo.getState(),
queryInfo.getSelf(),
queryInfo.getFieldNames(),
queryInfo.getQuery(),
queryStats.getCreateTime(),
queryStats.getExecutionStartTime(),
queryStats.getEndTime(),
queryStats.getQueuedTime(),
queryStats.getAnalysisTime(),
queryStats.getDistributedPlanningTime(),
queryStats.getTotalScheduledTime(),
queryStats.getTotalCpuTime(),
queryStats.getRawInputDataSize(),
queryStats.getRawInputPositions(),
queryStats.getTotalDrivers(),
queryInfo.getErrorCode(),
failureType,
failureMessage,
objectMapper.writeValueAsString(queryInfo.getOutputStage()),
objectMapper.writeValueAsString(queryInfo.getFailureInfo()),
objectMapper.writeValueAsString(queryInfo.getInputs())));
logQueryTimeline(queryInfo);
} catch (JsonProcessingException e) {
throw Throwables.propagate(e);
}
}
private void logQueryTimeline(QueryInfo queryInfo) {
try {
QueryStats queryStats = queryInfo.getQueryStats();
DateTime queryStartTime = queryStats.getCreateTime();
DateTime queryEndTime = queryStats.getEndTime();
// query didn't finish cleanly
if (queryStartTime == null || queryEndTime == null) {
return;
}
// planning duration -- start to end of planning
Duration planning = queryStats.getTotalPlanningTime();
if (planning == null) {
planning = new Duration(0, MILLISECONDS);
}
List<StageInfo> stages = StageInfo.getAllStages(queryInfo.getOutputStage());
// long lastSchedulingCompletion = 0;
long firstTaskStartTime = queryEndTime.getMillis();
long lastTaskStartTime = queryStartTime.getMillis() + planning.toMillis();
long lastTaskEndTime = queryStartTime.getMillis() + planning.toMillis();
for (StageInfo stage : stages) {
// only consider leaf stages
if (!stage.getSubStages().isEmpty()) {
continue;
}
for (TaskInfo taskInfo : stage.getTasks()) {
TaskStats taskStats = taskInfo.getStats();
DateTime firstStartTime = taskStats.getFirstStartTime();
if (firstStartTime != null) {
firstTaskStartTime = Math.min(firstStartTime.getMillis(), firstTaskStartTime);
}
DateTime lastStartTime = taskStats.getLastStartTime();
if (lastStartTime != null) {
lastTaskStartTime = Math.max(lastStartTime.getMillis(), lastTaskStartTime);
}
DateTime endTime = taskStats.getEndTime();
if (endTime != null) {
lastTaskEndTime = Math.max(endTime.getMillis(), lastTaskEndTime);
}
}
}
Duration elapsed = millis(queryEndTime.getMillis() - queryStartTime.getMillis());
Duration scheduling =
millis(firstTaskStartTime - queryStartTime.getMillis() - planning.toMillis());
Duration running = millis(lastTaskEndTime - firstTaskStartTime);
Duration finishing = millis(queryEndTime.getMillis() - lastTaskEndTime);
log.info(
"TIMELINE: Query %s :: elapsed %s :: planning %s :: scheduling %s :: running %s :: finishing %s :: begin %s :: end %s",
queryInfo.getQueryId(),
elapsed,
planning,
scheduling,
running,
finishing,
queryStartTime,
queryEndTime);
} catch (Exception e) {
log.error(e, "Error logging query timeline");
}
}