server: return elapsed time for active executions

Previously, we calculated the time elapsed for an active
stmt or txn based on the start time returned from the
server and the time the response was last received.
Calculating this value on the client is not reliable and
can lead to negative values when the server time is slightly
ahead. This commit fixes this issue by including the time
elapsed as part of the active txns and stmts response.

Release note (bug fix): time elapsed for active txns and stmts
is never negative.

docs/generated/http/full.md

@@ -2138,6 +2138,7 @@ ActiveQuery represents a query in flight on some Session.
 | sql_no_constants | [string](#cockroach.server.serverpb.ListSessionsResponse-string) |  | The SQL statement fingerprint, compatible with StatementStatisticsKey. | [reserved](#support-status) |
 | sql_summary | [string](#cockroach.server.serverpb.ListSessionsResponse-string) |  | A summarized version of the sql query. | [reserved](#support-status) |
 | is_full_scan | [bool](#cockroach.server.serverpb.ListSessionsResponse-bool) |  | True if the query contains a full table or index scan. Note that this field is only valid if the query is in the EXECUTING phase. | [reserved](#support-status) |
+| elapsed_time | [google.protobuf.Duration](#cockroach.server.serverpb.ListSessionsResponse-google.protobuf.Duration) |  | Time elapsed since this query started execution. | [reserved](#support-status) |
 
 
 
@@ -2165,6 +2166,7 @@ TxnInfo represents an in flight user transaction on some Session.
 | priority | [string](#cockroach.server.serverpb.ListSessionsResponse-string) |  |  | [reserved](#support-status) |
 | quality_of_service | [string](#cockroach.server.serverpb.ListSessionsResponse-string) |  |  | [reserved](#support-status) |
 | last_auto_retry_reason | [string](#cockroach.server.serverpb.ListSessionsResponse-string) |  | Error message describing the cause for the txn's last automatic retry. | [reserved](#support-status) |
+| elapsed_time | [google.protobuf.Duration](#cockroach.server.serverpb.ListSessionsResponse-google.protobuf.Duration) |  | Time elapsed since this transaction started execution. | [reserved](#support-status) |
 
 
 
@@ -2278,6 +2280,7 @@ ActiveQuery represents a query in flight on some Session.
 | sql_no_constants | [string](#cockroach.server.serverpb.ListSessionsResponse-string) |  | The SQL statement fingerprint, compatible with StatementStatisticsKey. | [reserved](#support-status) |
 | sql_summary | [string](#cockroach.server.serverpb.ListSessionsResponse-string) |  | A summarized version of the sql query. | [reserved](#support-status) |
 | is_full_scan | [bool](#cockroach.server.serverpb.ListSessionsResponse-bool) |  | True if the query contains a full table or index scan. Note that this field is only valid if the query is in the EXECUTING phase. | [reserved](#support-status) |
+| elapsed_time | [google.protobuf.Duration](#cockroach.server.serverpb.ListSessionsResponse-google.protobuf.Duration) |  | Time elapsed since this query started execution. | [reserved](#support-status) |
 
 
 
@@ -2305,6 +2308,7 @@ TxnInfo represents an in flight user transaction on some Session.
 | priority | [string](#cockroach.server.serverpb.ListSessionsResponse-string) |  |  | [reserved](#support-status) |
 | quality_of_service | [string](#cockroach.server.serverpb.ListSessionsResponse-string) |  |  | [reserved](#support-status) |
 | last_auto_retry_reason | [string](#cockroach.server.serverpb.ListSessionsResponse-string) |  | Error message describing the cause for the txn's last automatic retry. | [reserved](#support-status) |
+| elapsed_time | [google.protobuf.Duration](#cockroach.server.serverpb.ListSessionsResponse-google.protobuf.Duration) |  | Time elapsed since this transaction started execution. | [reserved](#support-status) |
 
 
 

pkg/server/serverpb/status.proto

@@ -862,6 +862,10 @@ message TxnInfo {
 
   // Error message describing the cause for the txn's last automatic retry.
   string last_auto_retry_reason = 15;
+
+  // Time elapsed since this transaction started execution.
+  google.protobuf.Duration elapsed_time = 16
+  [ (gogoproto.nullable) = false, (gogoproto.stdduration) = true ];
 }
 
 // ActiveQuery represents a query in flight on some Session.
@@ -905,6 +909,9 @@ message ActiveQuery {
   // field is only valid if the query is in the EXECUTING phase.
   bool is_full_scan = 10;
 
+  // Time elapsed since this query started execution.
+  google.protobuf.Duration elapsed_time = 11
+  [ (gogoproto.nullable) = false, (gogoproto.stdduration) = true ];
 }
 
 // Request object for ListSessions and ListLocalSessions.

pkg/sql/conn_executor.go

@@ -3131,11 +3131,14 @@ func (ex *connExecutor) serialize() serverpb.Session {
 		autoRetryReasonStr = ex.state.mu.autoRetryReason.Error()
 	}
 
+	timeNow := timeutil.Now()
+
 	if txn != nil {
 		id := txn.ID()
 		activeTxnInfo = &serverpb.TxnInfo{
 			ID:                    id,
 			Start:                 ex.state.mu.txnStart,
+			ElapsedTime:           timeNow.Sub(ex.state.mu.txnStart),
 			NumStatementsExecuted: int32(ex.state.mu.stmtCount),
 			NumRetries:            int32(txn.Epoch()),
 			NumAutoRetries:        ex.state.mu.autoRetryCounter,
@@ -3178,10 +3181,12 @@ func (ex *connExecutor) serialize() serverpb.Session {
 		sqlNoConstants := truncateSQL(formatStatementHideConstants(ast))
 		sql := truncateSQL(ast.String())
 		progress := math.Float64frombits(atomic.LoadUint64(&query.progressAtomic))
+		queryStart := query.start.UTC()
 		activeQueries = append(activeQueries, serverpb.ActiveQuery{
 			TxnID:          query.txnID,
 			ID:             id.String(),
-			Start:          query.start.UTC(),
+			Start:          queryStart,
+			ElapsedTime:    timeNow.Sub(queryStart),
 			Sql:            sql,
 			SqlNoConstants: sqlNoConstants,
 			SqlSummary:     formatStatementSummary(ast),

pkg/ui/workspaces/cluster-ui/src/activeExecutions/activeStatementUtils.spec.ts

@@ -32,7 +32,6 @@ import {
 type ActiveQuery = protos.cockroach.server.serverpb.ActiveQuery;
 const Timestamp = protos.google.protobuf.Timestamp;
 
-const LAST_UPDATED = moment(new Date("2022-01-04T08:01:00"));
 const MOCK_START_TIME = moment(new Date("2022-01-04T08:00:00"));
 
 const defaultActiveQuery = {
@@ -53,7 +52,7 @@ const defaultActiveStatement: ActiveStatement = {
   query: defaultActiveQuery.sql,
   status: "Executing",
   start: MOCK_START_TIME,
-  elapsedTimeMillis: 60,
+  elapsedTime: moment.duration(60),
   application: "test",
   user: "user",
   clientAddress: "clientAddress",
@@ -79,7 +78,7 @@ function makeActiveTxn(
     transactionID: "txn",
     sessionID: "sessionID",
     start: MOCK_START_TIME,
-    elapsedTimeMillis: 10,
+    elapsedTime: moment.duration(60),
     application: "application",
     query: defaultActiveStatement.query,
     statementID: defaultActiveStatement.statementID,
@@ -215,10 +214,8 @@ describe("test activeStatementUtils", () => {
         toJSON: () => ({}),
       };
 
-      const statements = getActiveExecutionsFromSessions(
-        sessionsResponse,
-        LAST_UPDATED,
-      ).statements;
+      const statements =
+        getActiveExecutionsFromSessions(sessionsResponse).statements;
 
       expect(statements.length).toBe(2);
 
@@ -234,9 +231,6 @@ describe("test activeStatementUtils", () => {
         }
         // expect(stmt.transactionID).toBe(defaultActiveStatement.transactionID);
         expect(stmt.status).toBe("Executing");
-        expect(stmt.elapsedTimeMillis).toBe(
-          LAST_UPDATED.diff(MOCK_START_TIME, "ms"),
-        );
         expect(stmt.start.unix()).toBe(
           TimestampToMoment(defaultActiveQuery.start).unix(),
         );
@@ -297,10 +291,8 @@ describe("test activeStatementUtils", () => {
         toJSON: () => ({}),
       };
 
-      const activeTransactions = getActiveExecutionsFromSessions(
-        sessionsResponse,
-        LAST_UPDATED,
-      ).transactions;
+      const activeTransactions =
+        getActiveExecutionsFromSessions(sessionsResponse).transactions;
 
       // Should filter out the txn from closed  session.
       expect(activeTransactions.length).toBe(2);
@@ -309,9 +301,6 @@ describe("test activeStatementUtils", () => {
         expect(txn.application).toBe(
           sessionsResponse.sessions[i].application_name,
         );
-        expect(txn.elapsedTimeMillis).toBe(
-          LAST_UPDATED.diff(MOCK_START_TIME, "ms"),
-        );
         expect(txn.status).toBe("Executing");
         expect(txn.query).toBeTruthy();
         expect(txn.start.unix()).toBe(
@@ -356,10 +345,7 @@ describe("test activeStatementUtils", () => {
         toJSON: () => ({}),
       };
 
-      const activeExecs = getActiveExecutionsFromSessions(
-        sessionsResponse,
-        LAST_UPDATED,
-      );
+      const activeExecs = getActiveExecutionsFromSessions(sessionsResponse);
 
       expect(activeExecs.transactions[0].query).toBe(lastActiveQueryText);
       expect(activeExecs.transactions[1].query).toBeFalsy();

pkg/ui/workspaces/cluster-ui/src/activeExecutions/activeStatementUtils.ts

@@ -8,7 +8,7 @@
 // by the Apache License, Version 2.0, included in the file
 // licenses/APL.txt.
 
-import moment, { Moment } from "moment";
+import moment from "moment";
 import { byteArrayToUuid } from "src/sessions";
 import { TimestampToMoment, unset } from "src/util";
 import { ActiveTransaction } from ".";
@@ -25,6 +25,7 @@ import {
 } from "./types";
 import { ActiveStatement, ActiveStatementFilters } from "./types";
 import { ClusterLocksResponse, ClusterLockState } from "src/api";
+import { DurationToMomentDuration } from "src/util/convert";
 
 export const ACTIVE_STATEMENT_SEARCH_PARAM = "q";
 export const INTERNAL_APP_NAME_PREFIX = "$ internal";
@@ -83,12 +84,10 @@ export function filterActiveStatements(
  */
 export function getActiveExecutionsFromSessions(
   sessionsResponse: SessionsResponse,
-  lastUpdated: Moment,
 ): ActiveExecutions {
   if (sessionsResponse.sessions == null)
     return { statements: [], transactions: [] };
 
-  const time = lastUpdated || moment.utc();
   const statements: ActiveStatement[] = [];
   const transactions: ActiveTransaction[] = [];
 
@@ -117,7 +116,7 @@ export function getActiveExecutionsFromSessions(
               ? "Executing"
               : "Preparing",
           start: TimestampToMoment(query.start),
-          elapsedTimeMillis: time.diff(TimestampToMoment(query.start), "ms"),
+          elapsedTime: DurationToMomentDuration(query.elapsed_time),
           application: session.application_name,
           user: session.username,
           clientAddress: session.client_address,
@@ -141,7 +140,7 @@ export function getActiveExecutionsFromSessions(
         statementID: activeStmt?.statementID,
         status: "Executing" as ExecutionStatus,
         start: TimestampToMoment(activeTxn.start),
-        elapsedTimeMillis: time.diff(TimestampToMoment(activeTxn.start), "ms"),
+        elapsedTime: DurationToMomentDuration(activeTxn.elapsed_time),
         application: session.application_name,
         retries: activeTxn.num_auto_retries,
         statementCount: activeTxn.num_statements_executed,

pkg/ui/workspaces/cluster-ui/src/activeExecutions/execTableCommon.tsx

@@ -187,14 +187,15 @@ function makeActiveExecutionColumns(
     elapsedTime: {
       name: "elapsedTime",
       title: executionsTableTitles.elapsedTime(execType),
-      cell: (item: ActiveExecution) => Duration(item.elapsedTimeMillis * 1e6),
-      sort: (item: ActiveExecution) => item.elapsedTimeMillis,
+      cell: (item: ActiveExecution) =>
+        Duration(item.elapsedTime.asMilliseconds() * 1e6),
+      sort: (item: ActiveExecution) => item.elapsedTime.asMilliseconds(),
     },
     timeSpentWaiting: {
       name: "timeSpentWaiting",
       title: executionsTableTitles.timeSpentWaiting(execType),
       cell: (item: ActiveExecution) =>
-        Duration(item.timeSpentWaiting?.asMilliseconds() ?? 0 * 1e6),
+        Duration((item.timeSpentWaiting?.asMilliseconds() ?? 0) * 1e6),
       sort: (item: ActiveExecution) =>
         item.timeSpentWaiting?.asMilliseconds() || 0,
     },

pkg/ui/workspaces/cluster-ui/src/activeExecutions/types.ts

@@ -30,7 +30,7 @@ export interface ActiveExecution {
   sessionID: string;
   status: ExecutionStatus;
   start: Moment;
-  elapsedTimeMillis: number;
+  elapsedTime: moment.Duration;
   application: string;
   query?: string; // For transactions, this is the latest query executed.
   timeSpentWaiting?: moment.Duration;

pkg/ui/workspaces/cluster-ui/src/selectors/activeExecutions.selectors.ts

@@ -27,16 +27,12 @@ import {
 
 const selectSessions = (state: AppState) => state.adminUI.sessions?.data;
 
-const selectSessionsLastUpdated = (state: AppState) =>
-  state.adminUI.sessions?.lastUpdated;
-
 const selectClusterLocks = (state: AppState) =>
   state.adminUI.clusterLocks?.data;
 
 export const selectActiveExecutions = createSelector(
   selectSessions,
   selectClusterLocks,
-  selectSessionsLastUpdated,
   selectActiveExecutionsCombiner,
 );
 

pkg/ui/workspaces/cluster-ui/src/selectors/activeExecutionsCommon.selectors.ts

@@ -29,12 +29,11 @@ export const selectExecutionID = (
 export const selectActiveExecutionsCombiner = (
   sessions: SessionsResponse | null,
   clusterLocks: ClusterLocksResponse | null,
-  lastUpdated: moment.Moment,
 ): ActiveExecutions => {
   if (!sessions) return { statements: [], transactions: [] };
 
   const waitTimeByTxnID = getWaitTimeByTxnIDFromLocks(clusterLocks);
-  const execs = getActiveExecutionsFromSessions(sessions, lastUpdated);
+  const execs = getActiveExecutionsFromSessions(sessions);
 
   return {
     statements: execs.statements.map(s => ({

pkg/ui/workspaces/cluster-ui/src/statementDetails/activeStatementDetails.tsx

@@ -108,7 +108,9 @@ export const ActiveStatementDetails: React.FC<ActiveStatementDetailsProps> = ({
                     />
                     <SummaryCardItem
                       label="Elapsed Time"
-                      value={Duration(statement.elapsedTimeMillis * 1e6)}
+                      value={Duration(
+                        statement.elapsedTime.asMilliseconds() * 1e6,
+                      )}
                     />
                     <SummaryCardItem
                       label="Status"

pkg/ui/workspaces/cluster-ui/src/transactionDetails/activeTransactionDetails.tsx

@@ -127,7 +127,9 @@ export const ActiveTransactionDetails: React.FC<
                     />
                     <SummaryCardItem
                       label={ActiveTxnInsightsLabels.ELAPSED_TIME}
-                      value={Duration(transaction.elapsedTimeMillis * 1e6)}
+                      value={Duration(
+                        transaction.elapsedTime.asMilliseconds() * 1e6,
+                      )}
                     />
                     <SummaryCardItem
                       label={ActiveTxnInsightsLabels.STATUS}

pkg/ui/workspaces/db-console/src/selectors/activeExecutionsSelectors.ts

@@ -23,16 +23,12 @@ import { SessionsResponseMessage } from "src/util/api";
 
 const selectSessions = (state: AdminUIState) => state.cachedData.sessions?.data;
 
-const selectSessionsLastUpdated = (state: AdminUIState) =>
-  state.cachedData.sessions?.setAt;
-
 const selectClusterLocks = (state: AdminUIState) =>
   state.cachedData.clusterLocks?.data;
 
 export const selectActiveExecutions = createSelector(
   selectSessions,
   selectClusterLocks,
-  selectSessionsLastUpdated,
   selectActiveExecutionsCombiner,
 );