diff --git a/CHANGELOG.md b/CHANGELOG.md index 04780c899..0b8577acb 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/Plugins/BigQueryDriverPlugin/BigQueryConnection.swift b/Plugins/BigQueryDriverPlugin/BigQueryConnection.swift index 34545cb56..1fc0700d9 100644 --- a/Plugins/BigQueryDriverPlugin/BigQueryConnection.swift +++ b/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 diff --git a/Plugins/BigQueryDriverPlugin/BigQueryPluginDriver.swift b/Plugins/BigQueryDriverPlugin/BigQueryPluginDriver.swift index 3f9105ab4..26a42e887 100644 --- a/Plugins/BigQueryDriverPlugin/BigQueryPluginDriver.swift +++ b/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 { @@ -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) ) } diff --git a/Plugins/ClickHouseDriverPlugin/ClickHousePlugin.swift b/Plugins/ClickHouseDriverPlugin/ClickHousePlugin.swift index c26f9a1d2..baba9448e 100644 --- a/Plugins/ClickHouseDriverPlugin/ClickHousePlugin.swift +++ b/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 ) } diff --git a/Plugins/ClickHouseDriverPlugin/ClickHousePluginDriver+Http.swift b/Plugins/ClickHouseDriverPlugin/ClickHousePluginDriver+Http.swift index 1ec6b5a3d..c14d0f002 100644 --- a/Plugins/ClickHouseDriverPlugin/ClickHousePluginDriver+Http.swift +++ b/Plugins/ClickHouseDriverPlugin/ClickHousePluginDriver+Http.swift @@ -53,8 +53,9 @@ 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( @@ -62,7 +63,8 @@ extension ClickHousePluginDriver { columnTypeNames: outcome.columnTypeNames, rows: outcome.rows, affectedRows: outcome.affectedRows, - isTruncated: outcome.isTruncated + isTruncated: outcome.isTruncated, + serverElapsed: ClickHouseSummaryParser.parse(headers: headers)?.elapsed ) } diff --git a/Plugins/MySQLDriverPlugin/MariaDBPluginConnection.swift b/Plugins/MySQLDriverPlugin/MariaDBPluginConnection.swift index 7a9bc1e7e..6a88f587b 100644 --- a/Plugins/MySQLDriverPlugin/MariaDBPluginConnection.swift +++ b/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,6 +891,10 @@ 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) @@ -885,6 +902,7 @@ final class MariaDBPluginConnection: @unchecked Sendable { 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 ) } diff --git a/Plugins/MySQLDriverPlugin/MySQLPluginDriver.swift b/Plugins/MySQLDriverPlugin/MySQLPluginDriver.swift index 0c80c3a14..e82ad268c 100644 --- a/Plugins/MySQLDriverPlugin/MySQLPluginDriver.swift +++ b/Plugins/MySQLDriverPlugin/MySQLPluginDriver.swift @@ -129,7 +129,10 @@ final class MySQLPluginDriver: PluginDatabaseDriver, @unchecked Sendable { columnTypeNames: result.columnTypeNames, rows: result.rows, rowsAffected: Int(result.affectedRows), - executionTime: Date().timeIntervalSince(startTime), + timing: PluginQueryTiming( + total: Date().timeIntervalSince(startTime), + firstRow: result.firstRowTime + ), isTruncated: result.isTruncated, columnMeta: result.columnMeta ) @@ -154,7 +157,10 @@ final class MySQLPluginDriver: PluginDatabaseDriver, @unchecked Sendable { columnTypeNames: result.columnTypeNames, rows: result.rows, rowsAffected: Int(result.affectedRows), - executionTime: Date().timeIntervalSince(startTime), + timing: PluginQueryTiming( + total: Date().timeIntervalSince(startTime), + firstRow: result.firstRowTime + ), isTruncated: result.isTruncated, columnMeta: result.columnMeta ) @@ -184,7 +190,10 @@ final class MySQLPluginDriver: PluginDatabaseDriver, @unchecked Sendable { columnTypeNames: Array(repeating: "TEXT", count: columns.count), rows: [], rowsAffected: Int(result.affectedRows), - executionTime: Date().timeIntervalSince(startTime), + timing: PluginQueryTiming( + total: Date().timeIntervalSince(startTime), + firstRow: result.firstRowTime + ), isTruncated: result.isTruncated ) } @@ -195,7 +204,10 @@ final class MySQLPluginDriver: PluginDatabaseDriver, @unchecked Sendable { columnTypeNames: result.columnTypeNames, rows: result.rows, rowsAffected: Int(result.affectedRows), - executionTime: Date().timeIntervalSince(startTime), + timing: PluginQueryTiming( + total: Date().timeIntervalSince(startTime), + firstRow: result.firstRowTime + ), isTruncated: result.isTruncated, columnMeta: result.columnMeta ) diff --git a/Plugins/PostgreSQLDriverPlugin/LibPQDriverCore.swift b/Plugins/PostgreSQLDriverPlugin/LibPQDriverCore.swift index cbb9bcbdf..c3044a15e 100644 --- a/Plugins/PostgreSQLDriverPlugin/LibPQDriverCore.swift +++ b/Plugins/PostgreSQLDriverPlugin/LibPQDriverCore.swift @@ -150,7 +150,10 @@ final class LibPQDriverCore: @unchecked Sendable { columnTypeNames: result.columnTypeNames, rows: result.rows, rowsAffected: result.affectedRows, - executionTime: Date().timeIntervalSince(startTime), + timing: PluginQueryTiming( + total: Date().timeIntervalSince(startTime), + firstRow: result.firstRowTime + ), isTruncated: result.isTruncated ) } catch let error as NSError where !isRetry && Self.isConnectionLostError(error) { diff --git a/Plugins/PostgreSQLDriverPlugin/LibPQPluginConnection.swift b/Plugins/PostgreSQLDriverPlugin/LibPQPluginConnection.swift index 635c7bb3f..24b9bbb9a 100644 --- a/Plugins/PostgreSQLDriverPlugin/LibPQPluginConnection.swift +++ b/Plugins/PostgreSQLDriverPlugin/LibPQPluginConnection.swift @@ -39,6 +39,10 @@ struct LibPQPluginQueryResult { let affectedRows: Int let commandTag: String? let isTruncated: Bool + + /// Send to first row, when the read went through single-row mode and could see one. The + /// buffered `PQexec` path has no such boundary and leaves it nil. + var firstRowTime: TimeInterval? } // MARK: - Type Mapping @@ -546,6 +550,9 @@ final class LibPQPluginConnection: @unchecked Sendable { let generation = cancellationGate.beginQuery() defer { cancellationGate.endQuery(generation) } + /// Started before the drain, so a result the previous statement abandoned is charged to the + /// time before the first row rather than appearing as this query's row transfer. + let sentAt = Date() while let stale = PQgetResult(conn) { PQclear(stale) } /// Cancelling a statement inside a transaction block puts the transaction into the aborted @@ -573,9 +580,11 @@ final class LibPQPluginConnection: @unchecked Sendable { var commandTag: String? var truncated = false var pendingError: Error? + var firstRowTime: TimeInterval? while let result = PQgetResult(conn) { let status = PQresultStatus(result) + if firstRowTime == nil { firstRowTime = Date().timeIntervalSince(sentAt) } if status == PGRES_SINGLE_TUPLE { let columns = metadata ?? readColumnMetadata(from: result) @@ -644,7 +653,8 @@ final class LibPQPluginConnection: @unchecked Sendable { rows: rows, affectedRows: affectedRows, commandTag: commandTag, - isTruncated: truncated + isTruncated: truncated, + firstRowTime: firstRowTime ?? Date().timeIntervalSince(sentAt) ) return applySpatialRendering(to: bounded) } @@ -1009,7 +1019,8 @@ final class LibPQPluginConnection: @unchecked Sendable { rows: rows, affectedRows: result.affectedRows, commandTag: result.commandTag, - isTruncated: result.isTruncated + isTruncated: result.isTruncated, + firstRowTime: result.firstRowTime ) } diff --git a/Plugins/TableProPluginKit/ClickHouseSummaryParser.swift b/Plugins/TableProPluginKit/ClickHouseSummaryParser.swift new file mode 100644 index 000000000..5add2c61d --- /dev/null +++ b/Plugins/TableProPluginKit/ClickHouseSummaryParser.swift @@ -0,0 +1,61 @@ +import Foundation + +/// Reads the execution figures ClickHouse sends back in `X-ClickHouse-Summary`. +/// +/// The header is a JSON object whose numbers are quoted strings, and its member set has grown over +/// releases: `elapsed_ns` only appears on servers new enough to send it. Every field is therefore +/// optional, and a header that cannot be read at all yields nothing rather than a zero, because a +/// zero would read as a query that took no time. +public enum ClickHouseSummaryParser { + public struct Summary: Sendable, Equatable { + public let elapsed: TimeInterval? + public let readRows: UInt64? + public let readBytes: UInt64? + + public init(elapsed: TimeInterval?, readRows: UInt64?, readBytes: UInt64?) { + self.elapsed = elapsed + self.readRows = readRows + self.readBytes = readBytes + } + } + + public static let headerName = "X-ClickHouse-Summary" + + public static func parse(headers: [String: String]) -> Summary? { + guard let raw = value(forHeader: headerName, in: headers) else { return nil } + return parse(headerValue: raw) + } + + public static func parse(headerValue: String) -> Summary? { + guard let data = headerValue.data(using: .utf8), + let object = try? JSONSerialization.jsonObject(with: data) as? [String: Any] + else { + return nil + } + + let elapsedNanoseconds = unsignedValue(object["elapsed_ns"]) + let summary = Summary( + elapsed: elapsedNanoseconds.map { TimeInterval($0) / 1_000_000_000 }, + readRows: unsignedValue(object["read_rows"]), + readBytes: unsignedValue(object["read_bytes"]) + ) + guard summary.elapsed != nil || summary.readRows != nil || summary.readBytes != nil else { + return nil + } + return summary + } + + /// HTTP header names are case-insensitive and `HTTPURLResponse` hands them back in whatever + /// case the server used, so the lookup cannot be a plain subscript. + private static func value(forHeader name: String, in headers: [String: String]) -> String? { + if let exact = headers[name] { return exact } + let lowered = name.lowercased() + return headers.first { $0.key.lowercased() == lowered }?.value + } + + private static func unsignedValue(_ raw: Any?) -> UInt64? { + if let text = raw as? String { return UInt64(text) } + if let number = raw as? NSNumber { return UInt64(exactly: number.uint64Value) } + return nil + } +} diff --git a/Plugins/TableProPluginKit/PluginBoundedStream.swift b/Plugins/TableProPluginKit/PluginBoundedStream.swift index 251079cca..15deee830 100644 --- a/Plugins/TableProPluginKit/PluginBoundedStream.swift +++ b/Plugins/TableProPluginKit/PluginBoundedStream.swift @@ -7,10 +7,22 @@ import Foundation /// collector ever keeping the extra row. A driver that bounds its own fetch has to read one row /// past the cap to draw the same distinction. public enum PluginBoundedStream { + @_disfavoredOverload public static func collect( _ stream: AsyncThrowingStream, rowCap: Int, startedAt: Date + ) async throws -> PluginQueryResult { + try await collect(stream, rowCap: rowCap, startedAt: startedAt, serverElapsed: nil) + } + + /// `serverElapsed` is the engine's own report where its protocol carries one. Streaming + /// responses often send it as a trailer the client never sees, so it stays optional. + public static func collect( + _ stream: AsyncThrowingStream, + rowCap: Int, + startedAt: Date, + serverElapsed: TimeInterval? ) async throws -> PluginQueryResult { let cap = max(rowCap, 1) var columns: [String] = [] @@ -18,6 +30,9 @@ public enum PluginBoundedStream { var rows: [PluginRow] = [] rows.reserveCapacity(min(cap, 10_000)) var truncated = false + /// The first batch to arrive is the first row the server produced, which is the only part + /// of a streamed read that separates the query's own cost from the cost of moving its rows. + var firstRowTime: TimeInterval? for try await element in stream { switch element { @@ -25,6 +40,9 @@ public enum PluginBoundedStream { columns = header.columns columnTypeNames = header.columnTypeNames case .rows(let batch): + if firstRowTime == nil, !batch.isEmpty { + firstRowTime = Date().timeIntervalSince(startedAt) + } let remaining = cap - rows.count if batch.count > remaining { rows.append(contentsOf: batch.prefix(remaining)) @@ -41,7 +59,11 @@ public enum PluginBoundedStream { columnTypeNames: columnTypeNames, rows: rows, rowsAffected: 0, - executionTime: Date().timeIntervalSince(startedAt), + timing: PluginQueryTiming( + total: Date().timeIntervalSince(startedAt), + firstRow: firstRowTime ?? Date().timeIntervalSince(startedAt), + server: serverElapsed + ), isTruncated: truncated ) } diff --git a/Plugins/TableProPluginKit/PluginQueryResult.swift b/Plugins/TableProPluginKit/PluginQueryResult.swift index d2d69ad1a..c66013485 100644 --- a/Plugins/TableProPluginKit/PluginQueryResult.swift +++ b/Plugins/TableProPluginKit/PluginQueryResult.swift @@ -9,13 +9,14 @@ public struct PluginQueryResult: Codable, Sendable { public let isTruncated: Bool public let statusMessage: String? public let columnMeta: [PluginColumnInfo]? + public let timing: PluginQueryTiming public init( columns: [String], columnTypeNames: [String], rows: [[PluginCellValue]], rowsAffected: Int, - executionTime: TimeInterval, + timing: PluginQueryTiming, isTruncated: Bool = false, statusMessage: String? = nil, columnMeta: [PluginColumnInfo]? = nil @@ -24,10 +25,37 @@ public struct PluginQueryResult: Codable, Sendable { self.columnTypeNames = columnTypeNames self.rows = rows self.rowsAffected = rowsAffected - self.executionTime = executionTime + self.executionTime = timing.total self.isTruncated = isTruncated self.statusMessage = statusMessage self.columnMeta = columnMeta + self.timing = timing + } + + /// Kept at its exact published signature. Adding `timing:` to it would replace its mangled + /// symbol and every already-built plugin would fail to load, which is what shipping a defaulted + /// `columnMeta:` parameter on this initializer did in 0.49.0. + @_disfavoredOverload + public init( + columns: [String], + columnTypeNames: [String], + rows: [[PluginCellValue]], + rowsAffected: Int, + executionTime: TimeInterval, + isTruncated: Bool = false, + statusMessage: String? = nil, + columnMeta: [PluginColumnInfo]? = nil + ) { + self.init( + columns: columns, + columnTypeNames: columnTypeNames, + rows: rows, + rowsAffected: rowsAffected, + timing: PluginQueryTiming(total: executionTime), + isTruncated: isTruncated, + statusMessage: statusMessage, + columnMeta: columnMeta + ) } @_disfavoredOverload @@ -45,18 +73,34 @@ public struct PluginQueryResult: Codable, Sendable { columnTypeNames: columnTypeNames, rows: rows, rowsAffected: rowsAffected, - executionTime: executionTime, + timing: PluginQueryTiming(total: executionTime), isTruncated: isTruncated, statusMessage: statusMessage, columnMeta: nil ) } + /// A result decoded from a release that predates the split carries only the elapsed number, so + /// the timing is rebuilt from it rather than failing to decode. + public init(from decoder: any Decoder) throws { + let container = try decoder.container(keyedBy: CodingKeys.self) + columns = try container.decode([String].self, forKey: .columns) + columnTypeNames = try container.decode([String].self, forKey: .columnTypeNames) + rows = try container.decode([[PluginCellValue]].self, forKey: .rows) + rowsAffected = try container.decode(Int.self, forKey: .rowsAffected) + executionTime = try container.decode(TimeInterval.self, forKey: .executionTime) + isTruncated = try container.decode(Bool.self, forKey: .isTruncated) + statusMessage = try container.decodeIfPresent(String.self, forKey: .statusMessage) + columnMeta = try container.decodeIfPresent([PluginColumnInfo].self, forKey: .columnMeta) + timing = try container.decodeIfPresent(PluginQueryTiming.self, forKey: .timing) + ?? PluginQueryTiming(total: executionTime) + } + public static let empty = PluginQueryResult( columns: [], columnTypeNames: [], rows: [], rowsAffected: 0, - executionTime: 0 + timing: PluginQueryTiming(total: 0) ) } diff --git a/Plugins/TableProPluginKit/PluginQueryTiming.swift b/Plugins/TableProPluginKit/PluginQueryTiming.swift new file mode 100644 index 000000000..d6a048c18 --- /dev/null +++ b/Plugins/TableProPluginKit/PluginQueryTiming.swift @@ -0,0 +1,47 @@ +import Foundation + +/// What a query's duration was actually spent on. +/// +/// A single elapsed number cannot answer "was the query slow, or was the link slow", which is the +/// question a user asks of a remote database or a tunnelled one. `total` is that elapsed number and +/// stays what it always was. The other two are optional because most engines can only supply one of +/// them and some can supply neither, and a fabricated figure is worse than an absent one. +/// +/// `firstRow` is client-measured and therefore carries one network round trip. `server` is the +/// engine's own report and carries none, so it wins wherever a protocol already sends it. +public struct PluginQueryTiming: Codable, Sendable, Hashable { + /// Send to last row decoded. + public let total: TimeInterval + + /// Send to the first row, or to the completion of a statement that returns none. Nil when the + /// driver buffers the whole result before it can see a row. + public let firstRow: TimeInterval? + + /// Execution time as the engine itself reported it. Nil when the protocol does not carry one. + public let server: TimeInterval? + + public init(total: TimeInterval, firstRow: TimeInterval? = nil, server: TimeInterval? = nil) { + self.total = total + self.firstRow = firstRow + self.server = server + } + + /// The best available estimate of the time the database spent, as opposed to the wire. + /// + /// Falling back to `total` keeps the quantity defined for every driver, so a ranking built on it + /// never has to drop the rows that could not measure a split. + public var databaseTime: TimeInterval { + server ?? firstRow ?? total + } + + /// The part of the elapsed time spent moving rows, when the split is known. + public var transfer: TimeInterval? { + guard let firstRow else { return nil } + return max(0, total - firstRow) + } + + /// Whether there is anything to show beyond the elapsed number. + public var hasBreakdown: Bool { + firstRow != nil || server != nil + } +} diff --git a/TablePro/Core/Coordinators/PaginationCoordinator.swift b/TablePro/Core/Coordinators/PaginationCoordinator.swift index 95b22d0d3..d50bda61f 100644 --- a/TablePro/Core/Coordinators/PaginationCoordinator.swift +++ b/TablePro/Core/Coordinators/PaginationCoordinator.swift @@ -358,7 +358,7 @@ final class PaginationCoordinator { } parent.dataTabDelegate?.tableViewCoordinator?.applyDelta(replaceDelta) parent.retireQueryTask(for: nil) - parent.toolbarState.lastQueryDuration = result.executionTime + parent.toolbarState.lastQueryTiming = result.resolvedTiming let totalTime = CFAbsoluteTimeGetCurrent() - start progressLog.info("[fetchAll] DONE rows=\(result.rows.count) fetchTime=\(String(format: "%.3f", fetchTime))s totalTime=\(String(format: "%.3f", totalTime))s") diff --git a/TablePro/Core/Coordinators/QueryExecutionCoordinator+Helpers.swift b/TablePro/Core/Coordinators/QueryExecutionCoordinator+Helpers.swift index ec855807f..6ca64a612 100644 --- a/TablePro/Core/Coordinators/QueryExecutionCoordinator+Helpers.swift +++ b/TablePro/Core/Coordinators/QueryExecutionCoordinator+Helpers.swift @@ -165,7 +165,8 @@ extension QueryExecutionCoordinator { isTruncated: Bool = false, queryParameterValues: [QueryParameter]? = nil, historySQL: String? = nil, - anchor: StatementAnchor? = nil + anchor: StatementAnchor? = nil, + timing: PluginQueryTiming? = nil ) { guard let idx = parent.tabManager.tabs.firstIndex(where: { $0.id == tabId }) else { return } @@ -185,7 +186,8 @@ extension QueryExecutionCoordinator { historySQL: historySQL ?? sql, connection: conn, queryParameterValues: queryParameterValues, - anchor: anchor + anchor: anchor, + timing: timing ) return } @@ -304,7 +306,8 @@ extension QueryExecutionCoordinator { source: historySource(tabId: tabId), executionTime: executionTime, rowCount: rows.count, - wasSuccessful: true + wasSuccessful: true, + timing: timing ) ) @@ -322,7 +325,8 @@ extension QueryExecutionCoordinator { historySQL: String, connection conn: DatabaseConnection, queryParameterValues: [QueryParameter]?, - anchor: StatementAnchor? = nil + anchor: StatementAnchor? = nil, + timing: PluginQueryTiming? = nil ) { let databaseName = historyDatabaseName(tabId: tabId) let schemaName = historySchemaName(tabId: tabId) @@ -379,7 +383,8 @@ extension QueryExecutionCoordinator { executionTime: executionTime, rowCount: rowCount, wasSuccessful: true, - planCapture: captured.capture + planCapture: captured.capture, + timing: timing ) ) } @@ -761,7 +766,7 @@ extension QueryExecutionCoordinator { // itself on its own tab and leaves the window chrome to whatever is actually on screen. if parent.tabManager.selectedTabId == tabId { parent.toolbarState.isResultsCollapsed = false - parent.toolbarState.lastQueryDuration = nil + parent.toolbarState.lastQueryTiming = nil parent.announceQueryError(message) } diff --git a/TablePro/Core/Coordinators/QueryExecutionCoordinator+MultiStatement.swift b/TablePro/Core/Coordinators/QueryExecutionCoordinator+MultiStatement.swift index 5ece7e57d..9cf02bd82 100644 --- a/TablePro/Core/Coordinators/QueryExecutionCoordinator+MultiStatement.swift +++ b/TablePro/Core/Coordinators/QueryExecutionCoordinator+MultiStatement.swift @@ -101,7 +101,8 @@ extension QueryExecutionCoordinator { source: .editor, executionTime: result.executionTime, rowCount: result.rows.count, - wasSuccessful: true + wasSuccessful: true, + timing: result.resolvedTiming ) ) } @@ -109,13 +110,14 @@ extension QueryExecutionCoordinator { func applyMultiStatementResults( tabId: UUID, claim: TabExecutionClaim, - cumulativeTime: TimeInterval, + timing: PluginQueryTiming, totalRowsAffected: Int, newResultSets: [ResultSet] ) { + let cumulativeTime = timing.total guard parent.tabExecution.settle(claim) else { return } parent.retireQueryTask(for: claim) - parent.toolbarState.lastQueryDuration = cumulativeTime + parent.toolbarState.lastQueryTiming = timing /// Once for the batch, never once per statement, and below the settle gate rather than at /// the call site: a superseded batch has its results dropped here, and a notification diff --git a/TablePro/Core/Coordinators/QueryExecutionCoordinator+Parameters.swift b/TablePro/Core/Coordinators/QueryExecutionCoordinator+Parameters.swift index 1efe11160..2979a3709 100644 --- a/TablePro/Core/Coordinators/QueryExecutionCoordinator+Parameters.swift +++ b/TablePro/Core/Coordinators/QueryExecutionCoordinator+Parameters.swift @@ -116,10 +116,6 @@ extension QueryExecutionCoordinator { } let tab = parent.tabManager.tabs[index] - if PluginManager.shared.supportsQueryProgress(for: parent.connection.type) { - parent.installClickHouseProgressHandler() - } - let conn = parent.connection let tabId = parent.tabManager.tabs[index].id let claim = parent.tabExecution.claim(tabId) @@ -319,7 +315,7 @@ extension QueryExecutionCoordinator { applyMultiStatementResults( tabId: tabId, claim: claim, - cumulativeTime: results.reduce(0) { $0 + $1.executionTime }, + timing: PluginQueryTiming.batch(of: results), totalRowsAffected: results.reduce(0) { $0 + $1.rowsAffected }, newResultSets: resultSets ) @@ -339,7 +335,7 @@ extension QueryExecutionCoordinator { statements: statements, executedCount: results.count, totalCount: totalCount, - cumulativeTime: results.reduce(0) { $0 + $1.executionTime }, + timing: PluginQueryTiming.batch(of: results), failedSQL: failedSQL, resultSets: &resultSets ) @@ -509,10 +505,7 @@ extension QueryExecutionCoordinator { ]) return } - if PluginManager.shared.supportsQueryProgress(for: parent.connection.type) { - parent.clearClickHouseProgress() - } - parent.toolbarState.lastQueryDuration = fetchResult.executionTime + parent.toolbarState.lastQueryTiming = fetchResult.resolvedTiming reportOperation( kind: .query, claim: claim, @@ -541,7 +534,8 @@ extension QueryExecutionCoordinator { isTruncated: fetchResult.isTruncated, queryParameterValues: originalParameters, historySQL: originalSQL, - anchor: anchor + anchor: anchor, + timing: fetchResult.resolvedTiming ) let parameterValues = nativeParameters.map { $0 as? String } @@ -562,10 +556,11 @@ extension QueryExecutionCoordinator { statements: [SQLStatementScanner.ExecutableStatement], executedCount: Int, totalCount: Int, - cumulativeTime: TimeInterval, + timing: PluginQueryTiming, failedSQL: String?, resultSets: inout [ResultSet] ) async { + let cumulativeTime = timing.total /// A statement failure knows which statement it was: `executedCount` counts the ones that finished, so the /// next one is the one that threw. A commit failure knows no such thing. Every statement ran and the /// transaction failed on the way out, so numbering it `executedCount + 1` invented a statement past the end @@ -621,7 +616,7 @@ extension QueryExecutionCoordinator { parent.seedBufferFromActiveResult(tabId: tabId) if parent.tabManager.selectedTabId == tabId { parent.toolbarState.isResultsCollapsed = false - parent.toolbarState.lastQueryDuration = cumulativeTime + parent.toolbarState.lastQueryTiming = timing parent.announceQueryError(contextMsg) } diff --git a/TablePro/Core/Plugins/PluginDriverAdapter.swift b/TablePro/Core/Plugins/PluginDriverAdapter.swift index acb1a05d0..16415bdfc 100644 --- a/TablePro/Core/Plugins/PluginDriverAdapter.swift +++ b/TablePro/Core/Plugins/PluginDriverAdapter.swift @@ -761,6 +761,7 @@ final class PluginDriverAdapter: DatabaseDriver, SchemaSwitchable, DatabaseRepor ) result.isTruncated = pluginResult.isTruncated result.statusMessage = pluginResult.statusMessage + result.timing = pluginResult.timing result.columnMeta = pluginResult.columnMeta?.map { ResultColumnMeta(isPrimaryKey: $0.isPrimaryKey, isNullable: $0.isNullable, isAutoIncrement: $0.isIdentity) } diff --git a/TablePro/Core/Plugins/PluginManager.swift b/TablePro/Core/Plugins/PluginManager.swift index 118d9335e..8b2a4e9ad 100644 --- a/TablePro/Core/Plugins/PluginManager.swift +++ b/TablePro/Core/Plugins/PluginManager.swift @@ -14,15 +14,19 @@ import TableProPluginKit @MainActor @Observable final class PluginManager { static let shared = PluginManager() - /// Raised to 20 for the whole-schema index and table metadata requirements. + /// Raised to 21 for two additions: `tableDDLIncludesForeignKeys` on `PluginDatabaseDriver` and + /// `PluginExportDataSource`, and `PluginQueryTiming` with the `PluginQueryResult` initializer + /// that carries it. Raised to 20 before that for the whole-schema index and table metadata + /// requirements. /// - /// They carry default implementations, so an already-built v19 plugin keeps loading here. The - /// break is the other way round, and it is not what Library Evolution covers: a plugin compiled - /// against these requirements emits undefined references to their method descriptors, their - /// default-implementation symbols and their async function pointers, none of which exist in a - /// v19 host. Measured on a rebuilt CassandraDriver, which implements none of them and imports - /// all six. Left at 19, such a plugin passes `validateBundleVersions` in a shipped v19 app and - /// then fails `Bundle.loadAndReturnError`; at 20 that app refuses it and says to update. + /// Every one of these is safe in the direction Library Evolution covers, so an already-built + /// v19 or v20 plugin keeps loading here. The break is the other way round: a plugin compiled + /// against the new API emits undefined references to symbols an older host does not have. + /// Measured on a rebuilt ClickHouseDriver, whose `nm -u` lists + /// `PluginQueryTiming.init(total:firstRow:server:)` and that type's metadata accessor, and on a + /// rebuilt CassandraDriver for the v20 requirements it implements none of. Left at 20, such a + /// plugin passes `validateBundleVersions` in a shipped v20 app and then fails + /// `Bundle.loadAndReturnError`; at 21 that app refuses it and says to update. nonisolated static let currentPluginKitVersion = 21 /// Still 19, so every plugin already published for the previous release keeps loading. diff --git a/TablePro/Core/Services/Query/QueryExecutor.swift b/TablePro/Core/Services/Query/QueryExecutor.swift index 9582db187..19ff353ec 100644 --- a/TablePro/Core/Services/Query/QueryExecutor.swift +++ b/TablePro/Core/Services/Query/QueryExecutor.swift @@ -13,6 +13,13 @@ struct QueryFetchResult { let statusMessage: String? let isTruncated: Bool let resultColumnMeta: [ResultColumnMeta]? + + /// What the elapsed time was spent on, when the driver could tell. + var timing: PluginQueryTiming? + + var resolvedTiming: PluginQueryTiming { + timing ?? PluginQueryTiming(total: executionTime) + } } struct FetchedTableSchema { @@ -124,7 +131,8 @@ final class QueryExecutor { rowsAffected: result.rowsAffected, statusMessage: result.statusMessage, isTruncated: result.isTruncated, - resultColumnMeta: result.columnMeta + resultColumnMeta: result.columnMeta, + timing: result.timing ) } @@ -149,7 +157,8 @@ final class QueryExecutor { rowsAffected: result.rowsAffected, statusMessage: result.statusMessage, isTruncated: result.isTruncated, - resultColumnMeta: result.columnMeta + resultColumnMeta: result.columnMeta, + timing: result.timing ) } @@ -172,7 +181,8 @@ final class QueryExecutor { rowsAffected: result.rowsAffected, statusMessage: result.statusMessage, isTruncated: result.isTruncated, - resultColumnMeta: result.columnMeta + resultColumnMeta: result.columnMeta, + timing: result.timing ) } diff --git a/TablePro/Core/Storage/QueryHistoryManager.swift b/TablePro/Core/Storage/QueryHistoryManager.swift index e189640d6..f287c7f0f 100644 --- a/TablePro/Core/Storage/QueryHistoryManager.swift +++ b/TablePro/Core/Storage/QueryHistoryManager.swift @@ -1,5 +1,6 @@ import Combine import Foundation +import TableProPluginKit final class QueryHistoryManager: QueryHistoryRecording, QueryHistoryReading, QueryPlanSnapshotReading, Sendable { static let shared = QueryHistoryManager() @@ -32,7 +33,9 @@ final class QueryHistoryManager: QueryHistoryRecording, QueryHistoryReading, Que executionTime: request.executionTime, rowCount: request.rowCount, wasSuccessful: request.wasSuccessful, - errorMessage: request.errorMessage + errorMessage: request.errorMessage, + firstRowTime: request.timing?.firstRow, + serverTime: request.timing?.server ) let stored = await record(entry) diff --git a/TablePro/Core/Storage/QueryHistoryStorage.swift b/TablePro/Core/Storage/QueryHistoryStorage.swift index b3197db6d..a0a2c1e91 100644 --- a/TablePro/Core/Storage/QueryHistoryStorage.swift +++ b/TablePro/Core/Storage/QueryHistoryStorage.swift @@ -1,6 +1,7 @@ import Foundation import os import SQLite3 +import TableProPluginKit actor QueryHistoryStorage { private static let logger = Logger(subsystem: "com.TablePro", category: "QueryHistoryStorage") @@ -124,7 +125,9 @@ actor QueryHistoryStorage { row_count INTEGER NOT NULL, was_successful INTEGER NOT NULL, error_message TEXT, - fingerprint_hash INTEGER NOT NULL DEFAULT 0 + fingerprint_hash INTEGER NOT NULL DEFAULT 0, + first_row_time REAL, + server_time REAL ); """ @@ -195,11 +198,24 @@ actor QueryHistoryStorage { migrateToVersion3() } migrateToVersion4() + migrateToVersion5() // Stamped only once the column it describes is actually there. Stamping regardless would // claim a schema a failed ALTER never produced, and `record`'s insert would then fail to // prepare against the old column count, silently recording nothing. if hasColumn("fingerprint_hash", inTable: "history") { - setUserVersion(4) + setUserVersion(hasColumn("server_time", inTable: "history") ? 5 : 4) + } + } + + /// Both columns are nullable and deliberately not backfilled. A row written before the split + /// existed has no honest value to put in either, and `COALESCE` down to `execution_time` reads + /// it exactly as this release's predecessor did. + private func migrateToVersion5() { + if hasColumn("first_row_time", inTable: "history") == false { + execute("ALTER TABLE history ADD COLUMN first_row_time REAL;") + } + if hasColumn("server_time", inTable: "history") == false { + execute("ALTER TABLE history ADD COLUMN server_time REAL;") } } @@ -448,8 +464,8 @@ actor QueryHistoryStorage { INSERT INTO history ( id, query, connection_id, database_name, database_type, schema_name, source, statement_type, executed_at, execution_time, row_count, - was_successful, error_message, fingerprint_hash - ) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); + was_successful, error_message, fingerprint_hash, first_row_time, server_time + ) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?); """ var statement: OpaquePointer? @@ -482,6 +498,16 @@ actor QueryHistoryStorage { sqlite3_bind_null(statement, 13) } sqlite3_bind_int64(statement, 14, SQLQueryFingerprint.hash(entry.query, databaseType: entry.databaseType)) + if let firstRowTime = entry.firstRowTime { + sqlite3_bind_double(statement, 15, firstRowTime) + } else { + sqlite3_bind_null(statement, 15) + } + if let serverTime = entry.serverTime { + sqlite3_bind_double(statement, 16, serverTime) + } else { + sqlite3_bind_null(statement, 16) + } guard sqlite3_step(statement) == SQLITE_DONE else { logSqliteError(context: "insert") @@ -510,7 +536,7 @@ actor QueryHistoryStorage { clause.append(""" SELECT h.id, h.query, h.connection_id, h.database_name, h.database_type, h.schema_name, h.source, h.statement_type, h.executed_at, h.execution_time, h.row_count, - h.was_successful, h.error_message + h.was_successful, h.error_message, h.first_row_time, h.server_time FROM history h INNER JOIN history_fts ON h.rowid = history_fts.rowid WHERE history_fts MATCH ? @@ -519,7 +545,7 @@ actor QueryHistoryStorage { clause.append(""" SELECT id, query, connection_id, database_name, database_type, schema_name, source, statement_type, executed_at, execution_time, row_count, - was_successful, error_message + was_successful, error_message, first_row_time, server_time FROM history WHERE 1 = 1 """) @@ -661,6 +687,14 @@ actor QueryHistoryStorage { /// Ranked shapes for one panel. Every arm reads a column the grouped subquery selects, so the /// ordering never reaches a value the caller cannot also see. + /// What "how long did this query take" means once transfer is separable from execution. + /// + /// The server's own report wins where a protocol carries one, the client-measured time to the + /// first row stands in where it does not, and elapsed is the floor so a row written before the + /// split existed still ranks. Every panel that answers "is this query slow" reads through this; + /// the totals bar deliberately does not, because "how long did I wait" is elapsed by definition. + private static let databaseTimeExpression = "COALESCE(server_time, first_row_time, execution_time)" + private enum InsightsRanking { case callCount case totalDuration @@ -768,8 +802,8 @@ actor QueryHistoryStorage { SELECT COUNT(*), SUM(CASE WHEN was_successful = 0 THEN 1 ELSE 0 END), COUNT(DISTINCT fingerprint_hash), - SUM(execution_time), - MAX(execution_time) + SUM(\(Self.databaseTimeExpression)), + MAX(\(Self.databaseTimeExpression)) FROM history WHERE 1 = 1 """) @@ -809,8 +843,8 @@ actor QueryHistoryStorage { SELECT fingerprint_hash, COUNT(*) AS call_count, SUM(CASE WHEN was_successful = 0 THEN 1 ELSE 0 END) AS failure_count, - SUM(execution_time) AS total_duration, - MAX(execution_time) AS max_duration, + SUM(\(Self.databaseTimeExpression)) AS total_duration, + MAX(\(Self.databaseTimeExpression)) AS max_duration, SUM(CASE WHEN row_count >= 0 THEN row_count ELSE 0 END) AS total_rows FROM history WHERE 1 = 1 @@ -879,7 +913,7 @@ actor QueryHistoryStorage { WITH windowed AS ( SELECT fingerprint_hash, CASE WHEN executed_at >= ? THEN 1 ELSE 0 END AS is_recent, - execution_time + \(Self.databaseTimeExpression) AS execution_time FROM history WHERE was_successful = 1 AND executed_at >= ? AND executed_at < ? """, .double(middle), .double(start), .double(end)) @@ -1162,7 +1196,16 @@ actor QueryHistoryStorage { executionTime: sqlite3_column_double(statement, 9), rowCount: Int(sqlite3_column_int(statement, 10)), wasSuccessful: sqlite3_column_int(statement, 11) == 1, - errorMessage: sqlite3_column_text(statement, 12).map { String(cString: $0) } + errorMessage: sqlite3_column_text(statement, 12).map { String(cString: $0) }, + firstRowTime: optionalDouble(statement, 13), + serverTime: optionalDouble(statement, 14) ) } + + /// A NULL column reads back as 0.0 through `sqlite3_column_double`, and 0.0 is a query that + /// took no time rather than one that was never measured. + private func optionalDouble(_ statement: OpaquePointer?, _ index: Int32) -> TimeInterval? { + guard let statement, sqlite3_column_type(statement, index) != SQLITE_NULL else { return nil } + return sqlite3_column_double(statement, index) + } } diff --git a/TablePro/Models/ClickHouse/ClickHouseQueryProgress.swift b/TablePro/Models/ClickHouse/ClickHouseQueryProgress.swift deleted file mode 100644 index d879a675d..000000000 --- a/TablePro/Models/ClickHouse/ClickHouseQueryProgress.swift +++ /dev/null @@ -1,52 +0,0 @@ -// -// ClickHouseQueryProgress.swift -// TablePro -// -// Query progress tracking data for ClickHouse queries. -// - -import Foundation - -/// Live query progress data polled from system.processes -struct ClickHouseQueryProgress: Equatable { - let rowsRead: UInt64 - let bytesRead: UInt64 - let totalRowsToRead: UInt64 - let elapsedSeconds: Double - - /// Formatted string for live display during execution: "1.2M rows · 45 MB" - var formattedLive: String { - "\(Self.formatCount(rowsRead)) rows · \(Self.formatBytes(bytesRead))" - } - - /// Formatted summary after completion: "235ms · 1.2M rows · 45 MB" - var formattedSummary: String { - "\(Self.formatDuration(elapsedSeconds)) · \(Self.formatCount(rowsRead)) rows · \(Self.formatBytes(bytesRead))" - } - - // MARK: - Formatting Helpers - - private static func formatCount(_ count: UInt64) -> String { - switch count { - case 0..<1_000: - return "\(count)" - case 1_000..<1_000_000: - let k = Double(count) / 1_000 - return String(format: "%.1fK", k) - case 1_000_000..<1_000_000_000: - let m = Double(count) / 1_000_000 - return String(format: "%.1fM", m) - default: - let b = Double(count) / 1_000_000_000 - return String(format: "%.1fB", b) - } - } - - private static func formatBytes(_ bytes: UInt64) -> String { - ByteSizeFormatting.string(bytes: bytes) - } - - private static func formatDuration(_ seconds: Double) -> String { - DurationFormatting.string(seconds: seconds) - } -} diff --git a/TablePro/Models/Connection/ConnectionToolbarState.swift b/TablePro/Models/Connection/ConnectionToolbarState.swift index 6b4d7b63c..f7b3e1171 100644 --- a/TablePro/Models/Connection/ConnectionToolbarState.swift +++ b/TablePro/Models/Connection/ConnectionToolbarState.swift @@ -86,14 +86,8 @@ final class ConnectionToolbarState { // MARK: - Query Execution - /// Duration of the last completed query - var lastQueryDuration: TimeInterval? - - /// Live ClickHouse query progress (rows/bytes read during execution) - var clickHouseProgress: ClickHouseQueryProgress? - - /// Retained progress from last completed ClickHouse query (for summary display) - var lastClickHouseProgress: ClickHouseQueryProgress? + /// How long the last completed query took, and what that time was spent on. + var lastQueryTiming: PluginQueryTiming? // MARK: - Future Expansion @@ -241,9 +235,7 @@ final class ConnectionToolbarState { brandColor = databaseType.themeColor identityColor = nil connectionState = .disconnected - lastQueryDuration = nil - clickHouseProgress = nil - lastClickHouseProgress = nil + lastQueryTiming = nil safeModeLevel = .silent isTableTab = false latencyMs = nil diff --git a/TablePro/Models/Query/QueryHistoryEntry.swift b/TablePro/Models/Query/QueryHistoryEntry.swift index 1c118bfc0..48db35dbd 100644 --- a/TablePro/Models/Query/QueryHistoryEntry.swift +++ b/TablePro/Models/Query/QueryHistoryEntry.swift @@ -1,4 +1,5 @@ import Foundation +import TableProPluginKit struct QueryHistoryEntry: Identifiable, Codable, Hashable, Sendable { let id: UUID @@ -15,6 +16,12 @@ struct QueryHistoryEntry: Identifiable, Codable, Hashable, Sendable { let wasSuccessful: Bool let errorMessage: String? + /// Client-measured time to the first row, when the driver could see one. + let firstRowTime: TimeInterval? + + /// Execution time as the engine reported it, when its protocol carries one. + let serverTime: TimeInterval? + init( id: UUID = UUID(), query: String, @@ -28,7 +35,9 @@ struct QueryHistoryEntry: Identifiable, Codable, Hashable, Sendable { executionTime: TimeInterval, rowCount: Int, wasSuccessful: Bool, - errorMessage: String? = nil + errorMessage: String? = nil, + firstRowTime: TimeInterval? = nil, + serverTime: TimeInterval? = nil ) { self.id = id self.query = query @@ -43,6 +52,20 @@ struct QueryHistoryEntry: Identifiable, Codable, Hashable, Sendable { self.rowCount = rowCount self.wasSuccessful = wasSuccessful self.errorMessage = errorMessage + self.firstRowTime = firstRowTime + self.serverTime = serverTime + } + + var timing: PluginQueryTiming { + PluginQueryTiming(total: executionTime, firstRow: firstRowTime, server: serverTime) + } + + /// What the database itself spent, as opposed to the wire. This is what the insights panels + /// rank on, so a query that is only slow to transfer stops reading as a slow query. + var databaseTime: TimeInterval { timing.databaseTime } + + var formattedDatabaseTime: String { + QueryDurationFormatter.string(from: databaseTime) } var cursor: QueryHistoryCursor { diff --git a/TablePro/Models/Query/QueryHistoryRecordRequest.swift b/TablePro/Models/Query/QueryHistoryRecordRequest.swift index 99bca8310..8ff062c06 100644 --- a/TablePro/Models/Query/QueryHistoryRecordRequest.swift +++ b/TablePro/Models/Query/QueryHistoryRecordRequest.swift @@ -1,4 +1,5 @@ import Foundation +import TableProPluginKit struct QueryHistoryRecordRequest: Sendable { /// Chosen by the caller so a run that also saves a plan can link the two before either is @@ -20,6 +21,10 @@ struct QueryHistoryRecordRequest: Sendable { /// its place in history. var planCapture: QueryPlanCapture? + /// What the elapsed time was spent on, when the driver could tell. Defaulted, because most + /// recorders write a statement they timed themselves and have no split to offer. + var timing: PluginQueryTiming? + init( id: UUID = UUID(), query: String, @@ -32,7 +37,8 @@ struct QueryHistoryRecordRequest: Sendable { rowCount: Int, wasSuccessful: Bool, errorMessage: String? = nil, - planCapture: QueryPlanCapture? = nil + planCapture: QueryPlanCapture? = nil, + timing: PluginQueryTiming? = nil ) { self.id = id self.query = query @@ -46,5 +52,6 @@ struct QueryHistoryRecordRequest: Sendable { self.wasSuccessful = wasSuccessful self.errorMessage = errorMessage self.planCapture = planCapture + self.timing = timing } } diff --git a/TablePro/Models/Query/QueryResult.swift b/TablePro/Models/Query/QueryResult.swift index 0d5e960cb..0d6cbbff8 100644 --- a/TablePro/Models/Query/QueryResult.swift +++ b/TablePro/Models/Query/QueryResult.swift @@ -16,6 +16,14 @@ struct QueryResult { let executionTime: TimeInterval let error: DatabaseError? + /// What the elapsed time was spent on, when the driver could tell. Defaults to the elapsed + /// number alone so a result built without one reads exactly as it always did. + var timing: PluginQueryTiming? + + var resolvedTiming: PluginQueryTiming { + timing ?? PluginQueryTiming(total: executionTime) + } + /// Whether the result was truncated due to driver-level row limits var isTruncated: Bool = false diff --git a/TablePro/Models/Query/QueryTimingAggregation.swift b/TablePro/Models/Query/QueryTimingAggregation.swift new file mode 100644 index 000000000..c4dfccda8 --- /dev/null +++ b/TablePro/Models/Query/QueryTimingAggregation.swift @@ -0,0 +1,38 @@ +// +// QueryTimingAggregation.swift +// TablePro +// + +import Foundation +import TableProPluginKit + +extension PluginQueryTiming { + /// Folds a batch of statements into one timing. + /// + /// A part is summed only when every statement supplied it. Summing the ones that did and + /// ignoring the rest would report a server time smaller than the work it claims to describe, + /// which reads as a fast batch rather than as a partly unmeasured one. + static func total(of timings: [PluginQueryTiming]) -> PluginQueryTiming? { + guard !timings.isEmpty else { return nil } + return PluginQueryTiming( + total: timings.reduce(0) { $0 + $1.total }, + firstRow: summed(timings.map(\.firstRow)), + server: summed(timings.map(\.server)) + ) + } + + /// A batch with nothing in it still has to report something, and zero is what the elapsed sum + /// reported before there was a timing to fold. + static func batch(of results: [QueryResult]) -> PluginQueryTiming { + total(of: results.map(\.resolvedTiming)) ?? PluginQueryTiming(total: 0) + } + + private static func summed(_ parts: [TimeInterval?]) -> TimeInterval? { + var accumulated: TimeInterval = 0 + for part in parts { + guard let part else { return nil } + accumulated += part + } + return accumulated + } +} diff --git a/TablePro/Views/Editor/History/HistoryDetailPane.swift b/TablePro/Views/Editor/History/HistoryDetailPane.swift index 04132ef97..bd1d9a1fd 100644 --- a/TablePro/Views/Editor/History/HistoryDetailPane.swift +++ b/TablePro/Views/Editor/History/HistoryDetailPane.swift @@ -1,4 +1,5 @@ import SwiftUI +import TableProPluginKit struct HistoryDetailPane: View { let entry: QueryHistoryEntry? @@ -57,7 +58,7 @@ struct HistoryDetailPane: View { } row(String(localized: "Database"), databaseDescription(for: entry)) row(String(localized: "Ran"), entry.executedAt.formatted(date: .abbreviated, time: .standard)) - row(String(localized: "Duration"), entry.hasMeasuredDuration ? entry.formattedExecutionTime : "–") + durationRows(for: entry) row(String(localized: "Rows"), entry.hasKnownRowCount ? entry.formattedRowCount : "–") row(String(localized: "Source"), entry.source.displayName) } @@ -74,6 +75,21 @@ struct HistoryDetailPane: View { .frame(maxWidth: .infinity, alignment: .leading) } + /// A driver that could separate execution from transfer gets every part it measured, because + /// the whole point of storing them is that the elapsed number alone does not say which was slow. + @ViewBuilder + private func durationRows(for entry: QueryHistoryEntry) -> some View { + if !entry.hasMeasuredDuration { + row(String(localized: "Duration"), "–") + } else if entry.timing.hasBreakdown { + ForEach(QueryTimingBreakdown(timing: entry.timing).rows) { breakdownRow in + row(breakdownRow.label, breakdownRow.value) + } + } else { + row(String(localized: "Duration"), entry.formattedExecutionTime) + } + } + private func row(_ label: String, _ value: String) -> some View { GridRow { Text(label) diff --git a/TablePro/Views/Main/Extensions/MainContentCoordinator+ClickHouse.swift b/TablePro/Views/Main/Extensions/MainContentCoordinator+ClickHouse.swift deleted file mode 100644 index a25a97ffd..000000000 --- a/TablePro/Views/Main/Extensions/MainContentCoordinator+ClickHouse.swift +++ /dev/null @@ -1,22 +0,0 @@ -// -// MainContentCoordinator+ClickHouse.swift -// TablePro -// -// ClickHouse-specific coordinator methods: progress tracking. -// - -import Foundation - -extension MainContentCoordinator { - func installClickHouseProgressHandler() { - // Progress polling is handled internally by the ClickHouse plugin. - // This is a no-op stub retained for call-site compatibility. - } - - func clearClickHouseProgress() { - if let live = toolbarState.clickHouseProgress { - toolbarState.lastClickHouseProgress = live - } - toolbarState.clickHouseProgress = nil - } -} diff --git a/TablePro/Views/Main/Extensions/MainContentCoordinator+QueryHelpers.swift b/TablePro/Views/Main/Extensions/MainContentCoordinator+QueryHelpers.swift index a762f6edf..6bbbfdb2e 100644 --- a/TablePro/Views/Main/Extensions/MainContentCoordinator+QueryHelpers.swift +++ b/TablePro/Views/Main/Extensions/MainContentCoordinator+QueryHelpers.swift @@ -101,7 +101,8 @@ extension MainContentCoordinator { connection conn: DatabaseConnection, isTruncated: Bool = false, queryParameterValues: [QueryParameter]? = nil, - anchor: StatementAnchor? = nil + anchor: StatementAnchor? = nil, + timing: PluginQueryTiming? = nil ) { queryExecutionCoordinator.applyPhase1Result( tabId: tabId, @@ -119,7 +120,8 @@ extension MainContentCoordinator { connection: conn, isTruncated: isTruncated, queryParameterValues: queryParameterValues, - anchor: anchor + anchor: anchor, + timing: timing ) } diff --git a/TablePro/Views/Main/MainContentCoordinator.swift b/TablePro/Views/Main/MainContentCoordinator.swift index d879edbb8..acd151ac6 100644 --- a/TablePro/Views/Main/MainContentCoordinator.swift +++ b/TablePro/Views/Main/MainContentCoordinator.swift @@ -1263,10 +1263,6 @@ final class MainContentCoordinator { } let tab = tabManager.tabs[index] - if services.pluginManager.supportsQueryProgress(for: connection.type) { - installClickHouseProgressHandler() - } - let conn = connection let tabId = tabManager.tabs[index].id @@ -1371,10 +1367,7 @@ final class MainContentCoordinator { traceStaleResultDropped(traceToken) return } - if services.pluginManager.supportsQueryProgress(for: self.connection.type) { - self.clearClickHouseProgress() - } - toolbarState.lastQueryDuration = fetchResult.executionTime + toolbarState.lastQueryTiming = fetchResult.resolvedTiming traceApplyingResult(traceToken, tabId: tabId) @@ -1393,7 +1386,8 @@ final class MainContentCoordinator { sql: sql, connection: conn, isTruncated: fetchResult.isTruncated, - anchor: anchor + anchor: anchor, + timing: fetchResult.resolvedTiming ) scheduleTraceCompletion(traceToken, outcome: .completed) @@ -1505,7 +1499,7 @@ final class MainContentCoordinator { ]) guard currentQueryTaskOwner == claim else { return } retireQueryTask(for: claim) - toolbarState.lastQueryDuration = executionTime + toolbarState.lastQueryTiming = PluginQueryTiming(total: executionTime) } internal func resolveTableEditability(tab: QueryTab, sql: String) -> (tableName: String?, isEditable: Bool) { diff --git a/TablePro/Views/Toolbar/ExecutionIndicatorView.swift b/TablePro/Views/Toolbar/ExecutionIndicatorView.swift index 2f0035f38..51b5683f7 100644 --- a/TablePro/Views/Toolbar/ExecutionIndicatorView.swift +++ b/TablePro/Views/Toolbar/ExecutionIndicatorView.swift @@ -7,13 +7,12 @@ // import SwiftUI +import TableProPluginKit /// Compact execution indicator for the toolbar right section struct ExecutionIndicatorView: View { let isExecuting: Bool - let lastDuration: TimeInterval? - let clickHouseProgress: ClickHouseQueryProgress? - let lastClickHouseProgress: ClickHouseQueryProgress? + let lastTiming: PluginQueryTiming? var onCancel: (() -> Void)? /// Held back rather than the spinner inside it, so a query too fast to report leaves the @@ -25,6 +24,18 @@ struct ExecutionIndicatorView: View { /// button is there, which is what the HIG asks: "When it's feasible, let people halt /// processing." @State private var showsExecution = false + @State private var showsBreakdown = false + + /// Why the two numbers differ, in the popover's own words. A client-measured first row carries + /// one network round trip and a server-reported figure does not, and a reader comparing them + /// has no other way to know that. + private static let clientExplanation = String(localized: """ + Time to the first row is measured here, so it includes one network round trip. + """) + + private static let serverExplanation = String(localized: """ + The server figure is the engine's own report, so it excludes network time. + """) var body: some View { HStack(spacing: 4) { @@ -33,15 +44,9 @@ struct ExecutionIndicatorView: View { .controlSize(.small) .accessibilityLabel(String(localized: "Query executing")) .accessibilityIdentifier("execution-indicator") - if let progress = clickHouseProgress { - Text(progress.formattedLive) - .font(.system(.subheadline, design: .monospaced).weight(.regular)) - .foregroundStyle(ThemeEngine.shared.colors.toolbar.tertiaryTextSwiftUI) - } else { - Text("Executing…") - .font(.system(.subheadline, design: .monospaced).weight(.regular)) - .foregroundStyle(ThemeEngine.shared.colors.toolbar.tertiaryTextSwiftUI) - } + Text("Executing…") + .font(.system(.subheadline, design: .monospaced).weight(.regular)) + .foregroundStyle(ThemeEngine.shared.colors.toolbar.tertiaryTextSwiftUI) Button { onCancel?() } label: { @@ -52,20 +57,8 @@ struct ExecutionIndicatorView: View { .controlSize(.small) .accessibilityIdentifier("execution-stop") .help(String(localized: "Cancel Query (⌘.)")) - } else if let chProgress = lastClickHouseProgress { - Text(chProgress.formattedSummary) - .font(.system(.subheadline, design: .monospaced).weight(.regular)) - .foregroundStyle(ThemeEngine.shared.colors.toolbar.tertiaryTextSwiftUI) - .accessibilityLabel(String(format: String(localized: "Last query: %@"), chProgress.formattedSummary)) - .help(String(localized: "Last query execution summary")) - } else if let duration = lastDuration { - Text(formattedDuration(duration)) - .font(.system(.subheadline, design: .monospaced).weight(.regular)) - .foregroundStyle(ThemeEngine.shared.colors.toolbar.tertiaryTextSwiftUI) - .accessibilityLabel( - String(format: String(localized: "Last query took %@"), formattedDuration(duration)) - ) - .help(String(localized: "Last query execution time")) + } else if let timing = lastTiming { + durationReadout(timing) } else { Text("--") .font(.system(.subheadline, design: .monospaced).weight(.regular)) @@ -74,51 +67,79 @@ struct ExecutionIndicatorView: View { .help(String(localized: "Run a query to see execution time")) } } + .onChange(of: isExecuting) { _, nowExecuting in + if nowExecuting { showsBreakdown = false } + } .loadingRevealGate(isActive: isExecuting, isRevealed: $showsExecution) } - // MARK: - Helpers + // MARK: - Readout + + /// The elapsed number stays the label, because that is what a reader already knows how to read. + /// The split lives one click away rather than widening the toolbar with a second figure whose + /// meaning nothing on screen explains. + @ViewBuilder + private func durationReadout(_ timing: PluginQueryTiming) -> some View { + let text = QueryDurationFormatter.string(from: timing.total) - /// Format duration for display - private func formattedDuration(_ duration: TimeInterval) -> String { - if duration < 0.001 { - return String(localized: "<1ms") - } else if duration < 1.0 { - let ms = String(format: "%.0f", duration * 1_000) - return String(format: String(localized: "%@ms"), ms) - } else if duration < 60.0 { - let secs = String(format: "%.2f", duration) - return String(format: String(localized: "%@s"), secs) + if timing.hasBreakdown { + let breakdown = QueryTimingBreakdown(timing: timing) + Button { + showsBreakdown.toggle() + } label: { + durationLabel(text) + } + .buttonStyle(.plain) + .accessibilityLabel(String(format: String(localized: "Last query took %@"), text)) + .accessibilityHint(String(localized: "Shows how the time was spent")) + .accessibilityIdentifier("execution-duration") + .help(breakdown.summary) + .popover(isPresented: $showsBreakdown, arrowEdge: .bottom) { + QueryTimingPopover( + breakdown: breakdown, + explanation: timing.server != nil ? Self.serverExplanation : Self.clientExplanation + ) + } } else { - let minutes = Int(duration) / 60 - let seconds = Int(duration) % 60 - return String(format: String(localized: "%dm %ds"), minutes, seconds) + durationLabel(text) + .accessibilityLabel(String(format: String(localized: "Last query took %@"), text)) + .accessibilityIdentifier("execution-duration") + .help(String(localized: "Last query execution time")) } } + + private func durationLabel(_ text: String) -> some View { + Text(text) + .font(.system(.subheadline, design: .monospaced).weight(.regular)) + .foregroundStyle(ThemeEngine.shared.colors.toolbar.tertiaryTextSwiftUI) + } } // MARK: - Preview #Preview("Executing") { - ExecutionIndicatorView(isExecuting: true, lastDuration: nil, clickHouseProgress: nil, lastClickHouseProgress: nil) + ExecutionIndicatorView(isExecuting: true, lastTiming: nil) .padding() .background(Color(nsColor: .windowBackgroundColor)) } #Preview("Completed Fast") { - ExecutionIndicatorView(isExecuting: false, lastDuration: 0.023, clickHouseProgress: nil, lastClickHouseProgress: nil) + ExecutionIndicatorView(isExecuting: false, lastTiming: PluginQueryTiming(total: 0.023)) .padding() .background(Color(nsColor: .windowBackgroundColor)) } -#Preview("Completed Slow") { - ExecutionIndicatorView(isExecuting: false, lastDuration: 2.456, clickHouseProgress: nil, lastClickHouseProgress: nil) - .padding() - .background(Color(nsColor: .windowBackgroundColor)) +#Preview("Split") { + ExecutionIndicatorView( + isExecuting: false, + lastTiming: PluginQueryTiming(total: 3.421, firstRow: 0.012) + ) + .padding() + .background(Color(nsColor: .windowBackgroundColor)) } #Preview("No Duration") { - ExecutionIndicatorView(isExecuting: false, lastDuration: nil, clickHouseProgress: nil, lastClickHouseProgress: nil) + ExecutionIndicatorView(isExecuting: false, lastTiming: nil) .padding() .background(Color(nsColor: .windowBackgroundColor)) } diff --git a/TablePro/Views/Toolbar/QueryTimingBreakdown.swift b/TablePro/Views/Toolbar/QueryTimingBreakdown.swift new file mode 100644 index 000000000..62f652b7e --- /dev/null +++ b/TablePro/Views/Toolbar/QueryTimingBreakdown.swift @@ -0,0 +1,87 @@ +// +// QueryTimingBreakdown.swift +// TablePro +// + +import SwiftUI +import TableProPluginKit + +/// The rows a timing popover shows, resolved once so the view and its tests read the same list. +/// +/// Kept apart from the view because what is worth showing depends on what the driver could measure, +/// and that decision is the part worth pinning with a test. +struct QueryTimingBreakdown: Equatable { + struct Row: Equatable, Identifiable { + let id: String + let label: String + let value: String + } + + let rows: [Row] + let summary: String + + init(timing: PluginQueryTiming) { + var rows: [Row] = [ + Row( + id: "elapsed", + label: String(localized: "Elapsed"), + value: QueryDurationFormatter.string(from: timing.total) + ), + ] + + if let server = timing.server { + rows.append(Row( + id: "server", + label: String(localized: "Server"), + value: QueryDurationFormatter.string(from: server) + )) + } + if let firstRow = timing.firstRow { + rows.append(Row( + id: "firstRow", + label: String(localized: "First row"), + value: QueryDurationFormatter.string(from: firstRow) + )) + } + if let transfer = timing.transfer { + rows.append(Row( + id: "transfer", + label: String(localized: "Transfer"), + value: QueryDurationFormatter.string(from: transfer) + )) + } + + self.rows = rows + summary = rows.map { "\($0.label) \($0.value)" }.joined(separator: " · ") + } +} + +/// The popover behind the toolbar's duration readout. +struct QueryTimingPopover: View { + let breakdown: QueryTimingBreakdown + let explanation: String + + var body: some View { + VStack(alignment: .leading, spacing: 10) { + Grid(alignment: .leading, horizontalSpacing: 16, verticalSpacing: 4) { + ForEach(breakdown.rows) { row in + GridRow { + Text(row.label) + .foregroundStyle(.secondary) + Text(row.value) + .font(.system(.body, design: .monospaced)) + .gridColumnAlignment(.trailing) + } + } + } + + Text(explanation) + .font(.caption) + .foregroundStyle(.secondary) + .fixedSize(horizontal: false, vertical: true) + .frame(maxWidth: 240, alignment: .leading) + } + .padding(14) + .accessibilityIdentifier("query-timing-popover") + } +} diff --git a/TablePro/Views/Toolbar/TableProToolbarView.swift b/TablePro/Views/Toolbar/TableProToolbarView.swift index 095c4c0b8..4ac51fa6b 100644 --- a/TablePro/Views/Toolbar/TableProToolbarView.swift +++ b/TablePro/Views/Toolbar/TableProToolbarView.swift @@ -58,9 +58,7 @@ struct ToolbarPrincipalContent: View { ExecutionIndicatorView( isExecuting: coordinator?.tabExecution.isAnyExecuting ?? false, - lastDuration: state.lastQueryDuration, - clickHouseProgress: state.clickHouseProgress, - lastClickHouseProgress: state.lastClickHouseProgress, + lastTiming: state.lastQueryTiming, onCancel: onCancelQuery ) diff --git a/TableProTests/Core/Execution/CancelledExecutionOwnershipTests.swift b/TableProTests/Core/Execution/CancelledExecutionOwnershipTests.swift index 14aaaec7f..810d1c980 100644 --- a/TableProTests/Core/Execution/CancelledExecutionOwnershipTests.swift +++ b/TableProTests/Core/Execution/CancelledExecutionOwnershipTests.swift @@ -110,7 +110,7 @@ struct CancelledExecutionOwnershipTests { #expect(coordinator.currentQueryTask != nil) #expect(coordinator.currentQueryTaskOwner == live) - #expect(coordinator.toolbarState.lastQueryDuration == nil) + #expect(coordinator.toolbarState.lastQueryTiming == nil) } @Test("Closing a tab releases the execution it was running") diff --git a/TableProTests/Core/Storage/QueryHistoryMigrationTests.swift b/TableProTests/Core/Storage/QueryHistoryMigrationTests.swift index 34d619aca..639e2025b 100644 --- a/TableProTests/Core/Storage/QueryHistoryMigrationTests.swift +++ b/TableProTests/Core/Storage/QueryHistoryMigrationTests.swift @@ -292,7 +292,7 @@ struct QueryHistoryMigrationTests { "database_name", "database_type", "schema_name", "variant_key", "format", "raw_plan", "byte_count", "execution_time", "captured_at", "is_pinned" ]) - #expect(scalarInt(in: url, sql: "PRAGMA user_version;") == 4) + #expect(scalarInt(in: url, sql: "PRAGMA user_version;") == 5) let second = QueryHistoryStorage(databaseURL: url, removeDatabaseOnDeinit: true) #expect(await second.count(scope: .all) == 1) @@ -314,7 +314,7 @@ struct QueryHistoryMigrationTests { let second = QueryHistoryStorage(databaseURL: url, removeDatabaseOnDeinit: true) #expect(await second.count(scope: .all) == 0) - #expect(scalarInt(in: url, sql: "PRAGMA user_version;") == 4) + #expect(scalarInt(in: url, sql: "PRAGMA user_version;") == 5) #expect( scalarInt( in: url, diff --git a/TableProTests/Core/Storage/QueryHistoryTimingTests.swift b/TableProTests/Core/Storage/QueryHistoryTimingTests.swift new file mode 100644 index 000000000..242818ef5 --- /dev/null +++ b/TableProTests/Core/Storage/QueryHistoryTimingTests.swift @@ -0,0 +1,224 @@ +// +// QueryHistoryTimingTests.swift +// TableProTests +// +// The split between execution and transfer, from the column that stores it to the ranking +// that reads it. +// + +import Foundation +import SQLite3 +@testable import TablePro +import TableProPluginKit +import Testing + +@Suite("QueryHistory timing") +struct QueryHistoryTimingTests { + private static let transient = unsafeBitCast(-1, to: sqlite3_destructor_type.self) + + private func makeStorage() -> QueryHistoryStorage { + QueryHistoryStorage( + databaseURL: FileManager.default.temporaryDirectory + .appendingPathComponent("tablepro-tests") + .appendingPathComponent("query_timing_\(UUID().uuidString).db"), + removeDatabaseOnDeinit: true + ) + } + + private func record( + _ storage: QueryHistoryStorage, + _ query: String, + connectionId: UUID, + executionTime: TimeInterval, + firstRowTime: TimeInterval? = nil, + serverTime: TimeInterval? = nil + ) async { + _ = await storage.record(QueryHistoryEntry( + query: query, + connectionId: connectionId, + databaseName: "testdb", + databaseType: .postgresql, + source: .editor, + executionTime: executionTime, + rowCount: 1, + wasSuccessful: true, + firstRowTime: firstRowTime, + serverTime: serverTime + )) + } + + // MARK: - Round trip + + @Test("Both figures survive a write and a read") + func splitRoundTrips() async { + let storage = makeStorage() + let connectionId = UUID() + await record(storage, "SELECT 1", connectionId: connectionId, + executionTime: 3.4, firstRowTime: 0.012, serverTime: 0.009) + + let entries = await storage.fetch( + QueryHistoryFilter(scope: .connection(connectionId)), after: nil, limit: 10 + ).entries + + #expect(entries.count == 1) + #expect(entries.first?.firstRowTime == 0.012) + #expect(entries.first?.serverTime == 0.009) + #expect(entries.first?.databaseTime == 0.009) + } + + /// The columns are nullable and `sqlite3_column_double` reads a NULL back as 0.0, which would + /// render as a query that took no time rather than one nothing measured. + @Test("An unmeasured row reads back as absent, not as zero") + func unmeasuredReadsBackAsNil() async { + let storage = makeStorage() + let connectionId = UUID() + await record(storage, "SELECT 2", connectionId: connectionId, executionTime: 1.5) + + let entry = await storage.fetch( + QueryHistoryFilter(scope: .connection(connectionId)), after: nil, limit: 10 + ).entries.first + + #expect(entry?.firstRowTime == nil) + #expect(entry?.serverTime == nil) + #expect(entry?.databaseTime == 1.5) + } + + // MARK: - Ranking + + @Test("The slowest panel ranks on database time, not on transfer") + func slowestRanksOnDatabaseTime() async { + let storage = makeStorage() + let connectionId = UUID() + // Slow only because it moved a lot of rows. + await record(storage, "SELECT * FROM wide", connectionId: connectionId, + executionTime: 9.0, firstRowTime: 0.005) + // Genuinely slow on the server, and quick to send. + await record(storage, "SELECT count(*) FROM huge", connectionId: connectionId, + executionTime: 2.0, firstRowTime: 1.9) + + let snapshot = await storage.insights( + QueryInsightsRequest(scope: .connection(connectionId)), + slowestRanking: .totalTime + ) + + #expect(snapshot.slowest.first?.representativeQuery.contains("count(*)") == true) + } + + @Test("A row written before the split existed still ranks on its elapsed time") + func unmeasuredRowsStillRank() async { + let storage = makeStorage() + let connectionId = UUID() + await record(storage, "SELECT * FROM slow_legacy", connectionId: connectionId, executionTime: 8.0) + await record(storage, "SELECT * FROM fast", connectionId: connectionId, + executionTime: 5.0, firstRowTime: 0.004) + + let snapshot = await storage.insights( + QueryInsightsRequest(scope: .connection(connectionId)), + slowestRanking: .totalTime + ) + + #expect(snapshot.slowest.first?.representativeQuery.contains("slow_legacy") == true) + } + + // MARK: - Migration + + /// A database written by the previous release has neither column. It must gain both, keep every + /// row, and read exactly as it did before, because there is no honest value to backfill. + @Test("A v4 database gains both columns without losing a row") + func migratesFromVersionFour() async { + let url = makeVersionFourDatabase(query: "SELECT * FROM legacy", executionTime: 2.5) + + let storage = QueryHistoryStorage(databaseURL: url, removeDatabaseOnDeinit: true) + let entries = await storage.fetch(QueryHistoryFilter(scope: .all), after: nil, limit: 10).entries + + #expect(columnNames(in: url, table: "history").isSuperset(of: ["first_row_time", "server_time"])) + #expect(entries.count == 1) + #expect(entries.first?.executionTime == 2.5) + #expect(entries.first?.firstRowTime == nil) + #expect(entries.first?.databaseTime == 2.5) + } + + // MARK: - Fixtures + + private func makeVersionFourDatabase(query: String, executionTime: TimeInterval) -> URL { + let url = FileManager.default.temporaryDirectory + .appendingPathComponent("tablepro-tests") + .appendingPathComponent("history_v4_\(UUID().uuidString).db") + try? FileManager.default.createDirectory( + at: url.deletingLastPathComponent(), + withIntermediateDirectories: true + ) + + var db: OpaquePointer? + guard sqlite3_open(url.path(percentEncoded: false), &db) == SQLITE_OK else { return url } + defer { sqlite3_close_v2(db) } + + let statements = [ + """ + CREATE TABLE history ( + id TEXT PRIMARY KEY, + query TEXT NOT NULL, + connection_id TEXT NOT NULL, + database_name TEXT NOT NULL, + database_type TEXT NOT NULL DEFAULT '', + schema_name TEXT, + source TEXT NOT NULL DEFAULT 'editor', + statement_type TEXT NOT NULL DEFAULT 'other', + executed_at REAL NOT NULL, + execution_time REAL NOT NULL, + row_count INTEGER NOT NULL, + was_successful INTEGER NOT NULL, + error_message TEXT, + fingerprint_hash INTEGER NOT NULL DEFAULT 0 + ); + """, + """ + CREATE VIRTUAL TABLE history_fts USING fts5( + query, content='history', content_rowid='rowid' + ); + """, + "PRAGMA user_version = 4;", + ] + for sql in statements { + sqlite3_exec(db, sql, nil, nil, nil) + } + + let insert = """ + INSERT INTO history (id, query, connection_id, database_name, database_type, schema_name, + source, statement_type, executed_at, execution_time, row_count, + was_successful, error_message, fingerprint_hash) + VALUES (?, ?, ?, 'legacydb', 'PostgreSQL', NULL, 'editor', 'select', ?, ?, 3, 1, NULL, 0); + """ + var statement: OpaquePointer? + if sqlite3_prepare_v2(db, insert, -1, &statement, nil) == SQLITE_OK { + sqlite3_bind_text(statement, 1, UUID().uuidString, -1, Self.transient) + sqlite3_bind_text(statement, 2, query, -1, Self.transient) + sqlite3_bind_text(statement, 3, UUID().uuidString, -1, Self.transient) + sqlite3_bind_double(statement, 4, Date().timeIntervalSince1970) + sqlite3_bind_double(statement, 5, executionTime) + sqlite3_step(statement) + } + sqlite3_finalize(statement) + + return url + } + + private func columnNames(in url: URL, table: String) -> Set { + var db: OpaquePointer? + guard sqlite3_open(url.path(percentEncoded: false), &db) == SQLITE_OK else { return [] } + defer { sqlite3_close_v2(db) } + + var names: Set = [] + var statement: OpaquePointer? + guard sqlite3_prepare_v2(db, "PRAGMA table_info(\(table))", -1, &statement, nil) == SQLITE_OK else { + return names + } + while sqlite3_step(statement) == SQLITE_ROW { + if let name = sqlite3_column_text(statement, 1) { + names.insert(String(cString: name)) + } + } + sqlite3_finalize(statement) + return names + } +} diff --git a/TableProTests/Models/QueryTimingTests.swift b/TableProTests/Models/QueryTimingTests.swift new file mode 100644 index 000000000..47989eebf --- /dev/null +++ b/TableProTests/Models/QueryTimingTests.swift @@ -0,0 +1,96 @@ +// +// QueryTimingTests.swift +// TableProTests +// + +import Foundation +@testable import TablePro +import TableProPluginKit +import Testing + +@Suite("PluginQueryTiming") +struct QueryTimingTests { + @Test("A driver that measured nothing reports the elapsed time as the database time") + func elapsedIsTheFloor() { + let timing = PluginQueryTiming(total: 3.4) + + #expect(timing.databaseTime == 3.4) + #expect(timing.transfer == nil) + #expect(timing.hasBreakdown == false) + } + + @Test("Time to first row stands in for database time when the engine reports none") + func firstRowBeatsElapsed() { + let timing = PluginQueryTiming(total: 3.4, firstRow: 0.012) + + #expect(timing.databaseTime == 0.012) + #expect(timing.transfer == 3.4 - 0.012) + #expect(timing.hasBreakdown) + } + + @Test("The engine's own report outranks the client measurement") + func serverBeatsFirstRow() { + let timing = PluginQueryTiming(total: 3.4, firstRow: 0.012, server: 0.009) + + #expect(timing.databaseTime == 0.009) + } + + /// A clock read on either side of a fast query can land out of order, and a negative transfer + /// would render as a query that finished before it started. + @Test("Transfer never goes negative when the first row outlasts the total") + func transferIsClamped() { + let timing = PluginQueryTiming(total: 0.010, firstRow: 0.012) + + #expect(timing.transfer == 0) + } + + @Test("A batch sums a part only when every statement supplied it") + func batchSumsOnlyCompleteParts() { + let folded = PluginQueryTiming.total(of: [ + PluginQueryTiming(total: 1.0, firstRow: 0.1, server: 0.05), + PluginQueryTiming(total: 2.0, firstRow: 0.2), + ]) + + let firstRow = folded?.firstRow ?? -1 + #expect(folded?.total == 3.0) + #expect(abs(firstRow - 0.3) < 0.000_001) + #expect(folded?.server == nil) + } + + @Test("An empty batch folds to nothing") + func emptyBatchFoldsToNil() { + #expect(PluginQueryTiming.total(of: []) == nil) + } + + @Test("A batch of results with no timing still reports zero rather than nothing") + func emptyResultBatchReportsZero() { + #expect(PluginQueryTiming.batch(of: []).total == 0) + } +} + +@Suite("QueryTimingBreakdown") +struct QueryTimingBreakdownTests { + @Test("Only the parts the driver measured become rows") + func rowsFollowWhatWasMeasured() { + let breakdown = QueryTimingBreakdown(timing: PluginQueryTiming(total: 3.4, firstRow: 0.012)) + + #expect(breakdown.rows.map(\.id) == ["elapsed", "firstRow", "transfer"]) + } + + @Test("A server-reported figure is listed ahead of the client measurement") + func serverLeadsTheClientFigure() { + let breakdown = QueryTimingBreakdown( + timing: PluginQueryTiming(total: 3.4, firstRow: 0.012, server: 0.009) + ) + + #expect(breakdown.rows.map(\.id) == ["elapsed", "server", "firstRow", "transfer"]) + } + + @Test("An unmeasured result reports the elapsed time alone") + func elapsedAlone() { + let breakdown = QueryTimingBreakdown(timing: PluginQueryTiming(total: 3.4)) + + #expect(breakdown.rows.count == 1) + #expect(breakdown.rows[0].id == "elapsed") + } +} diff --git a/TableProTests/Plugins/ClickHouseSummaryParserTests.swift b/TableProTests/Plugins/ClickHouseSummaryParserTests.swift new file mode 100644 index 000000000..6acf4a7b7 --- /dev/null +++ b/TableProTests/Plugins/ClickHouseSummaryParserTests.swift @@ -0,0 +1,66 @@ +// +// ClickHouseSummaryParserTests.swift +// TableProTests +// + +import Foundation +import TableProPluginKit +import Testing + +@Suite("ClickHouseSummaryParser") +struct ClickHouseSummaryParserTests { + @Test("Reads the elapsed nanoseconds a modern server sends") + func readsElapsed() { + let header = """ + {"read_rows":"1000","read_bytes":"8000","written_rows":"0","written_bytes":"0",\ + "total_rows_to_read":"1000","result_rows":"1000","result_bytes":"16000","elapsed_ns":"346699000"} + """ + + let summary = ClickHouseSummaryParser.parse(headerValue: header) + + #expect(summary?.elapsed == 0.346699) + #expect(summary?.readRows == 1_000) + #expect(summary?.readBytes == 8_000) + } + + /// `elapsed_ns` only appears on servers new enough to send it, and a missing figure has to stay + /// missing: a zero would render as a query that took no time at all. + @Test("A server that sends no elapsed figure yields nil rather than zero") + func missingElapsedStaysNil() { + let header = #"{"read_rows":"5","read_bytes":"40"}"# + + let summary = ClickHouseSummaryParser.parse(headerValue: header) + + #expect(summary?.elapsed == nil) + #expect(summary?.readRows == 5) + } + + @Test("Header lookup ignores the case the server used") + func headerLookupIsCaseInsensitive() { + let summary = ClickHouseSummaryParser.parse( + headers: ["x-clickhouse-summary": #"{"elapsed_ns":"1000000"}"#] + ) + + #expect(summary?.elapsed == 0.001) + } + + @Test("An absent header yields nothing") + func absentHeader() { + #expect(ClickHouseSummaryParser.parse(headers: ["Content-Type": "text/plain"]) == nil) + } + + @Test("A body that is not the expected object yields nothing") + func malformedHeader() { + #expect(ClickHouseSummaryParser.parse(headerValue: "not json") == nil) + #expect(ClickHouseSummaryParser.parse(headerValue: "[]") == nil) + #expect(ClickHouseSummaryParser.parse(headerValue: "{}") == nil) + } + + @Test("Unquoted numbers are read as well, in case a server stops quoting them") + func unquotedNumbers() { + let summary = ClickHouseSummaryParser.parse(headerValue: #"{"elapsed_ns":2000000,"read_rows":3}"#) + + #expect(summary?.elapsed == 0.002) + #expect(summary?.readRows == 3) + } +} diff --git a/TableProTests/Plugins/PluginBoundedStreamTimingTests.swift b/TableProTests/Plugins/PluginBoundedStreamTimingTests.swift new file mode 100644 index 000000000..62cac33a7 --- /dev/null +++ b/TableProTests/Plugins/PluginBoundedStreamTimingTests.swift @@ -0,0 +1,107 @@ +// +// PluginBoundedStreamTimingTests.swift +// TableProTests +// + +import Foundation +import TableProPluginKit +import Testing + +@Suite("PluginBoundedStream timing") +struct PluginBoundedStreamTimingTests { + private func stream( + header: PluginStreamHeader, + batches: [(delay: Duration, rows: [PluginRow])] + ) -> AsyncThrowingStream { + AsyncThrowingStream { continuation in + Task { + continuation.yield(.header(header)) + for batch in batches { + try? await Task.sleep(for: batch.delay) + continuation.yield(.rows(batch.rows)) + } + continuation.finish() + } + } + } + + private let header = PluginStreamHeader( + columns: ["a"], + columnTypeNames: ["INT"], + estimatedRowCount: nil + ) + + private let row: PluginRow = [.text("1")] + + /// The capped path is the one an editor `SELECT` without a `LIMIT` actually takes, so a + /// breakdown that only worked on the uncapped path would never be seen. + @Test("The first batch to arrive sets the first-row time") + func firstBatchSetsFirstRow() async throws { + let result = try await PluginBoundedStream.collect( + stream(header: header, batches: [ + (.milliseconds(120), [row]), + (.milliseconds(120), [row]), + ]), + rowCap: 10, + startedAt: Date() + ) + + let firstRow = try #require(result.timing.firstRow) + #expect(firstRow >= 0.1) + #expect(firstRow < result.timing.total) + #expect(result.timing.hasBreakdown) + } + + @Test("A result with no rows reports the whole read as time to first row") + func emptyResultHasNoTransfer() async throws { + let result = try await PluginBoundedStream.collect( + stream(header: header, batches: []), + rowCap: 10, + startedAt: Date() + ) + + let transfer = try #require(result.timing.transfer) + #expect(transfer == 0) + } + + /// An empty batch is not a row, so it must not stop the clock before one arrives. + @Test("An empty batch does not set the first-row time") + func emptyBatchDoesNotStopTheClock() async throws { + let result = try await PluginBoundedStream.collect( + stream(header: header, batches: [ + (.milliseconds(1), []), + (.milliseconds(120), [row]), + ]), + rowCap: 10, + startedAt: Date() + ) + + let firstRow = try #require(result.timing.firstRow) + #expect(firstRow >= 0.1) + } + + @Test("A server figure passed in reaches the result") + func serverElapsedIsCarried() async throws { + let result = try await PluginBoundedStream.collect( + stream(header: header, batches: [(.milliseconds(1), [row])]), + rowCap: 10, + startedAt: Date(), + serverElapsed: 0.042 + ) + + #expect(result.timing.server == 0.042) + #expect(result.timing.databaseTime == 0.042) + } + + @Test("The published overload still yields a timing with no server figure") + func legacyOverloadKeepsWorking() async throws { + let result = try await PluginBoundedStream.collect( + stream(header: header, batches: [(.milliseconds(1), [row])]), + rowCap: 10, + startedAt: Date() + ) + + #expect(result.timing.server == nil) + #expect(result.executionTime == result.timing.total) + } +} diff --git a/TableProTests/Views/Main/QueryFailureReportingTests.swift b/TableProTests/Views/Main/QueryFailureReportingTests.swift index d96e69dc2..40f823198 100644 --- a/TableProTests/Views/Main/QueryFailureReportingTests.swift +++ b/TableProTests/Views/Main/QueryFailureReportingTests.swift @@ -54,12 +54,12 @@ struct QueryFailureReportingTests { func failureClearsTheStaleDuration() { let (coordinator, tabManager) = Self.makeCoordinator() let tabId = Self.addQueryTab(to: tabManager) - coordinator.toolbarState.lastQueryDuration = 1.5 + coordinator.toolbarState.lastQueryTiming = PluginQueryTiming(total: 1.5) let claim = coordinator.tabExecution.claim(tabId) Self.finishFailure(on: coordinator, tabId: tabId, claim: claim) - #expect(coordinator.toolbarState.lastQueryDuration == nil) + #expect(coordinator.toolbarState.lastQueryTiming == nil) #expect(tabManager.tabs.first?.execution.executionTime == nil) } @@ -162,14 +162,14 @@ struct QueryFailureReportingTests { let backgroundTabId = Self.addQueryTab(to: tabManager) let selectedTabId = Self.addQueryTab(to: tabManager, title: "Query 2") tabManager.selectedTabId = selectedTabId - coordinator.toolbarState.lastQueryDuration = 1.5 + coordinator.toolbarState.lastQueryTiming = PluginQueryTiming(total: 1.5) coordinator.toolbarState.isResultsCollapsed = true let claim = coordinator.tabExecution.claim(backgroundTabId) Self.finishFailure(on: coordinator, tabId: backgroundTabId, claim: claim) #expect(tabManager.tabs.first?.execution.errorMessage != nil) - #expect(coordinator.toolbarState.lastQueryDuration == 1.5) + #expect(coordinator.toolbarState.lastQueryTiming?.total == 1.5) #expect(coordinator.toolbarState.isResultsCollapsed) } diff --git a/docs/features/query-history.mdx b/docs/features/query-history.mdx index b18374f41..c02b8fa50 100644 --- a/docs/features/query-history.mdx +++ b/docs/features/query-history.mdx @@ -18,7 +18,7 @@ The drawer opens under the editor and its divider resizes it. Height, filters an Entries group by day, newest first, under **Today**, **Yesterday**, or the date. A row carries the outcome, the query text, the database, the time it ran and how long it took. Under a millisecond reads `<1 ms`; a step whose duration was never measured reads `–` rather than `0 ms`. -Select a row and the right pane shows the full query, highlighted for the database it ran against, with its connection, database and schema, timestamp, duration, row count, source, and the error when it failed. The keyboard stays in the list, so arrow keys keep moving. +Select a row and the right pane shows the full query, highlighted for the database it ran against, with its connection, database and schema, timestamp, duration, row count, source, and the error when it failed. Where the driver separated execution from transfer, the duration is listed as its parts instead: see [How long it took](/features/query-results#how-long-it-took). The keyboard stays in the list, so arrow keys keep moving. Recent queries also appear in [Open Quickly](/features/open-quickly). For the summary rather than the list, see [Query Insights](/features/query-insights). diff --git a/docs/features/query-insights.mdx b/docs/features/query-insights.mdx index 0fb4c4e32..634a5d5f3 100644 --- a/docs/features/query-insights.mdx +++ b/docs/features/query-insights.mdx @@ -20,7 +20,7 @@ Each ranked panel lists the top 10 shapes. Right-click a row for **Copy Query** ### Summary -Across the top: how many queries ran, what share failed, the average duration, and the total time spent waiting. +Across the top: how many queries ran, what share failed, the average duration, and the total duration. ### Activity @@ -52,7 +52,9 @@ Shapes ranked by how many times they failed, with the most recent error message A row in **Slowest** or **Got Slower** is a shape, not a diagnosis. **Load in Editor** puts a real example in a query tab, where `Cmd+Option+E` gives you the execution plan: see [Explain Visualization](/features/explain-visualization). -Durations are measured on this side of the wire, from sending the query to getting the result, so they cover network time and any [SSH tunnel](/connections/ssh-profiles) as well as the server. For server-side timings, locks and running queries, see the [Server Dashboard](/features/server-dashboard). +Every duration on this page is the time the database spent, not the time you waited. On an engine that reports its own execution time that figure is used; on one that does not, the time to the first row stands in, which carries one network round trip. Where neither is available the whole elapsed time is used, and a query that is only slow to transfer then ranks as a slow query. The [results readout](/features/query-results#how-long-it-took) shows which figure a given engine supplies. + +For locks and running queries, see the [Server Dashboard](/features/server-dashboard). A shape ranked high under **Table Browsing** came from the app paging or sorting a table, not from anything you wrote. diff --git a/docs/features/query-results.mdx b/docs/features/query-results.mdx index fa7b20d32..9b73bd185 100644 --- a/docs/features/query-results.mdx +++ b/docs/features/query-results.mdx @@ -39,6 +39,23 @@ Picking a result moves the editor cursor to the statement that produced it and u The results panel expands itself when a query runs. The toolbar's trash button clears the query and the results together; to keep the query, right-click the results and choose **Clear Results**. +## How long it took + +The toolbar's right side reads the elapsed time of the last query, from sending it to having the last row. On a remote server, or through an [SSH tunnel](/connections/ssh-profiles), most of a large result's elapsed time is transfer rather than the query. + +Click the number for the split. + +| Row | What it measures | +|---|---| +| Elapsed | Sending the query to having the last row | +| Server | Execution time the engine reported for itself, with no network in it | +| First row | Sending the query to the first row arriving, including one network round trip | +| Transfer | The rest of the elapsed time, spent moving rows | + +A long **Transfer** behind a quick **Server** or **First row** is a slow link or a wide result, not a slow query. + +MySQL, MariaDB, PostgreSQL, CockroachDB, Redshift, ClickHouse and BigQuery report **First row**. BigQuery adds **Server** from its job statistics, and ClickHouse adds it on a query that returns no rows, where the summary arrives as a header the client sees. Every other engine shows the elapsed time on its own, and the number does not open. + ## The row cap A query that returns rows and carries no `LIMIT`, `FETCH FIRST` or `TOP` of its own stops at the row cap: `SELECT`, `WITH`, `TABLE`, `VALUES`, and a set operation whose arms are parenthesised.