Repository: prestodb/presto
Issue: Presto stats planning time is including queueing time

I noticed this when Presto was reporting super long planning times, but it looks like this was just because the queues are really full.


Changed files:
presto-main/src/main/java/com/facebook/presto/execution/QueryStateMachine.java
presto-main/src/test/java/com/facebook/presto/execution/TestQueryStateMachine.java

diff --git a/presto-main/src/main/java/com/facebook/presto/execution/QueryStateMachine.java b/presto-main/src/main/java/com/facebook/presto/execution/QueryStateMachine.java
index 8751bd1139..f97902577c 100644
--- a/presto-main/src/main/java/com/facebook/presto/execution/QueryStateMachine.java
+++ b/presto-main/src/main/java/com/facebook/presto/execution/QueryStateMachine.java
@@ -25,6 +25,7 @@ import com.facebook.presto.sql.planner.PlanFragment;
 import com.facebook.presto.sql.planner.plan.TableScanNode;
 import com.facebook.presto.transaction.TransactionId;
 import com.facebook.presto.transaction.TransactionManager;
+import com.google.common.base.Ticker;
 import com.google.common.collect.ImmutableList;
 import com.google.common.collect.ImmutableSet;
 import com.google.common.collect.Sets;
@@ -61,7 +62,7 @@ import static com.facebook.presto.spi.StandardErrorCode.USER_CANCELED;
 import static com.facebook.presto.util.Failures.toFailure;
 import static com.google.common.base.Preconditions.checkArgument;
 import static io.airlift.units.DataSize.succinctBytes;
-import static io.airlift.units.Duration.nanosSince;
+import static io.airlift.units.Duration.succinctNanos;
 import static java.util.Objects.requireNonNull;
 import static java.util.concurrent.TimeUnit.NANOSECONDS;
 
@@ -71,7 +72,7 @@ public class QueryStateMachine
     private static final Logger log = Logger.get(QueryStateMachine.class);
 
     private final DateTime createTime = DateTime.now();
-    private final long createNanos = System.nanoTime();
+    private final long createNanos;
     private final AtomicLong endNanos = new AtomicLong();
 
     private final QueryId queryId;
@@ -80,6 +81,7 @@ public class QueryStateMachine
     private final URI self;
     private final boolean autoCommit;
     private final TransactionManager transactionManager;
+    private final Ticker ticker;
 
     private final AtomicReference<VersionedMemoryPoolId> memoryPool = new AtomicReference<>(new VersionedMemoryPoolId(GENERAL_POOL, 0));
 
@@ -96,6 +98,7 @@ public class QueryStateMachine
     private final AtomicReference<Long> finishingStartNanos = new AtomicReference<>();
     private final AtomicReference<Duration> finishingTime = new AtomicReference<>();
 
+    private final AtomicReference<Long> totalPlanningStartNanos = new AtomicReference<>();
     private final AtomicReference<Duration> totalPlanningTime = new AtomicReference<>();
 
     private final StateMachine<QueryState> queryState;
@@ -119,7 +122,7 @@ public class QueryStateMachine
     private final AtomicReference<Optional<Output>> output = new AtomicReference<>(Optional.empty());
     private final StateMachine<Optional<QueryInfo>> finalQueryInfo;
 
-    private QueryStateMachine(QueryId queryId, String query, Session session, URI self, boolean autoCommit, TransactionManager transactionManager, Executor executor)
+    private QueryStateMachine(QueryId queryId, String query, Session session, URI self, boolean autoCommit, TransactionManager transactionManager, Executor executor, Ticker ticker)
     {
         this.queryId = requireNonNull(queryId, "queryId is null");
         this.query = requireNonNull(query, "query is null");
@@ -127,6 +130,8 @@ public class QueryStateMachine
         this.self = requireNonNull(self, "self is null");
         this.autoCommit = autoCommit;
         this.transactionManager = requireNonNull(transactionManager, "transactionManager is null");
+        this.ticker = ticker;
+        this.createNanos = tickerNanos();
 
         this.queryState = new StateMachine<>("query " + query, executor, QUEUED, TERMINAL_QUERY_STATES);
         this.finalQueryInfo = new StateMachine<>("finalQueryInfo-" + queryId, executor, Optional.empty());
@@ -136,6 +141,19 @@ public class QueryStateMachine
      * Created QueryStateMachines must be transitioned to terminal states to clean up resources.
      */
     public static QueryStateMachine begin(QueryId queryId, String query, Session session, URI self, boolean transactionControl, TransactionManager transactionManager, Executor executor)
+    {
+        return beginWithTicker(queryId, query, session, self, transactionControl, transactionManager, executor, Ticker.systemTicker());
+    }
+
+    static QueryStateMachine beginWithTicker(
+            QueryId queryId,
+            String query,
+            Session session,
+            URI self,
+            boolean transactionControl,
+            TransactionManager transactionManager,
+            Executor executor,
+            Ticker ticker)
     {
         session.getTransactionId().ifPresent(transactionControl ? transactionManager::trySetActive : transactionManager::checkAndSetActive);
 
@@ -150,7 +168,7 @@ public class QueryStateMachine
             querySession = session;
         }
 
-        QueryStateMachine queryStateMachine = new QueryStateMachine(queryId, query, querySession, self, autoCommit, transactionManager, executor);
+        QueryStateMachine queryStateMachine = new QueryStateMachine(queryId, query, querySession, self, autoCommit, transactionManager, executor, ticker);
         queryStateMachine.addStateChangeListener(newState -> log.debug("Query %s is %s", queryId, newState));
         queryStateMachine.addStateChangeListener(newState -> {
             if (newState.isDone()) {
@@ -166,7 +184,20 @@ public class QueryStateMachine
      */
     public static QueryStateMachine failed(QueryId queryId, String query, Session session, URI self, TransactionManager transactionManager, Executor executor, Throwable throwable)
     {
-        QueryStateMachine queryStateMachine = new QueryStateMachine(queryId, query, session, self, false, transactionManager, executor);
+        return failedWithTicker(queryId, query, session, self, transactionManager, executor, Ticker.systemTicker(), throwable);
+    }
+
+    static QueryStateMachine failedWithTicker(
+            QueryId queryId,
+            String query,
+            Session session,
+            URI self,
+            TransactionManager transactionManager,
+            Executor executor,
+            Ticker ticker,
+            Throwable throwable)
+    {
+        QueryStateMachine queryStateMachine = new QueryStateMachine(queryId, query, session, self, false, transactionManager, executor, ticker);
         queryStateMachine.transitionToFailed(throwable);
         return queryStateMachine;
     }
@@ -472,14 +503,15 @@ public class QueryStateMachine
     public boolean transitionToPlanning()
     {
         queuedTime.compareAndSet(null, nanosSince(createNanos).convertToMostSuccinctTimeUnit());
+        totalPlanningStartNanos.compareAndSet(null, tickerNanos());
         return queryState.compareAndSet(QUEUED, PLANNING);
     }
 
     public boolean transitionToStarting()
     {
-        Duration durationSinceCreation = nanosSince(createNanos).convertToMostSuccinctTimeUnit();
-        queuedTime.compareAndSet(null, durationSinceCreation);
-        totalPlanningTime.compareAndSet(null, durationSinceCreation);
+        queuedTime.compareAndSet(null, nanosSince(createNanos).convertToMostSuccinctTimeUnit());
+        totalPlanningStartNanos.compareAndSet(null, tickerNanos());
+        totalPlanningTime.compareAndSet(null, nanosSince(totalPlanningStartNanos.get()));
 
         return queryState.setIf(STARTING, currentState -> currentState == QUEUED || currentState == PLANNING);
     }
@@ -488,7 +520,8 @@ public class QueryStateMachine
     {
         Duration durationSinceCreation = nanosSince(createNanos).convertToMostSuccinctTimeUnit();
         queuedTime.compareAndSet(null, durationSinceCreation);
-        totalPlanningTime.compareAndSet(null, durationSinceCreation);
+        totalPlanningStartNanos.compareAndSet(null, tickerNanos());
+        totalPlanningTime.compareAndSet(null, nanosSince(totalPlanningStartNanos.get()));
         executionStartTime.compareAndSet(null, DateTime.now());
 
         return queryState.setIf(RUNNING, currentState -> currentState != RUNNING && currentState != FINISHING && !currentState.isDone());
@@ -498,10 +531,11 @@ public class QueryStateMachine
     {
         Duration durationSinceCreation = nanosSince(createNanos).convertToMostSuccinctTimeUnit();
         queuedTime.compareAndSet(null, durationSinceCreation);
-        totalPlanningTime.compareAndSet(null, durationSinceCreation);
+        totalPlanningStartNanos.compareAndSet(null, tickerNanos());
+        totalPlanningTime.compareAndSet(null, nanosSince(totalPlanningStartNanos.get()));
         DateTime now = DateTime.now();
         executionStartTime.compareAndSet(null, now);
-        finishingStartNanos.compareAndSet(null, System.nanoTime());
+        finishingStartNanos.compareAndSet(null, tickerNanos());
 
         if (!queryState.setIf(FINISHING, currentState -> currentState != FINISHING && !currentState.isDone())) {
             return false;
@@ -575,13 +609,14 @@ public class QueryStateMachine
     {
         Duration durationSinceCreation = nanosSince(createNanos).convertToMostSuccinctTimeUnit();
         queuedTime.compareAndSet(null, durationSinceCreation);
-        totalPlanningTime.compareAndSet(null, durationSinceCreation);
+        totalPlanningStartNanos.compareAndSet(null, tickerNanos());
+        totalPlanningTime.compareAndSet(null, nanosSince(totalPlanningStartNanos.get()));
         DateTime now = DateTime.now();
         executionStartTime.compareAndSet(null, now);
-        finishingStartNanos.compareAndSet(null, System.nanoTime());
+        finishingStartNanos.compareAndSet(null, tickerNanos());
         finishingTime.compareAndSet(null, nanosSince(finishingStartNanos.get()));
         endTime.compareAndSet(null, now);
-        endNanos.compareAndSet(0, System.nanoTime());
+        endNanos.compareAndSet(0, tickerNanos());
     }
 
     public void addStateChangeListener(StateChangeListener<QueryState> stateChangeListener)
@@ -693,4 +728,14 @@ public class QueryStateMachine
         );
         finalQueryInfo.compareAndSet(finalInfo, Optional.of(prunedQueryInfo));
     }
+
+    private long tickerNanos()
+    {
+        return ticker.read();
+    }
+
+    private Duration nanosSince(long start)
+    {
+        return succinctNanos(tickerNanos() - start);
+    }
 }
diff --git a/presto-main/src/test/java/com/facebook/presto/execution/TestQueryStateMachine.java b/presto-main/src/test/java/com/facebook/presto/execution/TestQueryStateMachine.java
index 8dafa666ce..2417172563 100644
--- a/presto-main/src/test/java/com/facebook/presto/execution/TestQueryStateMachine.java
+++ b/presto-main/src/test/java/com/facebook/presto/execution/TestQueryStateMachine.java
@@ -21,8 +21,10 @@ import com.facebook.presto.spi.PrestoException;
 import com.facebook.presto.spi.QueryId;
 import com.facebook.presto.spi.memory.MemoryPoolId;
 import com.facebook.presto.transaction.TransactionManager;
+import com.google.common.base.Ticker;
 import com.google.common.collect.ImmutableList;
 import com.google.common.collect.ImmutableMap;
+import io.airlift.testing.TestingTicker;
 import io.airlift.units.Duration;
 import org.testng.annotations.AfterClass;
 import org.testng.annotations.Test;
@@ -243,6 +245,36 @@ public class TestQueryStateMachine
         assertFinalState(stateMachine, FAILED, new PrestoException(USER_CANCELED, "canceled"));
     }
 
+    @Test
+    public void testPlanningTimeDuration()
+            throws InterruptedException
+    {
+        TestingTicker mockTicker = new TestingTicker();
+        QueryStateMachine stateMachine = createQueryStateMachineWithTicker(mockTicker);
+        assertState(stateMachine, QUEUED);
+
+        mockTicker.increment(100, TimeUnit.MILLISECONDS);
+        assertTrue(stateMachine.transitionToPlanning());
+        assertState(stateMachine, PLANNING);
+
+        mockTicker.increment(500, TimeUnit.MILLISECONDS);
+        assertTrue(stateMachine.transitionToStarting());
+        assertState(stateMachine, STARTING);
+
+        mockTicker.increment(300, TimeUnit.MILLISECONDS);
+        assertTrue(stateMachine.transitionToRunning());
+        assertState(stateMachine, RUNNING);
+
+        mockTicker.increment(200, TimeUnit.MILLISECONDS);
+        assertTrue(stateMachine.transitionToFinishing());
+        stateMachine.waitForStateChange(FINISHING, new Duration(2, TimeUnit.SECONDS));
+        assertState(stateMachine, FINISHED);
+
+        QueryStats queryStats = stateMachine.getQueryInfo(Optional.empty()).getQueryStats();
+        assertTrue(queryStats.getQueuedTime().toMillis() == 100);
+        assertTrue(queryStats.getTotalPlanningTime().toMillis() == 500);
+    }
+
     private static void assertFinalState(QueryStateMachine stateMachine, QueryState expectedState)
     {
         assertFinalState(stateMachine, expectedState, null);
@@ -362,9 +394,14 @@ public class TestQueryStateMachine
     }
 
     private QueryStateMachine createQueryStateMachine()
+    {
+        return createQueryStateMachineWithTicker(Ticker.systemTicker());
+    }
+
+    private QueryStateMachine createQueryStateMachineWithTicker(Ticker ticker)
     {
         TransactionManager transactionManager = createTestTransactionManager();
-        QueryStateMachine stateMachine = QueryStateMachine.begin(QUERY_ID, QUERY, TEST_SESSION, LOCATION, false, transactionManager, executor);
+        QueryStateMachine stateMachine = QueryStateMachine.beginWithTicker(QUERY_ID, QUERY, TEST_SESSION, LOCATION, false, transactionManager, executor, ticker);
         stateMachine.setInputs(INPUTS);
         stateMachine.setOutput(OUTPUT);
         stateMachine.setOutputFieldNames(OUTPUT_FIELD_NAMES);