Add time spent in WAITING_FOR_RESOURCES state to query timeline log

trinodb · Mar 12, 2019 · b7dd733 · b7dd733
1 parent 663583e
commit b7dd733
Showing 1 changed file with 8 additions and 1 deletion.
diff --git 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<StageInfo> 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,