diff --git a/presto-main/src/main/java/io/prestosql/event/QueryMonitor.java b/presto-main/src/main/java/io/prestosql/event/QueryMonitor.java index 8e3ad1b980457..e26f53dd96818 100644 --- a/presto-main/src/main/java/io/prestosql/event/QueryMonitor.java +++ b/presto-main/src/main/java/io/prestosql/event/QueryMonitor.java @@ -412,6 +412,9 @@ private static void logQueryTimeline(QueryInfo queryInfo) // planning duration -- start to end of planning long planning = queryStats.getTotalPlanningTime().toMillis(); + // Time spent waiting for required no. of worker nodes to be present + long waiting = queryStats.getResourceWaitingTime().toMillis(); + List stages = StageInfo.getAllStages(queryInfo.getOutputStage()); // long lastSchedulingCompletion = 0; long firstTaskStartTime = queryEndTime.getMillis(); @@ -453,6 +456,7 @@ private static void logQueryTimeline(QueryInfo queryInfo) queryInfo.getSession().getTransactionId().map(TransactionId::toString).orElse(""), elapsed, planning, + waiting, scheduling, running, finishing, @@ -484,6 +488,7 @@ private static void logQueryTimeline(BasicQueryInfo queryInfo) 0, 0, 0, + 0, queryStartTime, queryEndTime); } @@ -493,17 +498,19 @@ private static void logQueryTimeline( String transactionId, long elapsedMillis, long planningMillis, + long waitingMillis, long schedulingMillis, long runningMillis, long finishingMillis, DateTime queryStartTime, DateTime queryEndTime) { - log.info("TIMELINE: Query %s :: Transaction:[%s] :: elapsed %sms :: planning %sms :: scheduling %sms :: running %sms :: finishing %sms :: begin %s :: end %s", + log.info("TIMELINE: Query %s :: Transaction:[%s] :: elapsed %sms :: planning %sms :: waiting %sms :: scheduling %sms :: running %sms :: finishing %sms :: begin %s :: end %s", queryId, transactionId, elapsedMillis, planningMillis, + waitingMillis, schedulingMillis, runningMillis, finishingMillis,