feat(editor): split a query's duration into server, first row and transfer

CHANGELOG.md

@@ -9,11 +9,13 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ### Added
 
+- Breakdown of a query's time into server, first row and transfer, behind the toolbar's duration readout. (#2503)
 - Exclude the AUTO_INCREMENT counter and Exclude DEFINER clauses in the SQL export, both on by default. (#2516)
 
 ### Changed
 
 - PluginKit ABI 21. Every registry plugin needs rebuilding before or with this release.
+- Query Insights ranks on the time the database spent rather than on elapsed time. (#2503)
 - Export summary reports the warnings an export produced, instead of a bare "Export completed". (#2517)
 
 ### Fixed

Plugins/BigQueryDriverPlugin/BigQueryConnection.swift

@@ -162,6 +162,20 @@ internal struct BQJobResponse: Codable, Sendable {
     struct BQJobStatistics: Codable, Sendable {
         let totalBytesProcessed: String?
         let query: BQQueryStatistics?
+        /// Milliseconds since the epoch, as strings. The gap between them is the time the job ran
+        /// on BigQuery, with nothing from the client's own network in it.
+        let startTime: String?
+        let endTime: String?
+
+        var elapsed: TimeInterval? {
+            guard let start = startTime.flatMap(Double.init),
+                  let end = endTime.flatMap(Double.init),
+                  end >= start
+            else {
+                return nil
+            }
+            return (end - start) / 1_000
+        }
     }
 
     struct BQQueryStatistics: Codable, Sendable {
@@ -239,6 +253,10 @@ internal enum BQCellValue: Codable, Sendable {
 internal struct BQJobInfo: Sendable {
     let jobId: String
     let location: String?
+
+    /// How long BigQuery ran the job, from its own statistics. Nil when the response omitted the
+    /// start or end stamp.
+    var serverElapsed: TimeInterval?
 }
 
 internal struct BQExecuteResult: Sendable {
@@ -247,19 +265,22 @@ internal struct BQExecuteResult: Sendable {
     let totalBytesProcessed: String?
     let totalBytesBilled: String?
     let cacheHit: Bool?
+    let serverElapsed: TimeInterval?
 
     init(
         queryResponse: BQQueryResponse,
         dmlAffectedRows: Int,
         totalBytesProcessed: String?,
         totalBytesBilled: String? = nil,
-        cacheHit: Bool? = nil
+        cacheHit: Bool? = nil,
+        serverElapsed: TimeInterval? = nil
     ) {
         self.queryResponse = queryResponse
         self.dmlAffectedRows = dmlAffectedRows
         self.totalBytesProcessed = totalBytesProcessed
         self.totalBytesBilled = totalBytesBilled
         self.cacheHit = cacheHit
+        self.serverElapsed = serverElapsed
     }
 }
 
@@ -491,7 +512,8 @@ internal final class BigQueryConnection: @unchecked Sendable {
             dmlAffectedRows: dmlAffectedRows,
             totalBytesProcessed: totalBytesProcessed,
             totalBytesBilled: totalBytesBilled,
-            cacheHit: cacheHit
+            cacheHit: cacheHit,
+            serverElapsed: finalJobResponse.statistics?.elapsed
         )
     }
 
@@ -566,6 +588,7 @@ internal final class BigQueryConnection: @unchecked Sendable {
             _currentJobLocation = jobRef.location
         }
 
+        var completedJob = jobResponse
         if let state = jobResponse.status?.state, state != "DONE" {
             let finalJob = try await pollJobCompletion(
                 jobId: jobId, location: jobRef.location, auth: auth, session: session
@@ -574,12 +597,17 @@ internal final class BigQueryConnection: @unchecked Sendable {
                 let reason = errorResult.reason.map { " [\($0)]" } ?? ""
                 throw BigQueryError.jobFailed("\(errorResult.message ?? "Unknown job error")\(reason)")
             }
+            completedJob = finalJob
         } else if let errorResult = jobResponse.status?.errorResult {
             let reason = errorResult.reason.map { " [\($0)]" } ?? ""
             throw BigQueryError.jobFailed("\(errorResult.message ?? "Unknown job error")\(reason)")
         }
 
-        return BQJobInfo(jobId: jobId, location: jobRef.location)
+        return BQJobInfo(
+            jobId: jobId,
+            location: jobRef.location,
+            serverElapsed: completedJob.statistics?.elapsed
+        )
     }
 
     // MARK: - Dry Run

Plugins/BigQueryDriverPlugin/BigQueryPluginDriver.swift

@@ -27,6 +27,10 @@ internal final class BigQueryPluginDriver: PluginDatabaseDriver, @unchecked Send
     private var _columnTypeCache: [String: [String]] = [:]
     private var _queryTimeoutSeconds: Int = 300
 
+    /// How long BigQuery ran the job behind the last streamed read. The stream carries rows and a
+    /// header and nothing else, so the figure is handed over here rather than through it.
+    private var _lastJobElapsed: TimeInterval?
+
     var connection: BigQueryConnection? {
         lock.withLock { _connection }
     }
@@ -233,7 +237,10 @@ internal final class BigQueryPluginDriver: PluginDatabaseDriver, @unchecked Send
                 columnTypeNames: ["STRING"],
                 rows: [[.text("Statement executed")]],
                 rowsAffected: result.dmlAffectedRows,
-                executionTime: Date().timeIntervalSince(startTime),
+                timing: PluginQueryTiming(
+                    total: Date().timeIntervalSince(startTime),
+                    server: result.serverElapsed
+                ),
                 statusMessage: buildCostMessage(result)
             )
         }
@@ -247,7 +254,10 @@ internal final class BigQueryPluginDriver: PluginDatabaseDriver, @unchecked Send
             columnTypeNames: typeNames,
             rows: rows,
             rowsAffected: 0,
-            executionTime: Date().timeIntervalSince(startTime),
+            timing: PluginQueryTiming(
+                total: Date().timeIntervalSince(startTime),
+                server: result.serverElapsed
+            ),
             statusMessage: buildCostMessage(result)
         )
     }
@@ -651,8 +661,34 @@ internal final class BigQueryPluginDriver: PluginDatabaseDriver, @unchecked Send
 
     // MARK: - Streaming
 
+    /// Not `boundedQueryFromStream`: the default drops the job statistics, and BigQuery's own
+    /// execution time is the whole point of the breakdown on a warehouse this far away.
+    ///
+    /// The figure is read after the stream finishes, never as a call argument: an argument is
+    /// evaluated before the await, which would report the previous query's job.
     func executeBoundedQuery(query: String, rowCap: Int) async throws -> PluginQueryResult? {
-        try await boundedQueryFromStream(query: query, rowCap: rowCap)
+        let started = Date()
+        lock.withLock { _lastJobElapsed = nil }
+        let collected = try await PluginBoundedStream.collect(
+            streamRows(query: query),
+            rowCap: rowCap,
+            startedAt: started
+        )
+        guard let serverElapsed = lock.withLock({ _lastJobElapsed }) else { return collected }
+        return PluginQueryResult(
+            columns: collected.columns,
+            columnTypeNames: collected.columnTypeNames,
+            rows: collected.rows,
+            rowsAffected: collected.rowsAffected,
+            timing: PluginQueryTiming(
+                total: collected.timing.total,
+                firstRow: collected.timing.firstRow,
+                server: serverElapsed
+            ),
+            isTruncated: collected.isTruncated,
+            statusMessage: collected.statusMessage,
+            columnMeta: collected.columnMeta
+        )
     }
 
     func streamRows(query: String) -> AsyncThrowingStream<PluginStreamElement, Error> {
@@ -704,6 +740,7 @@ internal final class BigQueryPluginDriver: PluginDatabaseDriver, @unchecked Send
         }
 
         let jobInfo = try await conn.executeJobAndWait(sql, defaultDataset: dataset)
+        lock.withLock { _lastJobElapsed = jobInfo.serverElapsed }
         defer { conn.clearCurrentJob() }
 
         let firstPage = try await conn.getQueryResults(
@@ -917,7 +954,10 @@ internal final class BigQueryPluginDriver: PluginDatabaseDriver, @unchecked Send
             columnTypeNames: typeNames,
             rows: rows,
             rowsAffected: 0,
-            executionTime: Date().timeIntervalSince(startTime),
+            timing: PluginQueryTiming(
+                total: Date().timeIntervalSince(startTime),
+                server: result.serverElapsed
+            ),
             statusMessage: buildCostMessage(result)
         )
     }

Plugins/ClickHouseDriverPlugin/ClickHousePlugin.swift

@@ -138,6 +138,10 @@ struct CHQueryResult {
     let rows: [[PluginCellValue]]
     let affectedRows: Int
     let isTruncated: Bool
+
+    /// Execution time as the server reported it in `X-ClickHouse-Summary`, so the figure carries no
+    /// network round trip. Nil on a server too old to send it.
+    var serverElapsed: TimeInterval?
 }
 
 // MARK: - Plugin Driver
@@ -265,7 +269,7 @@ final class ClickHousePluginDriver: PluginDatabaseDriver, @unchecked Sendable {
             columnTypeNames: result.columnTypeNames,
             rows: result.rows,
             rowsAffected: result.affectedRows,
-            executionTime: executionTime,
+            timing: PluginQueryTiming(total: executionTime, server: result.serverElapsed),
             isTruncated: result.isTruncated
         )
     }
@@ -286,7 +290,7 @@ final class ClickHousePluginDriver: PluginDatabaseDriver, @unchecked Sendable {
             columnTypeNames: result.columnTypeNames,
             rows: result.rows,
             rowsAffected: result.affectedRows,
-            executionTime: executionTime,
+            timing: PluginQueryTiming(total: executionTime, server: result.serverElapsed),
             isTruncated: result.isTruncated
         )
     }

Plugins/ClickHouseDriverPlugin/ClickHousePluginDriver+Http.swift

@@ -53,16 +53,18 @@ extension ClickHousePluginDriver {
             throw ClickHouseError(message: body.trimmingCharacters(in: .whitespacesAndNewlines))
         }
 
+        let headers = Self.headerFields(httpResponse)
         let outcome = ClickHouseResponseClassifier.classify(
-            headers: Self.headerFields(httpResponse),
+            headers: headers,
             body: data
         )
         return CHQueryResult(
             columns: outcome.columns,
             columnTypeNames: outcome.columnTypeNames,
             rows: outcome.rows,
             affectedRows: outcome.affectedRows,
-            isTruncated: outcome.isTruncated
+            isTruncated: outcome.isTruncated,
+            serverElapsed: ClickHouseSummaryParser.parse(headers: headers)?.elapsed
         )
     }
 

Plugins/MySQLDriverPlugin/MariaDBPluginConnection.swift

@@ -58,6 +58,10 @@ struct MariaDBPluginQueryResult {
     let insertId: UInt64
     let isTruncated: Bool
     let columnMeta: [PluginColumnInfo]
+
+    /// Send to first row, measured from just before the statement goes out. Separates the server's
+    /// own work from the time spent pulling the rest of the result across the wire.
+    var firstRowTime: TimeInterval?
 }
 
 // MARK: - SSL Configuration
@@ -611,6 +615,10 @@ final class MariaDBPluginConnection: @unchecked Sendable {
         let generation = cancellationGate.beginQuery()
         defer { cancellationGate.endQuery(generation) }
 
+        /// Started before the `SQL_SELECT_LIMIT` reconciliation rather than after it. That
+        /// reconciliation is a round trip of its own, and leaving it outside this clock charges it
+        /// to `total - firstRow`, which the breakdown presents as row transfer.
+        let sentAt = Date()
         try reconcileSelectLimit(rowCap: rowCap, statement: query, on: mysql)
         if cancellationGate.isCancelled(generation) { throw CancellationError() }
 
@@ -632,7 +640,8 @@ final class MariaDBPluginConnection: @unchecked Sendable {
                 return MariaDBPluginQueryResult(
                     columns: [], columnTypes: [], columnTypeNames: [],
                     rows: [], affectedRows: affected, insertId: insertId, isTruncated: false,
-                    columnMeta: []
+                    columnMeta: [],
+                    firstRowTime: Date().timeIntervalSince(sentAt)
                 )
             } else {
                 throw self.getError()
@@ -679,8 +688,10 @@ final class MariaDBPluginConnection: @unchecked Sendable {
         let maxRows = mysqlClampedRowCap(rowCap) ?? PluginRowLimits.emergencyMax
         let fetchLimit = maxRows == PluginRowLimits.emergencyMax ? maxRows : maxRows + 1
         var serverSentMore = false
+        var firstRowTime: TimeInterval?
 
         while let rowPtr = mysql_fetch_row(resultPtr) {
+            if firstRowTime == nil { firstRowTime = Date().timeIntervalSince(sentAt) }
             if cancellationGate.isCancelled(generation) {
                 while mysql_fetch_row(resultPtr) != nil {}
                 mysql_free_result(resultPtr)
@@ -752,7 +763,8 @@ final class MariaDBPluginConnection: @unchecked Sendable {
         return MariaDBPluginQueryResult(
             columns: columns, columnTypes: columnTypes, columnTypeNames: columnTypeNames,
             rows: rows, affectedRows: UInt64(rows.count), insertId: 0, isTruncated: truncated,
-            columnMeta: columnMeta
+            columnMeta: columnMeta,
+            firstRowTime: firstRowTime ?? Date().timeIntervalSince(sentAt)
         )
     }
 
@@ -840,8 +852,9 @@ final class MariaDBPluginConnection: @unchecked Sendable {
         columnTypeNames: [String],
         columnIsBinary: [Bool],
         rowCap: Int? = nil,
-        generation: Int
-    ) throws -> (rows: [[PluginCellValue]], isTruncated: Bool) {
+        generation: Int,
+        sentAt: Date
+    ) throws -> (rows: [[PluginCellValue]], isTruncated: Bool, firstRowTime: TimeInterval) {
         let numFields = columns.count
         var resultBinds: [MYSQL_BIND] = Array(repeating: MYSQL_BIND(), count: numFields)
         var resultBuffers: [UnsafeMutableRawPointer] = []
@@ -878,13 +891,18 @@ final class MariaDBPluginConnection: @unchecked Sendable {
         let maxRows = mysqlClampedRowCap(rowCap) ?? PluginRowLimits.emergencyMax
         let fetchLimit = maxRows == PluginRowLimits.emergencyMax ? maxRows : maxRows + 1
         var serverSentMore = false
+        /// `mysql_stmt_execute` returns once the server has answered with a header, which on an
+        /// unbuffered statement can be long before the first tuple exists. Only a fetch that
+        /// returns a row proves the server produced one.
+        var firstRowTime: TimeInterval?
 
         while true {
             let fetchStatus = mysql_stmt_fetch(stmt)
             if fetchStatus == MYSQL_NO_DATA { break }
             if fetchStatus != 0, fetchStatus != MYSQL_DATA_TRUNCATED {
                 throw getStmtError(stmt)
             }
+            if firstRowTime == nil { firstRowTime = Date().timeIntervalSince(sentAt) }
 
             if cancellationGate.isCancelled(generation) {
                 throw CancellationError()
@@ -946,7 +964,11 @@ final class MariaDBPluginConnection: @unchecked Sendable {
             rows.removeLast(rows.count - outcome.keptRows)
         }
 
-        return (rows: rows, isTruncated: outcome.isTruncated)
+        return (
+            rows: rows,
+            isTruncated: outcome.isTruncated,
+            firstRowTime: firstRowTime ?? Date().timeIntervalSince(sentAt)
+        )
     }
 
     private func executeParameterizedQuerySync(
@@ -961,6 +983,8 @@ final class MariaDBPluginConnection: @unchecked Sendable {
         let generation = cancellationGate.beginQuery()
         defer { cancellationGate.endQuery(generation) }
 
+        /// Ahead of both the reconciliation and the prepare, for the reason the text path gives.
+        let sentAt = Date()
         try reconcileSelectLimit(rowCap: rowCap, statement: query, on: mysql)
         if cancellationGate.isCancelled(generation) { throw CancellationError() }
 
@@ -1001,6 +1025,7 @@ final class MariaDBPluginConnection: @unchecked Sendable {
                 throw getStmtError(stmt)
             }
         }
+        let executedAt = Date().timeIntervalSince(sentAt)
 
         let fieldCount = Int(mysql_stmt_field_count(stmt))
 
@@ -1010,7 +1035,8 @@ final class MariaDBPluginConnection: @unchecked Sendable {
             return MariaDBPluginQueryResult(
                 columns: [], columnTypes: [], columnTypeNames: [],
                 rows: [], affectedRows: UInt64(affected), insertId: UInt64(insertId), isTruncated: false,
-                columnMeta: []
+                columnMeta: [],
+                firstRowTime: executedAt
             )
         }
 
@@ -1054,14 +1080,15 @@ final class MariaDBPluginConnection: @unchecked Sendable {
         let fetchResult = try fetchResultSet(
             from: stmt, metadata: metadata,
             columns: columns, columnTypes: columnTypes, columnTypeNames: columnTypeNames,
-            columnIsBinary: columnIsBinary, rowCap: rowCap, generation: generation
+            columnIsBinary: columnIsBinary, rowCap: rowCap, generation: generation, sentAt: sentAt
         )
 
         return MariaDBPluginQueryResult(
             columns: columns, columnTypes: columnTypes, columnTypeNames: columnTypeNames,
             rows: fetchResult.rows, affectedRows: UInt64(fetchResult.rows.count),
             insertId: 0, isTruncated: fetchResult.isTruncated,
-            columnMeta: columnMeta
+            columnMeta: columnMeta,
+            firstRowTime: fetchResult.firstRowTime
         )
     }