From c01d56addaa4a4962a83b10783700bfe854e30c7 Mon Sep 17 00:00:00 2001 From: Ngo Quoc Dat Date: Wed, 2 Sep 2026 16:47:23 +0700 Subject: [PATCH] feat(editor): split a query's duration into server, first row and transfer Claude-Session: https://claude.ai/code/session_015EwoyM9XPxsVV75m48Noqa --- CHANGELOG.md | 9 + Plugins/BeancountDriverPlugin/Info.plist | 2 +- .../BigQueryConnection.swift | 34 ++- .../BigQueryPluginDriver.swift | 48 +++- Plugins/BigQueryDriverPlugin/Info.plist | 2 +- Plugins/CSVExportPlugin/Info.plist | 2 +- Plugins/CSVImportPlugin/Info.plist | 2 +- Plugins/CassandraDriverPlugin/Info.plist | 2 +- .../ClickHousePlugin.swift | 8 +- .../ClickHousePluginDriver+Http.swift | 6 +- Plugins/ClickHouseDriverPlugin/Info.plist | 2 +- Plugins/CloudflareD1DriverPlugin/Info.plist | 2 +- Plugins/DamengDriverPlugin/Info.plist | 2 +- Plugins/DuckDBDriverPlugin/Info.plist | 2 +- Plugins/DynamoDBDriverPlugin/Info.plist | 2 +- Plugins/ElasticsearchDriverPlugin/Info.plist | 2 +- Plugins/EtcdDriverPlugin/Info.plist | 2 +- Plugins/JSONExportPlugin/Info.plist | 2 +- Plugins/JSONImportPlugin/Info.plist | 2 +- Plugins/KafkaDriverPlugin/Info.plist | 2 +- Plugins/LibSQLDriverPlugin/Info.plist | 2 +- Plugins/MQLExportPlugin/Info.plist | 2 +- Plugins/MSSQLDriverPlugin/Info.plist | 2 +- Plugins/MongoDBDriverPlugin/Info.plist | 2 +- Plugins/MySQLDriverPlugin/Info.plist | 2 +- .../MariaDBPluginConnection.swift | 43 +++- .../MySQLDriverPlugin/MySQLPluginDriver.swift | 20 +- Plugins/OracleDriverPlugin/Info.plist | 2 +- Plugins/PostgreSQLDriverPlugin/Info.plist | 2 +- .../LibPQDriverCore.swift | 5 +- .../LibPQPluginConnection.swift | 15 +- Plugins/RedisDriverPlugin/Info.plist | 2 +- Plugins/SQLExportPlugin/Info.plist | 2 +- Plugins/SQLImportPlugin/Info.plist | 2 +- Plugins/SQLiteDriverPlugin/Info.plist | 2 +- Plugins/SnowflakeDriverPlugin/Info.plist | 2 +- Plugins/SurrealDBDriverPlugin/Info.plist | 2 +- .../ClickHouseSummaryParser.swift | 61 +++++ .../PluginBoundedStream.swift | 24 +- .../TableProPluginKit/PluginQueryResult.swift | 52 +++- .../TableProPluginKit/PluginQueryTiming.swift | 47 ++++ Plugins/TeradataDriverPlugin/Info.plist | 2 +- Plugins/TrinoDriverPlugin/Info.plist | 2 +- Plugins/XLSXExportPlugin/Info.plist | 2 +- .../Coordinators/PaginationCoordinator.swift | 2 +- .../QueryExecutionCoordinator+Helpers.swift | 17 +- ...yExecutionCoordinator+MultiStatement.swift | 8 +- ...QueryExecutionCoordinator+Parameters.swift | 21 +- .../Core/Plugins/PluginDriverAdapter.swift | 1 + TablePro/Core/Plugins/PluginManager.swift | 20 +- .../Core/Services/Query/QueryExecutor.swift | 16 +- .../Core/Storage/QueryHistoryManager.swift | 5 +- .../Core/Storage/QueryHistoryStorage.swift | 67 +++++- .../ClickHouse/ClickHouseQueryProgress.swift | 52 ---- .../Connection/ConnectionToolbarState.swift | 14 +- TablePro/Models/Query/QueryHistoryEntry.swift | 25 +- .../Query/QueryHistoryRecordRequest.swift | 9 +- TablePro/Models/Query/QueryResult.swift | 8 + .../Models/Query/QueryTimingAggregation.swift | 38 +++ .../Editor/History/HistoryDetailPane.swift | 18 +- .../MainContentCoordinator+ClickHouse.swift | 22 -- .../MainContentCoordinator+QueryHelpers.swift | 6 +- .../Views/Main/MainContentCoordinator.swift | 14 +- .../Toolbar/ExecutionIndicatorView.swift | 115 +++++---- .../Views/Toolbar/QueryTimingBreakdown.swift | 87 +++++++ .../Views/Toolbar/TableProToolbarView.swift | 4 +- .../CancelledExecutionOwnershipTests.swift | 2 +- .../Storage/QueryHistoryMigrationTests.swift | 4 +- .../Storage/QueryHistoryTimingTests.swift | 224 ++++++++++++++++++ TableProTests/Models/QueryTimingTests.swift | 96 ++++++++ .../ClickHouseSummaryParserTests.swift | 66 ++++++ .../PluginBoundedStreamTimingTests.swift | 107 +++++++++ .../Main/QueryFailureReportingTests.swift | 8 +- docs/development/plugin-development.mdx | 2 +- docs/development/plugin-registry.mdx | 4 +- docs/features/query-history.mdx | 2 +- docs/features/query-insights.mdx | 6 +- docs/features/query-results.mdx | 17 ++ 78 files changed, 1268 insertions(+), 273 deletions(-) create mode 100644 Plugins/TableProPluginKit/ClickHouseSummaryParser.swift create mode 100644 Plugins/TableProPluginKit/PluginQueryTiming.swift delete mode 100644 TablePro/Models/ClickHouse/ClickHouseQueryProgress.swift create mode 100644 TablePro/Models/Query/QueryTimingAggregation.swift delete mode 100644 TablePro/Views/Main/Extensions/MainContentCoordinator+ClickHouse.swift create mode 100644 TablePro/Views/Toolbar/QueryTimingBreakdown.swift create mode 100644 TableProTests/Core/Storage/QueryHistoryTimingTests.swift create mode 100644 TableProTests/Models/QueryTimingTests.swift create mode 100644 TableProTests/Plugins/ClickHouseSummaryParserTests.swift create mode 100644 TableProTests/Plugins/PluginBoundedStreamTimingTests.swift diff --git a/CHANGELOG.md b/CHANGELOG.md index e6bfdb2564..c792e635a7 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,15 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +### Added + +- Breakdown of a query's time into server, first row and transfer, behind the toolbar's duration readout. (#2503) + +### Changed + +- Query Insights ranks on the time the database spent rather than on elapsed time. (#2503) +- PluginKit ABI 21. Every registry plugin needs rebuilding before or with this release. + ## [0.71.0] - 2026-09-02 ### Added diff --git a/Plugins/BeancountDriverPlugin/Info.plist b/Plugins/BeancountDriverPlugin/Info.plist index 173ac7d820..8618e2f4d7 100644 --- a/Plugins/BeancountDriverPlugin/Info.plist +++ b/Plugins/BeancountDriverPlugin/Info.plist @@ -3,7 +3,7 @@ TableProPluginKitVersion - 20 + 21 TableProProvidesDatabaseTypeIds Beancount diff --git a/Plugins/BigQueryDriverPlugin/BigQueryConnection.swift b/Plugins/BigQueryDriverPlugin/BigQueryConnection.swift index 34545cb565..1fc0700d90 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 3f9105ab40..26a42e8873 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/BigQueryDriverPlugin/Info.plist b/Plugins/BigQueryDriverPlugin/Info.plist index d2cce4dc9e..4dafd54bc9 100644 --- a/Plugins/BigQueryDriverPlugin/Info.plist +++ b/Plugins/BigQueryDriverPlugin/Info.plist @@ -5,6 +5,6 @@ TableProMinAppVersion 0.42.0 TableProPluginKitVersion - 20 + 21 diff --git a/Plugins/CSVExportPlugin/Info.plist b/Plugins/CSVExportPlugin/Info.plist index aab4558fc9..b4a776c7b3 100644 --- a/Plugins/CSVExportPlugin/Info.plist +++ b/Plugins/CSVExportPlugin/Info.plist @@ -3,7 +3,7 @@ TableProPluginKitVersion - 20 + 21 TableProProvidesExportFormatIds csv diff --git a/Plugins/CSVImportPlugin/Info.plist b/Plugins/CSVImportPlugin/Info.plist index 121d712908..d6b8b25a3a 100644 --- a/Plugins/CSVImportPlugin/Info.plist +++ b/Plugins/CSVImportPlugin/Info.plist @@ -3,7 +3,7 @@ TableProPluginKitVersion - 20 + 21 TableProProvidesImportFormatIds csv diff --git a/Plugins/CassandraDriverPlugin/Info.plist b/Plugins/CassandraDriverPlugin/Info.plist index d73d6826ce..dd93807516 100644 --- a/Plugins/CassandraDriverPlugin/Info.plist +++ b/Plugins/CassandraDriverPlugin/Info.plist @@ -21,6 +21,6 @@ NSPrincipalClass $(PRODUCT_MODULE_NAME).CassandraPlugin TableProPluginKitVersion - 20 + 21 diff --git a/Plugins/ClickHouseDriverPlugin/ClickHousePlugin.swift b/Plugins/ClickHouseDriverPlugin/ClickHousePlugin.swift index c26f9a1d20..baba9448e0 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 1ec6b5a3d1..c14d0f002b 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/ClickHouseDriverPlugin/Info.plist b/Plugins/ClickHouseDriverPlugin/Info.plist index a7fa58059e..a22345aad3 100644 --- a/Plugins/ClickHouseDriverPlugin/Info.plist +++ b/Plugins/ClickHouseDriverPlugin/Info.plist @@ -3,7 +3,7 @@ TableProPluginKitVersion - 20 + 21 TableProProvidesDatabaseTypeIds ClickHouse diff --git a/Plugins/CloudflareD1DriverPlugin/Info.plist b/Plugins/CloudflareD1DriverPlugin/Info.plist index d2cce4dc9e..4dafd54bc9 100644 --- a/Plugins/CloudflareD1DriverPlugin/Info.plist +++ b/Plugins/CloudflareD1DriverPlugin/Info.plist @@ -5,6 +5,6 @@ TableProMinAppVersion 0.42.0 TableProPluginKitVersion - 20 + 21 diff --git a/Plugins/DamengDriverPlugin/Info.plist b/Plugins/DamengDriverPlugin/Info.plist index 0fdf6f0c92..6a412d916c 100644 --- a/Plugins/DamengDriverPlugin/Info.plist +++ b/Plugins/DamengDriverPlugin/Info.plist @@ -3,7 +3,7 @@ TableProPluginKitVersion - 20 + 21 TableProProvidesDatabaseTypeIds Dameng diff --git a/Plugins/DuckDBDriverPlugin/Info.plist b/Plugins/DuckDBDriverPlugin/Info.plist index c271ca1f66..bb241b15a9 100644 --- a/Plugins/DuckDBDriverPlugin/Info.plist +++ b/Plugins/DuckDBDriverPlugin/Info.plist @@ -3,6 +3,6 @@ TableProPluginKitVersion - 20 + 21 diff --git a/Plugins/DynamoDBDriverPlugin/Info.plist b/Plugins/DynamoDBDriverPlugin/Info.plist index d2cce4dc9e..4dafd54bc9 100644 --- a/Plugins/DynamoDBDriverPlugin/Info.plist +++ b/Plugins/DynamoDBDriverPlugin/Info.plist @@ -5,6 +5,6 @@ TableProMinAppVersion 0.42.0 TableProPluginKitVersion - 20 + 21 diff --git a/Plugins/ElasticsearchDriverPlugin/Info.plist b/Plugins/ElasticsearchDriverPlugin/Info.plist index c679a35746..a631ed7e96 100644 --- a/Plugins/ElasticsearchDriverPlugin/Info.plist +++ b/Plugins/ElasticsearchDriverPlugin/Info.plist @@ -5,6 +5,6 @@ TableProMinAppVersion 0.53.0 TableProPluginKitVersion - 20 + 21 diff --git a/Plugins/EtcdDriverPlugin/Info.plist b/Plugins/EtcdDriverPlugin/Info.plist index d2cce4dc9e..4dafd54bc9 100644 --- a/Plugins/EtcdDriverPlugin/Info.plist +++ b/Plugins/EtcdDriverPlugin/Info.plist @@ -5,6 +5,6 @@ TableProMinAppVersion 0.42.0 TableProPluginKitVersion - 20 + 21 diff --git a/Plugins/JSONExportPlugin/Info.plist b/Plugins/JSONExportPlugin/Info.plist index aa0d8bbb0c..ce6a23c40e 100644 --- a/Plugins/JSONExportPlugin/Info.plist +++ b/Plugins/JSONExportPlugin/Info.plist @@ -3,7 +3,7 @@ TableProPluginKitVersion - 20 + 21 TableProProvidesExportFormatIds json diff --git a/Plugins/JSONImportPlugin/Info.plist b/Plugins/JSONImportPlugin/Info.plist index 39fca1807d..0cd60a2a64 100644 --- a/Plugins/JSONImportPlugin/Info.plist +++ b/Plugins/JSONImportPlugin/Info.plist @@ -3,7 +3,7 @@ TableProPluginKitVersion - 20 + 21 TableProProvidesImportFormatIds json diff --git a/Plugins/KafkaDriverPlugin/Info.plist b/Plugins/KafkaDriverPlugin/Info.plist index 16959124e2..536864492a 100644 --- a/Plugins/KafkaDriverPlugin/Info.plist +++ b/Plugins/KafkaDriverPlugin/Info.plist @@ -3,7 +3,7 @@ TableProPluginKitVersion - 20 + 21 TableProProvidesDatabaseTypeIds Kafka diff --git a/Plugins/LibSQLDriverPlugin/Info.plist b/Plugins/LibSQLDriverPlugin/Info.plist index d2cce4dc9e..4dafd54bc9 100644 --- a/Plugins/LibSQLDriverPlugin/Info.plist +++ b/Plugins/LibSQLDriverPlugin/Info.plist @@ -5,6 +5,6 @@ TableProMinAppVersion 0.42.0 TableProPluginKitVersion - 20 + 21 diff --git a/Plugins/MQLExportPlugin/Info.plist b/Plugins/MQLExportPlugin/Info.plist index cb01349dac..a755e4d4ed 100644 --- a/Plugins/MQLExportPlugin/Info.plist +++ b/Plugins/MQLExportPlugin/Info.plist @@ -3,7 +3,7 @@ TableProPluginKitVersion - 20 + 21 TableProProvidesExportFormatIds mql diff --git a/Plugins/MSSQLDriverPlugin/Info.plist b/Plugins/MSSQLDriverPlugin/Info.plist index c271ca1f66..bb241b15a9 100644 --- a/Plugins/MSSQLDriverPlugin/Info.plist +++ b/Plugins/MSSQLDriverPlugin/Info.plist @@ -3,6 +3,6 @@ TableProPluginKitVersion - 20 + 21 diff --git a/Plugins/MongoDBDriverPlugin/Info.plist b/Plugins/MongoDBDriverPlugin/Info.plist index c271ca1f66..bb241b15a9 100644 --- a/Plugins/MongoDBDriverPlugin/Info.plist +++ b/Plugins/MongoDBDriverPlugin/Info.plist @@ -3,6 +3,6 @@ TableProPluginKitVersion - 20 + 21 diff --git a/Plugins/MySQLDriverPlugin/Info.plist b/Plugins/MySQLDriverPlugin/Info.plist index 2c3d7b025b..f05c54ac77 100644 --- a/Plugins/MySQLDriverPlugin/Info.plist +++ b/Plugins/MySQLDriverPlugin/Info.plist @@ -3,7 +3,7 @@ TableProPluginKitVersion - 20 + 21 TableProProvidesDatabaseTypeIds MySQL diff --git a/Plugins/MySQLDriverPlugin/MariaDBPluginConnection.swift b/Plugins/MySQLDriverPlugin/MariaDBPluginConnection.swift index 7a9bc1e7e5..6a88f587bf 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 5c1c89d4be..6dc890f968 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/OracleDriverPlugin/Info.plist b/Plugins/OracleDriverPlugin/Info.plist index c271ca1f66..bb241b15a9 100644 --- a/Plugins/OracleDriverPlugin/Info.plist +++ b/Plugins/OracleDriverPlugin/Info.plist @@ -3,6 +3,6 @@ TableProPluginKitVersion - 20 + 21 diff --git a/Plugins/PostgreSQLDriverPlugin/Info.plist b/Plugins/PostgreSQLDriverPlugin/Info.plist index d0b1fcf6b0..e3243ea198 100644 --- a/Plugins/PostgreSQLDriverPlugin/Info.plist +++ b/Plugins/PostgreSQLDriverPlugin/Info.plist @@ -3,7 +3,7 @@ TableProPluginKitVersion - 20 + 21 TableProProvidesDatabaseTypeIds PostgreSQL diff --git a/Plugins/PostgreSQLDriverPlugin/LibPQDriverCore.swift b/Plugins/PostgreSQLDriverPlugin/LibPQDriverCore.swift index cbb9bcbdfe..c3044a15e4 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 635c7bb3fd..24b9bbb9a0 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/RedisDriverPlugin/Info.plist b/Plugins/RedisDriverPlugin/Info.plist index ebc80fdb94..747e5ba196 100644 --- a/Plugins/RedisDriverPlugin/Info.plist +++ b/Plugins/RedisDriverPlugin/Info.plist @@ -21,7 +21,7 @@ NSPrincipalClass $(PRODUCT_MODULE_NAME).RedisPlugin TableProPluginKitVersion - 20 + 21 TableProProvidesDatabaseTypeIds Redis diff --git a/Plugins/SQLExportPlugin/Info.plist b/Plugins/SQLExportPlugin/Info.plist index 77b02579e0..dcd0cf36bd 100644 --- a/Plugins/SQLExportPlugin/Info.plist +++ b/Plugins/SQLExportPlugin/Info.plist @@ -3,7 +3,7 @@ TableProPluginKitVersion - 20 + 21 TableProProvidesExportFormatIds sql diff --git a/Plugins/SQLImportPlugin/Info.plist b/Plugins/SQLImportPlugin/Info.plist index 64945bd719..632b66b796 100644 --- a/Plugins/SQLImportPlugin/Info.plist +++ b/Plugins/SQLImportPlugin/Info.plist @@ -3,7 +3,7 @@ TableProPluginKitVersion - 20 + 21 TableProProvidesImportFormatIds sql diff --git a/Plugins/SQLiteDriverPlugin/Info.plist b/Plugins/SQLiteDriverPlugin/Info.plist index 426f9a62fa..3121d1beb3 100644 --- a/Plugins/SQLiteDriverPlugin/Info.plist +++ b/Plugins/SQLiteDriverPlugin/Info.plist @@ -3,7 +3,7 @@ TableProPluginKitVersion - 20 + 21 TableProProvidesDatabaseTypeIds SQLite diff --git a/Plugins/SnowflakeDriverPlugin/Info.plist b/Plugins/SnowflakeDriverPlugin/Info.plist index 7eb4de381f..698e9fa1e2 100644 --- a/Plugins/SnowflakeDriverPlugin/Info.plist +++ b/Plugins/SnowflakeDriverPlugin/Info.plist @@ -5,6 +5,6 @@ TableProMinAppVersion 0.48.0 TableProPluginKitVersion - 20 + 21 diff --git a/Plugins/SurrealDBDriverPlugin/Info.plist b/Plugins/SurrealDBDriverPlugin/Info.plist index 535b56f87c..86b0bf7baf 100644 --- a/Plugins/SurrealDBDriverPlugin/Info.plist +++ b/Plugins/SurrealDBDriverPlugin/Info.plist @@ -3,7 +3,7 @@ TableProPluginKitVersion - 20 + 21 TableProProvidesDatabaseTypeIds SurrealDB diff --git a/Plugins/TableProPluginKit/ClickHouseSummaryParser.swift b/Plugins/TableProPluginKit/ClickHouseSummaryParser.swift new file mode 100644 index 0000000000..5add2c61dd --- /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 251079ccad..15deee830f 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 d2d69ad1a4..c660134850 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 0000000000..d6a048c18e --- /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/Plugins/TeradataDriverPlugin/Info.plist b/Plugins/TeradataDriverPlugin/Info.plist index c271ca1f66..bb241b15a9 100644 --- a/Plugins/TeradataDriverPlugin/Info.plist +++ b/Plugins/TeradataDriverPlugin/Info.plist @@ -3,6 +3,6 @@ TableProPluginKitVersion - 20 + 21 diff --git a/Plugins/TrinoDriverPlugin/Info.plist b/Plugins/TrinoDriverPlugin/Info.plist index c271ca1f66..bb241b15a9 100644 --- a/Plugins/TrinoDriverPlugin/Info.plist +++ b/Plugins/TrinoDriverPlugin/Info.plist @@ -3,6 +3,6 @@ TableProPluginKitVersion - 20 + 21 diff --git a/Plugins/XLSXExportPlugin/Info.plist b/Plugins/XLSXExportPlugin/Info.plist index 4b81c4c361..3477527ac7 100644 --- a/Plugins/XLSXExportPlugin/Info.plist +++ b/Plugins/XLSXExportPlugin/Info.plist @@ -3,7 +3,7 @@ TableProPluginKitVersion - 20 + 21 TableProProvidesExportFormatIds xlsx diff --git a/TablePro/Core/Coordinators/PaginationCoordinator.swift b/TablePro/Core/Coordinators/PaginationCoordinator.swift index 95b22d0d33..d50bda61f6 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 ec855807fb..6ca64a6121 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 5ece7e57d8..9cf02bd82b 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 1efe11160e..2979a37091 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 acb1a05d0b..16415bdfc7 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 a76f4fe727..7641efc587 100644 --- a/TablePro/Core/Plugins/PluginManager.swift +++ b/TablePro/Core/Plugins/PluginManager.swift @@ -14,16 +14,18 @@ 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 `PluginQueryTiming` and the `PluginQueryResult` initializer that carries it. /// - /// 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. - nonisolated static let currentPluginKitVersion = 20 + /// Raised to 20 before that for the whole-schema index and table metadata requirements. + /// + /// Every one of these additions 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. 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. nonisolated static let minimumCompatiblePluginKitVersion = 19 diff --git a/TablePro/Core/Services/Query/QueryExecutor.swift b/TablePro/Core/Services/Query/QueryExecutor.swift index 9582db187d..19ff353ec7 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 e189640d69..f287c7f0f9 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 b3197db6d2..a0a2c1e91a 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 d879a675d8..0000000000 --- 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 6b4d7b63c6..f7b3e1171d 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 1c118bfc02..48db35dbd2 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 99bca8310e..8ff062c060 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 0d5e960cb0..0d6cbbff8c 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 0000000000..c4dfccda8e --- /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 04132ef975..bd1d9a1fda 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 a25a97ffd4..0000000000 --- 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 a762f6edf5..6bbbfdb2e7 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 d879edbb81..acd151ac69 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 2f0035f383..51b5683f74 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 0000000000..62f652b7e4 --- /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 095c4c0b83..4ac51fa6b0 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 14aaaec7f9..810d1c980e 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 34d619aca8..639e2025b7 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 0000000000..242818ef5d --- /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 0000000000..47989eebff --- /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 0000000000..6acf4a7b78 --- /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 0000000000..62cac33a70 --- /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 d96e69dc2a..40f8231984 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/development/plugin-development.mdx b/docs/development/plugin-development.mdx index 5755f33b89..1d4f7fd3a8 100644 --- a/docs/development/plugin-development.mdx +++ b/docs/development/plugin-development.mdx @@ -13,7 +13,7 @@ A plugin is a macOS loadable bundle target with `WRAPPER_EXTENSION = tableplugin | Key | Type | Required | Purpose | |-----|------|----------|---------| -| `TableProPluginKitVersion` | integer | Yes | The PluginKit ABI the plugin was built against. Current value: 20 | +| `TableProPluginKitVersion` | integer | Yes | The PluginKit ABI the plugin was built against. Current value: 21 | | `TableProProvidesDatabaseTypeIds` | array of strings | Recommended | Database type IDs the plugin serves, which is what makes lazy loading possible | | `CFBundleShortVersionString` | string | Yes | Plugin version, read by registry update checks | | `TableProMinAppVersion` | string | No | The loader rejects the plugin on an older app | diff --git a/docs/development/plugin-registry.mdx b/docs/development/plugin-registry.mdx index bbc54b2a82..8f21729f59 100644 --- a/docs/development/plugin-registry.mdx +++ b/docs/development/plugin-registry.mdx @@ -68,13 +68,13 @@ Themes carry no native code, so they match on architecture alone. "binaries": [ { "architecture": "arm64", - "pluginKitVersion": 20, + "pluginKitVersion": 21, "downloadURL": "https://github.com/TableProApp/TablePro/releases/download/plugin-oracle-v1.0.26/OracleDriver-arm64.zip", "sha256": "" }, { "architecture": "x86_64", - "pluginKitVersion": 20, + "pluginKitVersion": 21, "downloadURL": "https://github.com/TableProApp/TablePro/releases/download/plugin-oracle-v1.0.26/OracleDriver-x86_64.zip", "sha256": "" } diff --git a/docs/features/query-history.mdx b/docs/features/query-history.mdx index b18374f419..c02b8fa50d 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 0fb4c4e328..634a5d5f3c 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 fa7b20d32a..9b73bd1858 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.