From 3057900f11d599329624d9a216e48183a1bea9a9 Mon Sep 17 00:00:00 2001 From: Prem Palanisamy Date: Mon, 18 May 2026 06:32:31 +0100 Subject: [PATCH 01/16] feat explain idx --- src/Database/Adapter.php | 157 +++++++++++++++++++++ src/Database/Adapter/Mongo.php | 21 +++ src/Database/Adapter/Postgres.php | 53 +++++++ src/Database/Adapter/SQL.php | 163 ++++++++++++++++++++++ src/Database/Database.php | 45 ++++++ tests/e2e/Adapter/Base.php | 2 + tests/e2e/Adapter/Scopes/ExplainTests.php | 140 +++++++++++++++++++ tests/unit/ExplainTest.php | 111 +++++++++++++++ 8 files changed, 692 insertions(+) create mode 100644 tests/e2e/Adapter/Scopes/ExplainTests.php create mode 100644 tests/unit/ExplainTest.php diff --git a/src/Database/Adapter.php b/src/Database/Adapter.php index ef0598341..a49903a59 100644 --- a/src/Database/Adapter.php +++ b/src/Database/Adapter.php @@ -40,6 +40,34 @@ abstract class Adapter */ protected array $debug = []; + /** + * Captured query plans while inside Database::withExplain(). + * - null = capture disabled (the normal mode; reads pay nothing extra) + * - array = capture enabled; each entry is one explained read + * + * Mirrors the preserveDates / validate / resolveRelationships scoped-flag + * pattern: a single inline null-check on hot paths, opt-in only via the + * matching with*() method on Database. + * + * @var ?array> + */ + protected ?array $explainBuffer = null; + + /** + * Maps internal column names back to user-facing names in plan output. + * Single source of truth for the rename — same shape used by find()'s + * result post-processing in the SQL/Mongo adapters. + * + * @var array + */ + protected const EXPLAIN_COLUMN_RENAMES = [ + '_uid' => '$id', + '_createdAt' => '$createdAt', + '_updatedAt' => '$updatedAt', + '_permissions' => '$permissions', + '_tenant' => '$tenant', + ]; + /** * @var array> */ @@ -104,6 +132,135 @@ public function resetDebug(): static return $this; } + /** + * Begin capturing query plans for subsequent reads on this adapter. + * + * Pairs with stopExplainCapture(). Called by Database::withExplain() to + * open the scope; not intended for direct caller use. + */ + public function startExplainCapture(): void + { + $this->explainBuffer = []; + } + + /** + * Stop capturing and return the buffered query plans, clearing the buffer. + * + * @return array> + */ + public function stopExplainCapture(): array + { + $captured = $this->explainBuffer ?? []; + $this->explainBuffer = null; + return $captured; + } + + /** + * True while inside an active capture scope. + */ + public function isExplainCapturing(): bool + { + return $this->explainBuffer !== null; + } + + /** + * Adapter-internal hook: when a read is about to execute and capture is + * active, run vendor-native EXPLAIN against the same SQL+binds, sanitize + * the result (hiding internal _perms / _metadata references and renaming + * internal columns), and append to the buffer. + * + * Hot paths invoke this only after an inline `$this->explainBuffer !== null` + * check, so when capture is disabled there is no method-call cost. + * + * @param string $sql + * @param array $binds + * @param string $purpose 'find' | 'count' | 'sum' | adapter-defined + * @param array $context optional metadata (collection id, relation key, etc.) + */ + protected function capturePlan(string $sql, array $binds = [], string $purpose = 'find', array $context = []): void + { + try { + $plan = $this->explainSQL($sql, $binds); + $plan = $this->sanitizePlan($plan); + } catch (\Throwable $e) { + $plan = ['error' => $e->getMessage()]; + } + + $this->explainBuffer[] = [ + 'purpose' => $purpose, + 'context' => $context, + 'plan' => $plan, + ]; + } + + /** + * Strip Appwrite-internal storage details from a raw vendor plan before + * surfacing it to callers: + * - Tables ending in `_perms` are summarized as "" + * - The `__metadata` system table is summarized as "" + * - Internal column names (_uid, _createdAt, ...) are renamed to their + * user-facing form ($id, $createdAt, ...) + * + * Walks any nested array/object structure recursively; safe for arbitrary + * vendor-specific plan shapes. + * + * @param array $plan + * @return array + */ + protected function sanitizePlan(array $plan): array + { + return $this->sanitizePlanNode($plan); + } + + /** + * @param mixed $node + * @return mixed + */ + private function sanitizePlanNode(mixed $node): mixed + { + if (\is_array($node)) { + $result = []; + foreach ($node as $key => $value) { + $newKey = \is_string($key) ? $this->renameInternalIdentifier($key) : $key; + $result[$newKey] = $this->sanitizePlanNode($value); + } + return $result; + } + + if (\is_string($node)) { + return $this->renameInternalIdentifier($node); + } + + return $node; + } + + /** + * Apply the public-facing rename to a single identifier string. + * Conservatively matches table suffixes (`_perms`, `__metadata`) and exact + * internal column names from EXPLAIN_COLUMN_RENAMES. + */ + private function renameInternalIdentifier(string $name): string + { + if (\str_ends_with($name, '__metadata')) { + return ''; + } + if (\str_ends_with($name, '_perms')) { + return ''; + } + return self::EXPLAIN_COLUMN_RENAMES[$name] ?? $name; + } + + /** + * Vendor-specific EXPLAIN implementation. Receives the SQL + bindings that + * would otherwise be executed; must return the raw (unsanitized) plan as + * an associative array. Sanitization is applied centrally by capturePlan(). + * + * @param string $sql + * @param array $binds + * @return array + */ + abstract protected function explainSQL(string $sql, array $binds = []): array; + /** * Set Namespace. * diff --git a/src/Database/Adapter/Mongo.php b/src/Database/Adapter/Mongo.php index bc6d79638..c8a842fbe 100644 --- a/src/Database/Adapter/Mongo.php +++ b/src/Database/Adapter/Mongo.php @@ -3592,6 +3592,27 @@ public function getKeywords(): array return []; } + /** + * Mongo doesn't speak SQL — its "plan" comes from `$cursor->explain()` / + * aggregation `executionStats` against a built command document, not a + * SQL string. Satisfying the abstract contract with a stub here keeps the + * adapter loadable; real Mongo capture will be wired in a follow-up that + * hooks `find()`/`count()`/`sum()` to call the driver-native explain on + * the cursor before executing it. + * + * @param string $sql + * @param array $binds + * @return array + */ + protected function explainSQL(string $sql, array $binds = []): array + { + return [ + 'engine' => 'mongo', + 'tree' => null, + 'note' => 'Mongo explain capture is not yet implemented; use cursor->explain() at the find() level', + ]; + } + protected function processException(\Throwable $e): \Throwable { // Timeout diff --git a/src/Database/Adapter/Postgres.php b/src/Database/Adapter/Postgres.php index d81cdec0b..513624037 100644 --- a/src/Database/Adapter/Postgres.php +++ b/src/Database/Adapter/Postgres.php @@ -1578,6 +1578,59 @@ public function getConnectionId(): string return $stmt->fetchColumn(); } + /** + * Postgres equivalent of the MySQL EXPLAIN FORMAT=JSON override in SQL. + * Uses the `EXPLAIN (FORMAT JSON)` form (parenthesized options) and + * extracts `Plan Rows` / `Index Name` / `Total Cost` from the top-level + * Plan node so the headline fields line up with the MySQL adapter. + * + * @param string $sql + * @param array $binds + * @return array + */ + protected function explainSQL(string $sql, array $binds = []): array + { + $explainSql = 'EXPLAIN (FORMAT JSON) ' . \ltrim($sql); + + $stmt = $this->getPDO()->prepare($explainSql); + + foreach ($binds as $key => $value) { + if (\gettype($value) === 'double') { + $stmt->bindValue($key, $this->getFloatPrecision($value), \PDO::PARAM_STR); + } else { + $stmt->bindValue($key, $value, $this->getPDOType($value)); + } + } + + $stmt->execute(); + $raw = $stmt->fetchColumn(); + $stmt->closeCursor(); + + $decoded = \is_string($raw) ? \json_decode($raw, true) : null; + // Postgres wraps the plan in a one-element array. + $tree = (\is_array($decoded) && isset($decoded[0]) && \is_array($decoded[0])) + ? $decoded[0] + : null; + + $rootPlan = (\is_array($tree) && isset($tree['Plan']) && \is_array($tree['Plan'])) + ? $tree['Plan'] + : null; + + return [ + 'engine' => 'sql', + 'rowsScanned' => (\is_array($rootPlan) && isset($rootPlan['Plan Rows']) && \is_numeric($rootPlan['Plan Rows'])) + ? (int) $rootPlan['Plan Rows'] + : null, + 'indexUsed' => (\is_array($rootPlan) && isset($rootPlan['Index Name']) && \is_string($rootPlan['Index Name'])) + ? $rootPlan['Index Name'] + : null, + 'estimatedCost' => (\is_array($rootPlan) && isset($rootPlan['Total Cost']) && \is_numeric($rootPlan['Total Cost'])) + ? (float) $rootPlan['Total Cost'] + : null, + 'tree' => $tree, + ]; + } + /** * Handle distance spatial queries * diff --git a/src/Database/Adapter/SQL.php b/src/Database/Adapter/SQL.php index 4d640c900..c67462513 100644 --- a/src/Database/Adapter/SQL.php +++ b/src/Database/Adapter/SQL.php @@ -2526,6 +2526,153 @@ protected function execute(mixed $stmt): bool return $stmt->execute(); } + /** + * Run vendor-native EXPLAIN against the given SQL + bindings and return + * the parsed plan. Uses `EXPLAIN FORMAT=JSON` (not `EXPLAIN ANALYZE`) so + * the query is planned but not actually executed — bounded cost even on + * expensive reads. Subclasses can override (e.g. Postgres needs + * `EXPLAIN (FORMAT JSON) ...`). + * + * Extracts the three numbers consumers care about most up front + * (rowsScanned / indexUsed / estimatedCost) so callers don't have to walk + * the vendor JSON themselves. The full tree is preserved under `tree` for + * deep-dive debugging. + * + * Sanitization (hiding `_perms`/`_metadata`, renaming `_uid → $id`, ...) + * is applied centrally in Adapter::capturePlan(); this method returns the + * raw vendor output. + * + * @param string $sql + * @param array $binds + * @return array + */ + protected function explainSQL(string $sql, array $binds = []): array + { + $explainSql = 'EXPLAIN FORMAT=JSON ' . \ltrim($sql); + + $stmt = $this->getPDO()->prepare($explainSql); + + foreach ($binds as $key => $value) { + if (\gettype($value) === 'double') { + $stmt->bindValue($key, $this->getFloatPrecision($value), \PDO::PARAM_STR); + } else { + $stmt->bindValue($key, $value, $this->getPDOType($value)); + } + } + + $stmt->execute(); + $raw = $stmt->fetchColumn(); + $stmt->closeCursor(); + + $tree = \is_string($raw) ? \json_decode($raw, true) : null; + $tree = \is_array($tree) ? $tree : null; + + return [ + 'engine' => 'sql', + 'rowsScanned' => $this->extractRowsScanned($tree), + 'indexUsed' => $this->extractIndexUsed($tree), + 'estimatedCost' => $this->extractEstimatedCost($tree), + 'tree' => $tree, + ]; + } + + /** + * Sum `rows_examined_per_scan` across every table node in an EXPLAIN tree. + * Walks `nested_loop`, `attached_subqueries`, `materialized_from_subquery`, + * etc. transparently — anything with a `table.rows_examined_per_scan` adds + * to the total. Returns null if no table nodes are found. + * + * @param array|null $tree + */ + private function extractRowsScanned(?array $tree): ?int + { + if ($tree === null) { + return null; + } + $total = null; + $this->walkExplainTables($tree, function (array $table) use (&$total) { + if (isset($table['rows_examined_per_scan']) && \is_numeric($table['rows_examined_per_scan'])) { + $total = ($total ?? 0) + (int) $table['rows_examined_per_scan']; + } + }); + return $total; + } + + /** + * Return the `key` (index name) of the OUTER table — the one driving the + * query. Inner tables (permission subquery, joins) are intentionally + * ignored so the headline answers the customer's "did MY index get used" + * question, not "did some internal index get used". + * + * @param array|null $tree + */ + private function extractIndexUsed(?array $tree): ?string + { + if ($tree === null) { + return null; + } + $found = null; + $this->walkExplainTables($tree, function (array $table) use (&$found) { + if ($found === null && isset($table['key']) && \is_string($table['key'])) { + $found = $table['key']; + } + }, depthLimit: 1); + return $found; + } + + /** + * Pull `cost_info.query_cost` from the top of the plan. MySQL's "cost" is + * an opaque unit, not milliseconds — surfaced as-is for callers that want + * a single relative number. + * + * @param array|null $tree + */ + private function extractEstimatedCost(?array $tree): ?float + { + if ($tree === null) { + return null; + } + $cost = $tree['query_block']['cost_info']['query_cost'] ?? null; + return \is_numeric($cost) ? (float) $cost : null; + } + + /** + * Depth-first walk of an EXPLAIN JSON tree, invoking $visitor for every + * `table` node encountered. Handles MySQL's nested_loop arrays and the + * various subquery wrapper shapes generically. + * + * @param array $node + * @param callable(array): void $visitor + * @param int|null $depthLimit stop descending past this depth (null = unlimited) + * @param int $depth + */ + private function walkExplainTables(array $node, callable $visitor, ?int $depthLimit = null, int $depth = 0): void + { + if ($depthLimit !== null && $depth > $depthLimit) { + return; + } + + foreach ($node as $key => $value) { + if ($key === 'table' && \is_array($value)) { + $visitor($value); + if (isset($value['attached_subqueries']) && \is_array($value['attached_subqueries'])) { + foreach ($value['attached_subqueries'] as $sub) { + if (\is_array($sub)) { + $this->walkExplainTables($sub, $visitor, $depthLimit, $depth + 1); + } + } + } + if (isset($value['materialized_from_subquery']) && \is_array($value['materialized_from_subquery'])) { + $this->walkExplainTables($value['materialized_from_subquery'], $visitor, $depthLimit, $depth + 1); + } + continue; + } + if (\is_array($value)) { + $this->walkExplainTables($value, $visitor, $depthLimit, $depth); + } + } + } + /** * Create Documents in batches * @@ -3238,6 +3385,14 @@ public function find(Document $collection, array $queries = [], ?int $limit = 25 $sql = $this->trigger(Database::EVENT_DOCUMENT_FIND, $sql); + // Hot-path check matches the codebase's preserveDates / validate + // convention: single property comparison, zero overhead when capture + // is disabled. capturePlan() runs vendor EXPLAIN + sanitization only + // when called from inside Database::withExplain(). + if ($this->explainBuffer !== null) { + $this->capturePlan($sql, $binds, 'find', ['collection' => $collection]); + } + try { $stmt = $this->getPDO()->prepare($sql); @@ -3364,6 +3519,10 @@ public function count(Document $collection, array $queries = [], ?int $max = nul $sql = $this->trigger(Database::EVENT_DOCUMENT_COUNT, $sql); + if ($this->explainBuffer !== null) { + $this->capturePlan($sql, $binds, 'count', ['collection' => $collection->getId()]); + } + $stmt = $this->getPDO()->prepare($sql); foreach ($binds as $key => $value) { @@ -3459,6 +3618,10 @@ public function sum(Document $collection, string $attribute, array $queries = [] $sql = $this->trigger(Database::EVENT_DOCUMENT_SUM, $sql); + if ($this->explainBuffer !== null) { + $this->capturePlan($sql, $binds, 'sum', ['collection' => $collection->getId(), 'attribute' => $attribute]); + } + $stmt = $this->getPDO()->prepare($sql); foreach ($binds as $key => $value) { diff --git a/src/Database/Database.php b/src/Database/Database.php index 0e8c7a74f..44f492fd2 100644 --- a/src/Database/Database.php +++ b/src/Database/Database.php @@ -1454,6 +1454,51 @@ public function withPreserveDates(callable $callback): mixed } } + /** + * Capture vendor-native query plans for every read issued inside the callback. + * + * Appwrite resolves relationships by issuing additional `find()` calls per + * relation (not via SQL JOINs or Mongo `$lookup`), so a single user-level + * list-with-relationships expands into N separate reads against different + * collections. This method captures the plan for every one of those reads + * — without rebuilding any SQL — by toggling a per-adapter capture flag + * for the duration of the callback. Hot reads outside the callback pay a + * single null-check; reads inside additionally run EXPLAIN once each. + * + * Internal storage details (the `_perms` companion table, the `_metadata` + * system table, internal column names like `_uid`) are stripped from the + * plan before returning, so the output only references user-facing + * collection ids and `$`-prefixed attribute names. + * + * Returned Document shape: + * { + * queries: [ + * { purpose: 'find'|'count'|..., context: { collection, ... }, plan: { engine, tree, ... } }, + * ... one entry per executed read + * ] + * } + * + * Usage: + * $plan = $database->withExplain(fn () => $database->find('movies', $queries)); + * + * @param callable $callback + * @return Document + * @throws \Throwable + */ + public function withExplain(callable $callback): Document + { + $this->adapter->startExplainCapture(); + try { + $callback(); + } finally { + $captured = $this->adapter->stopExplainCapture(); + } + + return new Document([ + 'queries' => $captured, + ]); + } + public function getPreserveSequence(): bool { return $this->preserveSequence; diff --git a/tests/e2e/Adapter/Base.php b/tests/e2e/Adapter/Base.php index 4baeba35b..f944d8a2a 100644 --- a/tests/e2e/Adapter/Base.php +++ b/tests/e2e/Adapter/Base.php @@ -7,6 +7,7 @@ use Tests\E2E\Adapter\Scopes\CollectionTests; use Tests\E2E\Adapter\Scopes\CustomDocumentTypeTests; use Tests\E2E\Adapter\Scopes\DocumentTests; +use Tests\E2E\Adapter\Scopes\ExplainTests; use Tests\E2E\Adapter\Scopes\GeneralTests; use Tests\E2E\Adapter\Scopes\IndexTests; use Tests\E2E\Adapter\Scopes\ObjectAttributeTests; @@ -27,6 +28,7 @@ abstract class Base extends TestCase use CustomDocumentTypeTests; use DocumentTests; use AttributeTests; + use ExplainTests; use IndexTests; use OperatorTests; use PermissionTests; diff --git a/tests/e2e/Adapter/Scopes/ExplainTests.php b/tests/e2e/Adapter/Scopes/ExplainTests.php new file mode 100644 index 000000000..25d966cb5 --- /dev/null +++ b/tests/e2e/Adapter/Scopes/ExplainTests.php @@ -0,0 +1,140 @@ +explain() integration. + */ +trait ExplainTests +{ + public function testWithExplainCapturesPlanForFind(): void + { + /** @var Database $database */ + $database = $this->getDatabase(); + + if (! $database->getAdapter() instanceof SQL) { + $this->markTestSkipped('Explain capture is only wired in the SQL adapter today.'); + } + + $database->getAuthorization()->addRole(Role::any()->toString()); + + $collection = 'explain_test_' . \uniqid(); + + $database->createCollection($collection, permissions: [ + Permission::create(Role::any()), + Permission::read(Role::any()), + ]); + $database->createAttribute($collection, 'title', Database::VAR_STRING, 128, true); + $database->createAttribute($collection, 'status', Database::VAR_STRING, 32, true); + + $database->createDocument($collection, new Document([ + '$id' => ID::unique(), + '$permissions' => [Permission::read(Role::any())], + 'title' => 'first', + 'status' => 'published', + ])); + $database->createDocument($collection, new Document([ + '$id' => ID::unique(), + '$permissions' => [Permission::read(Role::any())], + 'title' => 'second', + 'status' => 'draft', + ])); + + // The actual capture: wrap a real find() in withExplain. + $plan = $database->withExplain(fn () => $database->find($collection, [ + Query::equal('status', ['published']), + Query::limit(10), + ])); + + $this->assertInstanceOf(Document::class, $plan); + + $entries = $plan->getAttribute('queries'); + $this->assertIsArray($entries); + $this->assertNotEmpty($entries, 'find() should produce at least one captured plan entry'); + + $entry = $entries[0]; + $this->assertSame('find', $entry['purpose']); + $this->assertArrayHasKey('context', $entry); + $this->assertArrayHasKey('collection', $entry['context']); + $this->assertSame($collection, $entry['context']['collection']); + + $this->assertArrayHasKey('plan', $entry); + $this->assertSame('sql', $entry['plan']['engine']); + $this->assertArrayHasKey('tree', $entry['plan']); + $this->assertNotNull($entry['plan']['tree'], 'EXPLAIN FORMAT=JSON tree must be parsed'); + + // The extracted top-level fields should appear even if some are null + // (e.g. when there's no usable index). + $this->assertArrayHasKey('rowsScanned', $entry['plan']); + $this->assertArrayHasKey('indexUsed', $entry['plan']); + $this->assertArrayHasKey('estimatedCost', $entry['plan']); + + // Sanitizer must have hidden the internal permission table reference + // (the EXISTS subquery against the _perms shadow table). + $rawTree = \json_encode($entry['plan']['tree']); + $this->assertStringNotContainsString('_perms', $rawTree, 'permission companion table must be redacted'); + + // Cleanup. + $database->deleteCollection($collection); + } + + public function testWithExplainBufferIsClearedAfterScope(): void + { + /** @var Database $database */ + $database = $this->getDatabase(); + + if (! $database->getAdapter() instanceof SQL) { + $this->markTestSkipped('Explain capture is only wired in the SQL adapter today.'); + } + + // Outside the scope: no capture, no overhead. + $this->assertFalse($database->getAdapter()->isExplainCapturing()); + + $database->withExplain(function () use ($database) { + $this->assertTrue($database->getAdapter()->isExplainCapturing()); + // Don't even need to run a query — just verify the flag toggles. + }); + + // After: cleanly reset. + $this->assertFalse($database->getAdapter()->isExplainCapturing()); + } + + public function testWithExplainExceptionDoesNotLeaveBufferOpen(): void + { + /** @var Database $database */ + $database = $this->getDatabase(); + + if (! $database->getAdapter() instanceof SQL) { + $this->markTestSkipped('Explain capture is only wired in the SQL adapter today.'); + } + + try { + $database->withExplain(function () { + throw new \RuntimeException('boom'); + }); + $this->fail('Expected RuntimeException to propagate'); + } catch (\RuntimeException) { + // expected + } + + $this->assertFalse( + $database->getAdapter()->isExplainCapturing(), + 'capture buffer must be cleared even when callback throws', + ); + } +} diff --git a/tests/unit/ExplainTest.php b/tests/unit/ExplainTest.php new file mode 100644 index 000000000..7451cabf1 --- /dev/null +++ b/tests/unit/ExplainTest.php @@ -0,0 +1,111 @@ +createMock(Adapter::class); + + // start must be called once before the callback, stop once after. + $adapter->expects($this->once())->method('startExplainCapture'); + $adapter + ->expects($this->once()) + ->method('stopExplainCapture') + ->willReturn([ + [ + 'purpose' => 'find', + 'context' => ['collection' => 'movies'], + 'plan' => [ + 'engine' => 'sql', + 'rowsScanned' => 25, + 'indexUsed' => '_idx_status', + 'estimatedCost' => 4.5, + 'tree' => null, + ], + ], + ]); + + $db = new Database($adapter, new Cache(new None())); + + $callbackRan = false; + $result = $db->withExplain(function () use (&$callbackRan) { + $callbackRan = true; + }); + + $this->assertTrue($callbackRan, 'callback must run inside the capture scope'); + $this->assertInstanceOf(Document::class, $result); + + $entries = $result->getAttribute('queries'); + $this->assertIsArray($entries); + $this->assertCount(1, $entries); + $this->assertSame('find', $entries[0]['purpose']); + $this->assertSame('movies', $entries[0]['context']['collection']); + $this->assertSame(25, $entries[0]['plan']['rowsScanned']); + } + + public function testStopExplainCaptureIsCalledEvenWhenCallbackThrows(): void + { + $adapter = $this->createMock(Adapter::class); + + // The point: stop must run via finally even on exception. + $adapter->expects($this->once())->method('startExplainCapture'); + $adapter->expects($this->once())->method('stopExplainCapture')->willReturn([]); + + $db = new Database($adapter, new Cache(new None())); + + $this->expectException(\RuntimeException::class); + $db->withExplain(function () { + throw new \RuntimeException('boom'); + }); + } + + public function testSanitizePlanHidesInternalTablesAndRenamesColumns(): void + { + // The sanitizer is a protected method on Adapter; use a mock + reflection + // so we don't have to satisfy the (huge) abstract surface manually. + $adapter = $this->createMock(Adapter::class); + $sanitize = (new \ReflectionMethod(Adapter::class, 'sanitizePlan')) + ->getClosure($adapter); + + $sanitized = $sanitize([ + 'table_name' => 'project_1_collection_5_perms', + 'meta_table' => 'appwrite__metadata', + 'projection' => ['_uid', '_createdAt', '_updatedAt', '_permissions', 'title'], + 'tenant_col' => '_tenant', + 'nested' => [ + 'inner_table' => 'project_1__metadata', + 'cols' => ['_uid', '_id'], + ], + ]); + + // Internal companion tables redacted to opaque markers. + $this->assertSame('', $sanitized['table_name']); + $this->assertSame('', $sanitized['meta_table']); + $this->assertSame('', $sanitized['nested']['inner_table']); + + // Internal column names translated to user-facing form. + $this->assertSame(['$id', '$createdAt', '$updatedAt', '$permissions', 'title'], $sanitized['projection']); + $this->assertSame('$tenant', $sanitized['tenant_col']); + + // _id intentionally NOT renamed — it's MySQL's auto-increment column reused + // throughout EXPLAIN output; translating it would muddle the plan. + $this->assertSame(['$id', '_id'], $sanitized['nested']['cols']); + } +} From 9896324490a04fe92c773a31410bc90b754652d8 Mon Sep 17 00:00:00 2001 From: Prem Palanisamy Date: Mon, 18 May 2026 07:16:11 +0100 Subject: [PATCH 02/16] fix test --- src/Database/Adapter.php | 66 ++++------------------- src/Database/Adapter/Mongo.php | 41 ++++++++++---- src/Database/Adapter/Pool.php | 36 +++++++++++-- src/Database/Adapter/Postgres.php | 5 -- src/Database/Adapter/SQL.php | 40 +------------- src/Database/Adapter/SQLite.php | 32 +++++++++++ src/Database/Database.php | 26 --------- tests/e2e/Adapter/Scopes/ExplainTests.php | 31 ++--------- tests/unit/ExplainTest.php | 19 +------ 9 files changed, 111 insertions(+), 185 deletions(-) diff --git a/src/Database/Adapter.php b/src/Database/Adapter.php index a49903a59..ae5569130 100644 --- a/src/Database/Adapter.php +++ b/src/Database/Adapter.php @@ -41,23 +41,11 @@ abstract class Adapter protected array $debug = []; /** - * Captured query plans while inside Database::withExplain(). - * - null = capture disabled (the normal mode; reads pay nothing extra) - * - array = capture enabled; each entry is one explained read - * - * Mirrors the preserveDates / validate / resolveRelationships scoped-flag - * pattern: a single inline null-check on hot paths, opt-in only via the - * matching with*() method on Database. - * * @var ?array> */ protected ?array $explainBuffer = null; /** - * Maps internal column names back to user-facing names in plan output. - * Single source of truth for the rename — same shape used by find()'s - * result post-processing in the SQL/Mongo adapters. - * * @var array */ protected const EXPLAIN_COLUMN_RENAMES = [ @@ -132,20 +120,12 @@ public function resetDebug(): static return $this; } - /** - * Begin capturing query plans for subsequent reads on this adapter. - * - * Pairs with stopExplainCapture(). Called by Database::withExplain() to - * open the scope; not intended for direct caller use. - */ public function startExplainCapture(): void { $this->explainBuffer = []; } /** - * Stop capturing and return the buffered query plans, clearing the buffer. - * * @return array> */ public function stopExplainCapture(): array @@ -155,27 +135,16 @@ public function stopExplainCapture(): array return $captured; } - /** - * True while inside an active capture scope. - */ public function isExplainCapturing(): bool { return $this->explainBuffer !== null; } /** - * Adapter-internal hook: when a read is about to execute and capture is - * active, run vendor-native EXPLAIN against the same SQL+binds, sanitize - * the result (hiding internal _perms / _metadata references and renaming - * internal columns), and append to the buffer. - * - * Hot paths invoke this only after an inline `$this->explainBuffer !== null` - * check, so when capture is disabled there is no method-call cost. - * * @param string $sql * @param array $binds - * @param string $purpose 'find' | 'count' | 'sum' | adapter-defined - * @param array $context optional metadata (collection id, relation key, etc.) + * @param string $purpose + * @param array $context */ protected function capturePlan(string $sql, array $binds = [], string $purpose = 'find', array $context = []): void { @@ -194,16 +163,6 @@ protected function capturePlan(string $sql, array $binds = [], string $purpose = } /** - * Strip Appwrite-internal storage details from a raw vendor plan before - * surfacing it to callers: - * - Tables ending in `_perms` are summarized as "" - * - The `__metadata` system table is summarized as "" - * - Internal column names (_uid, _createdAt, ...) are renamed to their - * user-facing form ($id, $createdAt, ...) - * - * Walks any nested array/object structure recursively; safe for arbitrary - * vendor-specific plan shapes. - * * @param array $plan * @return array */ @@ -212,10 +171,6 @@ protected function sanitizePlan(array $plan): array return $this->sanitizePlanNode($plan); } - /** - * @param mixed $node - * @return mixed - */ private function sanitizePlanNode(mixed $node): mixed { if (\is_array($node)) { @@ -234,11 +189,6 @@ private function sanitizePlanNode(mixed $node): mixed return $node; } - /** - * Apply the public-facing rename to a single identifier string. - * Conservatively matches table suffixes (`_perms`, `__metadata`) and exact - * internal column names from EXPLAIN_COLUMN_RENAMES. - */ private function renameInternalIdentifier(string $name): string { if (\str_ends_with($name, '__metadata')) { @@ -251,15 +201,17 @@ private function renameInternalIdentifier(string $name): string } /** - * Vendor-specific EXPLAIN implementation. Receives the SQL + bindings that - * would otherwise be executed; must return the raw (unsanitized) plan as - * an associative array. Sanitization is applied centrally by capturePlan(). - * * @param string $sql * @param array $binds * @return array */ - abstract protected function explainSQL(string $sql, array $binds = []): array; + protected function explainSQL(string $sql, array $binds = []): array + { + return [ + 'engine' => 'unsupported', + 'note' => 'Explain capture is not implemented for ' . static::class, + ]; + } /** * Set Namespace. diff --git a/src/Database/Adapter/Mongo.php b/src/Database/Adapter/Mongo.php index c8a842fbe..eca3e5a4c 100644 --- a/src/Database/Adapter/Mongo.php +++ b/src/Database/Adapter/Mongo.php @@ -2196,6 +2196,15 @@ public function find(Document $collection, array $queries = [], ?int $limit = 25 $found = []; $cursorId = null; + if ($this->explainBuffer !== null) { + $this->capturePlan( + \json_encode(['find' => $name, 'filter' => $filters, 'options' => $options]) ?: '', + [], + 'find', + ['collection' => $collection->getId()], + ); + } + try { // Use proper cursor iteration with reasonable batch size $options['batchSize'] = self::DEFAULT_BATCH_SIZE; @@ -2404,6 +2413,15 @@ public function count(Document $collection, array $queries = [], ?int $max = nul ]; } + if ($this->explainBuffer !== null) { + $this->capturePlan( + \json_encode(['aggregate' => $name, 'pipeline' => $pipeline]) ?: '', + [], + 'count', + ['collection' => $collection->getId()], + ); + } + try { $result = $this->client->aggregate($name, $pipeline, $options); @@ -2478,6 +2496,16 @@ public function sum(Document $collection, string $attribute, array $queries = [] ]; $options = $this->getTransactionOptions(); + + if ($this->explainBuffer !== null) { + $this->capturePlan( + \json_encode(['aggregate' => $name, 'pipeline' => $pipeline]) ?: '', + [], + 'sum', + ['collection' => $collection->getId(), 'attribute' => $attribute], + ); + } + return $this->client->aggregate($name, $pipeline, $options)->cursor->firstBatch[0]->total ?? 0; } @@ -3593,13 +3621,6 @@ public function getKeywords(): array } /** - * Mongo doesn't speak SQL — its "plan" comes from `$cursor->explain()` / - * aggregation `executionStats` against a built command document, not a - * SQL string. Satisfying the abstract contract with a stub here keeps the - * adapter loadable; real Mongo capture will be wired in a follow-up that - * hooks `find()`/`count()`/`sum()` to call the driver-native explain on - * the cursor before executing it. - * * @param string $sql * @param array $binds * @return array @@ -3607,9 +3628,9 @@ public function getKeywords(): array protected function explainSQL(string $sql, array $binds = []): array { return [ - 'engine' => 'mongo', - 'tree' => null, - 'note' => 'Mongo explain capture is not yet implemented; use cursor->explain() at the find() level', + 'engine' => 'mongo', + 'tree' => null, + 'command' => $sql !== '' ? \json_decode($sql, true) : null, ]; } diff --git a/src/Database/Adapter/Pool.php b/src/Database/Adapter/Pool.php index a08832088..20e705e3f 100644 --- a/src/Database/Adapter/Pool.php +++ b/src/Database/Adapter/Pool.php @@ -71,12 +71,27 @@ public function delegate(string $method, array $args): mixed $adapter->setMetadata($key, $value); } - if ($this->skipDuplicates) { - return $adapter->skipDuplicates( - fn () => $adapter->{$method}(...$args) - ); + // Propagate withExplain scope to whichever inner adapter handles + // this call and aggregate its captures back into the pool buffer. + $capturing = $this->isExplainCapturing(); + if ($capturing) { + $adapter->startExplainCapture(); + } + + try { + if ($this->skipDuplicates) { + return $adapter->skipDuplicates( + fn () => $adapter->{$method}(...$args) + ); + } + return $adapter->{$method}(...$args); + } finally { + if ($capturing) { + foreach ($adapter->stopExplainCapture() as $entry) { + $this->explainBuffer[] = $entry; + } + } } - return $adapter->{$method}(...$args); }); } @@ -323,6 +338,17 @@ public function find(Document $collection, array $queries = [], ?int $limit = 25 return $this->delegate(__FUNCTION__, \func_get_args()); } + /** + * @param string $sql + * @param array $binds + * @return array + */ + protected function explainSQL(string $sql, array $binds = []): array + { + // Explain runs on the inner adapter via delegate(), not on the pool itself. + throw new DatabaseException('Pool::explainSQL must not be invoked directly'); + } + public function sum(Document $collection, string $attribute, array $queries = [], ?int $max = null): float|int { return $this->delegate(__FUNCTION__, \func_get_args()); diff --git a/src/Database/Adapter/Postgres.php b/src/Database/Adapter/Postgres.php index 513624037..befebd0a0 100644 --- a/src/Database/Adapter/Postgres.php +++ b/src/Database/Adapter/Postgres.php @@ -1579,11 +1579,6 @@ public function getConnectionId(): string } /** - * Postgres equivalent of the MySQL EXPLAIN FORMAT=JSON override in SQL. - * Uses the `EXPLAIN (FORMAT JSON)` form (parenthesized options) and - * extracts `Plan Rows` / `Index Name` / `Total Cost` from the top-level - * Plan node so the headline fields line up with the MySQL adapter. - * * @param string $sql * @param array $binds * @return array diff --git a/src/Database/Adapter/SQL.php b/src/Database/Adapter/SQL.php index c67462513..ef4ed8592 100644 --- a/src/Database/Adapter/SQL.php +++ b/src/Database/Adapter/SQL.php @@ -2527,21 +2527,6 @@ protected function execute(mixed $stmt): bool } /** - * Run vendor-native EXPLAIN against the given SQL + bindings and return - * the parsed plan. Uses `EXPLAIN FORMAT=JSON` (not `EXPLAIN ANALYZE`) so - * the query is planned but not actually executed — bounded cost even on - * expensive reads. Subclasses can override (e.g. Postgres needs - * `EXPLAIN (FORMAT JSON) ...`). - * - * Extracts the three numbers consumers care about most up front - * (rowsScanned / indexUsed / estimatedCost) so callers don't have to walk - * the vendor JSON themselves. The full tree is preserved under `tree` for - * deep-dive debugging. - * - * Sanitization (hiding `_perms`/`_metadata`, renaming `_uid → $id`, ...) - * is applied centrally in Adapter::capturePlan(); this method returns the - * raw vendor output. - * * @param string $sql * @param array $binds * @return array @@ -2577,11 +2562,6 @@ protected function explainSQL(string $sql, array $binds = []): array } /** - * Sum `rows_examined_per_scan` across every table node in an EXPLAIN tree. - * Walks `nested_loop`, `attached_subqueries`, `materialized_from_subquery`, - * etc. transparently — anything with a `table.rows_examined_per_scan` adds - * to the total. Returns null if no table nodes are found. - * * @param array|null $tree */ private function extractRowsScanned(?array $tree): ?int @@ -2599,11 +2579,6 @@ private function extractRowsScanned(?array $tree): ?int } /** - * Return the `key` (index name) of the OUTER table — the one driving the - * query. Inner tables (permission subquery, joins) are intentionally - * ignored so the headline answers the customer's "did MY index get used" - * question, not "did some internal index get used". - * * @param array|null $tree */ private function extractIndexUsed(?array $tree): ?string @@ -2612,6 +2587,7 @@ private function extractIndexUsed(?array $tree): ?string return null; } $found = null; + // Only the outer table — inner permission subquery indexes are not user-facing. $this->walkExplainTables($tree, function (array $table) use (&$found) { if ($found === null && isset($table['key']) && \is_string($table['key'])) { $found = $table['key']; @@ -2621,10 +2597,6 @@ private function extractIndexUsed(?array $tree): ?string } /** - * Pull `cost_info.query_cost` from the top of the plan. MySQL's "cost" is - * an opaque unit, not milliseconds — surfaced as-is for callers that want - * a single relative number. - * * @param array|null $tree */ private function extractEstimatedCost(?array $tree): ?float @@ -2637,13 +2609,9 @@ private function extractEstimatedCost(?array $tree): ?float } /** - * Depth-first walk of an EXPLAIN JSON tree, invoking $visitor for every - * `table` node encountered. Handles MySQL's nested_loop arrays and the - * various subquery wrapper shapes generically. - * * @param array $node * @param callable(array): void $visitor - * @param int|null $depthLimit stop descending past this depth (null = unlimited) + * @param int|null $depthLimit * @param int $depth */ private function walkExplainTables(array $node, callable $visitor, ?int $depthLimit = null, int $depth = 0): void @@ -3385,10 +3353,6 @@ public function find(Document $collection, array $queries = [], ?int $limit = 25 $sql = $this->trigger(Database::EVENT_DOCUMENT_FIND, $sql); - // Hot-path check matches the codebase's preserveDates / validate - // convention: single property comparison, zero overhead when capture - // is disabled. capturePlan() runs vendor EXPLAIN + sanitization only - // when called from inside Database::withExplain(). if ($this->explainBuffer !== null) { $this->capturePlan($sql, $binds, 'find', ['collection' => $collection]); } diff --git a/src/Database/Adapter/SQLite.php b/src/Database/Adapter/SQLite.php index 5b07ce3b7..4ce4d03ba 100644 --- a/src/Database/Adapter/SQLite.php +++ b/src/Database/Adapter/SQLite.php @@ -88,6 +88,38 @@ public function __construct(mixed $pdo) $this->registerUserFunctions(); } + /** + * @param string $sql + * @param array $binds + * @return array + */ + protected function explainSQL(string $sql, array $binds = []): array + { + $explainSql = 'EXPLAIN QUERY PLAN ' . \ltrim($sql); + + $stmt = $this->getPDO()->prepare($explainSql); + + foreach ($binds as $key => $value) { + if (\gettype($value) === 'double') { + $stmt->bindValue($key, $this->getFloatPrecision($value), \PDO::PARAM_STR); + } else { + $stmt->bindValue($key, $value, $this->getPDOType($value)); + } + } + + $stmt->execute(); + $rows = $stmt->fetchAll(\PDO::FETCH_ASSOC); + $stmt->closeCursor(); + + return [ + 'engine' => 'sql', + 'rowsScanned' => null, + 'indexUsed' => null, + 'estimatedCost' => null, + 'tree' => ['steps' => \is_array($rows) ? $rows : []], + ]; + } + /** * Toggle MariaDB/MySQL emulation. See $emulateMySQL for what this * actually changes. diff --git a/src/Database/Database.php b/src/Database/Database.php index 44f492fd2..7a0205467 100644 --- a/src/Database/Database.php +++ b/src/Database/Database.php @@ -1455,32 +1455,6 @@ public function withPreserveDates(callable $callback): mixed } /** - * Capture vendor-native query plans for every read issued inside the callback. - * - * Appwrite resolves relationships by issuing additional `find()` calls per - * relation (not via SQL JOINs or Mongo `$lookup`), so a single user-level - * list-with-relationships expands into N separate reads against different - * collections. This method captures the plan for every one of those reads - * — without rebuilding any SQL — by toggling a per-adapter capture flag - * for the duration of the callback. Hot reads outside the callback pay a - * single null-check; reads inside additionally run EXPLAIN once each. - * - * Internal storage details (the `_perms` companion table, the `_metadata` - * system table, internal column names like `_uid`) are stripped from the - * plan before returning, so the output only references user-facing - * collection ids and `$`-prefixed attribute names. - * - * Returned Document shape: - * { - * queries: [ - * { purpose: 'find'|'count'|..., context: { collection, ... }, plan: { engine, tree, ... } }, - * ... one entry per executed read - * ] - * } - * - * Usage: - * $plan = $database->withExplain(fn () => $database->find('movies', $queries)); - * * @param callable $callback * @return Document * @throws \Throwable diff --git a/tests/e2e/Adapter/Scopes/ExplainTests.php b/tests/e2e/Adapter/Scopes/ExplainTests.php index 25d966cb5..8daab18be 100644 --- a/tests/e2e/Adapter/Scopes/ExplainTests.php +++ b/tests/e2e/Adapter/Scopes/ExplainTests.php @@ -10,16 +10,6 @@ use Utopia\Database\Helpers\Role; use Utopia\Database\Query; -/** - * Integration tests for Database::withExplain() against real backends. - * - * Verifies the full path: write-path hook fires inside Adapter::find(), - * adapter runs vendor-native EXPLAIN, the parsed plan flows back through - * the buffer, and the sanitizer strips internal storage references. - * - * Mongo skips itself — explain capture is stubbed there pending real - * cursor->explain() integration. - */ trait ExplainTests { public function testWithExplainCapturesPlanForFind(): void @@ -55,7 +45,6 @@ public function testWithExplainCapturesPlanForFind(): void 'status' => 'draft', ])); - // The actual capture: wrap a real find() in withExplain. $plan = $database->withExplain(fn () => $database->find($collection, [ Query::equal('status', ['published']), Query::limit(10), @@ -65,7 +54,7 @@ public function testWithExplainCapturesPlanForFind(): void $entries = $plan->getAttribute('queries'); $this->assertIsArray($entries); - $this->assertNotEmpty($entries, 'find() should produce at least one captured plan entry'); + $this->assertNotEmpty($entries); $entry = $entries[0]; $this->assertSame('find', $entry['purpose']); @@ -76,20 +65,15 @@ public function testWithExplainCapturesPlanForFind(): void $this->assertArrayHasKey('plan', $entry); $this->assertSame('sql', $entry['plan']['engine']); $this->assertArrayHasKey('tree', $entry['plan']); - $this->assertNotNull($entry['plan']['tree'], 'EXPLAIN FORMAT=JSON tree must be parsed'); + $this->assertNotNull($entry['plan']['tree']); - // The extracted top-level fields should appear even if some are null - // (e.g. when there's no usable index). $this->assertArrayHasKey('rowsScanned', $entry['plan']); $this->assertArrayHasKey('indexUsed', $entry['plan']); $this->assertArrayHasKey('estimatedCost', $entry['plan']); - // Sanitizer must have hidden the internal permission table reference - // (the EXISTS subquery against the _perms shadow table). $rawTree = \json_encode($entry['plan']['tree']); - $this->assertStringNotContainsString('_perms', $rawTree, 'permission companion table must be redacted'); + $this->assertStringNotContainsString('_perms', $rawTree); - // Cleanup. $database->deleteCollection($collection); } @@ -102,15 +86,12 @@ public function testWithExplainBufferIsClearedAfterScope(): void $this->markTestSkipped('Explain capture is only wired in the SQL adapter today.'); } - // Outside the scope: no capture, no overhead. $this->assertFalse($database->getAdapter()->isExplainCapturing()); $database->withExplain(function () use ($database) { $this->assertTrue($database->getAdapter()->isExplainCapturing()); - // Don't even need to run a query — just verify the flag toggles. }); - // After: cleanly reset. $this->assertFalse($database->getAdapter()->isExplainCapturing()); } @@ -129,12 +110,8 @@ public function testWithExplainExceptionDoesNotLeaveBufferOpen(): void }); $this->fail('Expected RuntimeException to propagate'); } catch (\RuntimeException) { - // expected } - $this->assertFalse( - $database->getAdapter()->isExplainCapturing(), - 'capture buffer must be cleared even when callback throws', - ); + $this->assertFalse($database->getAdapter()->isExplainCapturing()); } } diff --git a/tests/unit/ExplainTest.php b/tests/unit/ExplainTest.php index 7451cabf1..37d911ca9 100644 --- a/tests/unit/ExplainTest.php +++ b/tests/unit/ExplainTest.php @@ -9,21 +9,12 @@ use Utopia\Database\Database; use Utopia\Database\Document; -/** - * Tests for the in-process query-plan capture scope (Database::withExplain) - * and the Adapter-level sanitizer that strips internal storage details. - * - * Covers behavior — not specific vendor plan parsing (that lives in - * SQL::explainSQL / Mongo::explainSQL and is exercised by the e2e adapter - * tests against real backends). - */ class ExplainTest extends TestCase { public function testWithExplainTogglesCaptureAndWrapsResult(): void { $adapter = $this->createMock(Adapter::class); - // start must be called once before the callback, stop once after. $adapter->expects($this->once())->method('startExplainCapture'); $adapter ->expects($this->once()) @@ -49,7 +40,7 @@ public function testWithExplainTogglesCaptureAndWrapsResult(): void $callbackRan = true; }); - $this->assertTrue($callbackRan, 'callback must run inside the capture scope'); + $this->assertTrue($callbackRan); $this->assertInstanceOf(Document::class, $result); $entries = $result->getAttribute('queries'); @@ -64,7 +55,6 @@ public function testStopExplainCaptureIsCalledEvenWhenCallbackThrows(): void { $adapter = $this->createMock(Adapter::class); - // The point: stop must run via finally even on exception. $adapter->expects($this->once())->method('startExplainCapture'); $adapter->expects($this->once())->method('stopExplainCapture')->willReturn([]); @@ -78,8 +68,6 @@ public function testStopExplainCaptureIsCalledEvenWhenCallbackThrows(): void public function testSanitizePlanHidesInternalTablesAndRenamesColumns(): void { - // The sanitizer is a protected method on Adapter; use a mock + reflection - // so we don't have to satisfy the (huge) abstract surface manually. $adapter = $this->createMock(Adapter::class); $sanitize = (new \ReflectionMethod(Adapter::class, 'sanitizePlan')) ->getClosure($adapter); @@ -95,17 +83,14 @@ public function testSanitizePlanHidesInternalTablesAndRenamesColumns(): void ], ]); - // Internal companion tables redacted to opaque markers. $this->assertSame('', $sanitized['table_name']); $this->assertSame('', $sanitized['meta_table']); $this->assertSame('', $sanitized['nested']['inner_table']); - // Internal column names translated to user-facing form. $this->assertSame(['$id', '$createdAt', '$updatedAt', '$permissions', 'title'], $sanitized['projection']); $this->assertSame('$tenant', $sanitized['tenant_col']); - // _id intentionally NOT renamed — it's MySQL's auto-increment column reused - // throughout EXPLAIN output; translating it would muddle the plan. + // _id is MySQL's auto-increment column; not renamed. $this->assertSame(['$id', '_id'], $sanitized['nested']['cols']); } } From d08ee14cfe56c3e376885052cfe84cdffb78d473 Mon Sep 17 00:00:00 2001 From: Prem Palanisamy Date: Mon, 18 May 2026 14:12:09 +0100 Subject: [PATCH 03/16] fix explain capture on Mongo and MariaDB --- src/Database/Adapter.php | 21 +++++- src/Database/Adapter/MariaDB.php | 13 ++++ src/Database/Adapter/Mongo.php | 112 ++++++++++++++++++++++++++++++- src/Database/Adapter/SQL.php | 6 +- 4 files changed, 144 insertions(+), 8 deletions(-) diff --git a/src/Database/Adapter.php b/src/Database/Adapter.php index ae5569130..05a5fb5fb 100644 --- a/src/Database/Adapter.php +++ b/src/Database/Adapter.php @@ -197,7 +197,19 @@ private function renameInternalIdentifier(string $name): string if (\str_ends_with($name, '_perms')) { return ''; } - return self::EXPLAIN_COLUMN_RENAMES[$name] ?? $name; + if (isset(self::EXPLAIN_COLUMN_RENAMES[$name])) { + return self::EXPLAIN_COLUMN_RENAMES[$name]; + } + // EXPLAIN tree string-values can embed internal identifiers (e.g. + // index_condition: "main.`_uid` = '...'"). Substring-rewrite each. + if (\str_contains($name, '_')) { + foreach (self::EXPLAIN_COLUMN_RENAMES as $internal => $public) { + if (\str_contains($name, $internal)) { + $name = \str_replace($internal, $public, $name); + } + } + } + return $name; } /** @@ -208,8 +220,11 @@ private function renameInternalIdentifier(string $name): string protected function explainSQL(string $sql, array $binds = []): array { return [ - 'engine' => 'unsupported', - 'note' => 'Explain capture is not implemented for ' . static::class, + 'engine' => 'unsupported', + 'rowsScanned' => null, + 'indexUsed' => null, + 'estimatedCost' => null, + 'tree' => null, ]; } diff --git a/src/Database/Adapter/MariaDB.php b/src/Database/Adapter/MariaDB.php index 599da878e..8a8d2c90d 100644 --- a/src/Database/Adapter/MariaDB.php +++ b/src/Database/Adapter/MariaDB.php @@ -1957,6 +1957,19 @@ public function getConnectionId(): string return $stmt->fetchColumn(); } + /** + * @param string $sql + * @param array $binds + * @return array + */ + protected function explainSQL(string $sql, array $binds = []): array + { + // setTimeout() wraps statements with `SET STATEMENT ... FOR `, + // which is illegal inside EXPLAIN. Strip the wrapper before delegating. + $stripped = \preg_replace('/^\s*SET\s+STATEMENT\s+[^;]*?\s+FOR\s+/is', '', $sql, 1); + return parent::explainSQL($stripped ?? $sql, $binds); + } + public function getInternalIndexesKeys(): array { return ['primary', '_created_at', '_updated_at', '_tenant_id']; diff --git a/src/Database/Adapter/Mongo.php b/src/Database/Adapter/Mongo.php index eca3e5a4c..3874c352c 100644 --- a/src/Database/Adapter/Mongo.php +++ b/src/Database/Adapter/Mongo.php @@ -3627,13 +3627,119 @@ public function getKeywords(): array */ protected function explainSQL(string $sql, array $binds = []): array { + $captured = $sql !== '' ? \json_decode($sql, true) : null; + + // Without a captured command (or invalid JSON) we can't ask Mongo for a plan. + if (! \is_array($captured)) { + return [ + 'engine' => 'mongo', + 'rowsScanned' => null, + 'indexUsed' => null, + 'estimatedCost' => null, + 'tree' => $captured, + ]; + } + + // Capture stores find as { find, filter, options } and aggregate as + // { aggregate, pipeline }. Mongo's explain command wants the options + // hoisted to top level, and aggregate needs a cursor field. + $command = $captured; + if (isset($command['options']) && \is_array($command['options'])) { + $command = \array_merge($command, $command['options']); + unset($command['options']); + } + // Mongo's explain rejects `filter: []`; coerce to an empty object. + if (isset($command['filter']) && \is_array($command['filter']) && empty($command['filter'])) { + $command['filter'] = (object) []; + } + if (isset($command['aggregate']) && ! isset($command['cursor'])) { + $command['cursor'] = (object) []; + } + + $tree = null; + $rowsScanned = null; + $indexUsed = null; + try { + $raw = $this->client->query([ + 'explain' => (object) $command, + 'verbosity' => 'executionStats', + ]); + $tree = \json_decode(\json_encode($raw), true); + $rowsScanned = $this->extractMongoRowsScanned($tree); + $indexUsed = $this->extractMongoIndexUsed($tree); + } catch (\Throwable $e) { + // Fall back to the captured command on any explain failure so callers + // still see what was attempted. + $tree = ['command' => $captured, 'explainError' => $e->getMessage()]; + } + return [ - 'engine' => 'mongo', - 'tree' => null, - 'command' => $sql !== '' ? \json_decode($sql, true) : null, + 'engine' => 'mongo', + 'rowsScanned' => $rowsScanned, + 'indexUsed' => $indexUsed, + 'estimatedCost' => null, + 'tree' => $tree, ]; } + /** + * Walk a Mongo explain executionStats tree and sum totalDocsExamined. + * + * @param array|null $tree + */ + private function extractMongoRowsScanned(?array $tree): ?int + { + if (! \is_array($tree)) { + return null; + } + // find: executionStats.totalDocsExamined + $find = $tree['executionStats']['totalDocsExamined'] ?? null; + if (\is_numeric($find)) { + return (int) $find; + } + // aggregate: stages[].$cursor.executionStats.totalDocsExamined + $total = null; + foreach (($tree['stages'] ?? []) as $stage) { + $n = $stage['$cursor']['executionStats']['totalDocsExamined'] ?? null; + if (\is_numeric($n)) { + $total = ($total ?? 0) + (int) $n; + } + } + return $total; + } + + /** + * Find the winning IXSCAN indexName from a Mongo explain tree. + * + * @param array|null $tree + */ + private function extractMongoIndexUsed(?array $tree): ?string + { + if (! \is_array($tree)) { + return null; + } + $found = null; + $walk = function ($node) use (&$walk, &$found): void { + if ($found !== null || ! \is_array($node)) { + return; + } + if (($node['stage'] ?? null) === 'IXSCAN' && isset($node['indexName']) && \is_string($node['indexName'])) { + $found = $node['indexName']; + return; + } + foreach ($node as $value) { + if (\is_array($value)) { + $walk($value); + if ($found !== null) { + return; + } + } + } + }; + $walk($tree); + return $found; + } + protected function processException(\Throwable $e): \Throwable { // Timeout diff --git a/src/Database/Adapter/SQL.php b/src/Database/Adapter/SQL.php index ef4ed8592..5c299e278 100644 --- a/src/Database/Adapter/SQL.php +++ b/src/Database/Adapter/SQL.php @@ -2571,8 +2571,10 @@ private function extractRowsScanned(?array $tree): ?int } $total = null; $this->walkExplainTables($tree, function (array $table) use (&$total) { - if (isset($table['rows_examined_per_scan']) && \is_numeric($table['rows_examined_per_scan'])) { - $total = ($total ?? 0) + (int) $table['rows_examined_per_scan']; + // MySQL exposes 'rows_examined_per_scan', MariaDB exposes 'rows'. + $rows = $table['rows_examined_per_scan'] ?? $table['rows'] ?? null; + if (\is_numeric($rows)) { + $total = ($total ?? 0) + (int) $rows; } }); return $total; From 6944cd471aa8a98aa848fab51e5ba540b01b1226 Mon Sep 17 00:00:00 2001 From: Prem Palanisamy Date: Tue, 19 May 2026 09:07:24 +0100 Subject: [PATCH 04/16] fix explain crash on count/sum, pool transactions, nested scopes --- src/Database/Adapter.php | 8 ++ src/Database/Adapter/Pool.php | 55 +++++------ src/Database/Adapter/SQL.php | 6 +- tests/e2e/Adapter/Scopes/ExplainTests.php | 115 ++++++++++++++++++++++ 4 files changed, 154 insertions(+), 30 deletions(-) diff --git a/src/Database/Adapter.php b/src/Database/Adapter.php index 05a5fb5fb..436ea299c 100644 --- a/src/Database/Adapter.php +++ b/src/Database/Adapter.php @@ -120,8 +120,16 @@ public function resetDebug(): static return $this; } + /** + * @throws DatabaseException when called inside an already-active scope — + * the buffer is a single shared array, so silently clobbering the outer + * scope would lose every previously-captured entry. + */ public function startExplainCapture(): void { + if ($this->explainBuffer !== null) { + throw new DatabaseException('withExplain cannot be nested — finish the outer scope first.'); + } $this->explainBuffer = []; } diff --git a/src/Database/Adapter/Pool.php b/src/Database/Adapter/Pool.php index 20e705e3f..950a99a19 100644 --- a/src/Database/Adapter/Pool.php +++ b/src/Database/Adapter/Pool.php @@ -42,16 +42,35 @@ public function __construct(UtopiaPool $pool) */ public function delegate(string $method, array $args): mixed { - if ($this->pinnedAdapter !== null) { - if ($this->skipDuplicates) { - return $this->pinnedAdapter->skipDuplicates( - fn () => $this->pinnedAdapter->{$method}(...$args) - ); + // Wrap any inner-adapter call so withExplain scope propagates and its + // captures aggregate back into the pool buffer — needed for both the + // pinned-transaction and pooled paths. + $invoke = function (Adapter $adapter) use ($method, $args): mixed { + $capturing = $this->isExplainCapturing(); + if ($capturing) { + $adapter->startExplainCapture(); + } + try { + if ($this->skipDuplicates) { + return $adapter->skipDuplicates( + fn () => $adapter->{$method}(...$args) + ); + } + return $adapter->{$method}(...$args); + } finally { + if ($capturing) { + foreach ($adapter->stopExplainCapture() as $entry) { + $this->explainBuffer[] = $entry; + } + } } - return $this->pinnedAdapter->{$method}(...$args); + }; + + if ($this->pinnedAdapter !== null) { + return $invoke($this->pinnedAdapter); } - return $this->pool->use(function (Adapter $adapter) use ($method, $args) { + return $this->pool->use(function (Adapter $adapter) use ($invoke) { // Run setters in case config changed since this connection was last used $adapter->setDatabase($this->getDatabase()); $adapter->setNamespace($this->getNamespace()); @@ -71,27 +90,7 @@ public function delegate(string $method, array $args): mixed $adapter->setMetadata($key, $value); } - // Propagate withExplain scope to whichever inner adapter handles - // this call and aggregate its captures back into the pool buffer. - $capturing = $this->isExplainCapturing(); - if ($capturing) { - $adapter->startExplainCapture(); - } - - try { - if ($this->skipDuplicates) { - return $adapter->skipDuplicates( - fn () => $adapter->{$method}(...$args) - ); - } - return $adapter->{$method}(...$args); - } finally { - if ($capturing) { - foreach ($adapter->stopExplainCapture() as $entry) { - $this->explainBuffer[] = $entry; - } - } - } + return $invoke($adapter); }); } diff --git a/src/Database/Adapter/SQL.php b/src/Database/Adapter/SQL.php index 5c299e278..a3bf38036 100644 --- a/src/Database/Adapter/SQL.php +++ b/src/Database/Adapter/SQL.php @@ -3486,7 +3486,8 @@ public function count(Document $collection, array $queries = [], ?int $max = nul $sql = $this->trigger(Database::EVENT_DOCUMENT_COUNT, $sql); if ($this->explainBuffer !== null) { - $this->capturePlan($sql, $binds, 'count', ['collection' => $collection->getId()]); + // $collection was reassigned to the string id at the top of this method. + $this->capturePlan($sql, $binds, 'count', ['collection' => $collection]); } $stmt = $this->getPDO()->prepare($sql); @@ -3585,7 +3586,8 @@ public function sum(Document $collection, string $attribute, array $queries = [] $sql = $this->trigger(Database::EVENT_DOCUMENT_SUM, $sql); if ($this->explainBuffer !== null) { - $this->capturePlan($sql, $binds, 'sum', ['collection' => $collection->getId(), 'attribute' => $attribute]); + // $collection was reassigned to the string id at the top of this method. + $this->capturePlan($sql, $binds, 'sum', ['collection' => $collection, 'attribute' => $attribute]); } $stmt = $this->getPDO()->prepare($sql); diff --git a/tests/e2e/Adapter/Scopes/ExplainTests.php b/tests/e2e/Adapter/Scopes/ExplainTests.php index 8daab18be..7a1584879 100644 --- a/tests/e2e/Adapter/Scopes/ExplainTests.php +++ b/tests/e2e/Adapter/Scopes/ExplainTests.php @@ -2,9 +2,11 @@ namespace Tests\E2E\Adapter\Scopes; +use Utopia\Database\Adapter\Pool; use Utopia\Database\Adapter\SQL; use Utopia\Database\Database; use Utopia\Database\Document; +use Utopia\Database\Exception as DatabaseException; use Utopia\Database\Helpers\ID; use Utopia\Database\Helpers\Permission; use Utopia\Database\Helpers\Role; @@ -114,4 +116,117 @@ public function testWithExplainExceptionDoesNotLeaveBufferOpen(): void $this->assertFalse($database->getAdapter()->isExplainCapturing()); } + + public function testWithExplainCapturesCountAndSum(): void + { + /** @var Database $database */ + $database = $this->getDatabase(); + + if (! $database->getAdapter() instanceof SQL) { + $this->markTestSkipped('Explain capture is only wired in the SQL adapter today.'); + } + + $database->getAuthorization()->addRole(Role::any()->toString()); + + $collection = 'explain_count_sum_' . \uniqid(); + $database->createCollection($collection, permissions: [ + Permission::create(Role::any()), + Permission::read(Role::any()), + ]); + $database->createAttribute($collection, 'score', Database::VAR_INTEGER, 0, true); + + for ($i = 0; $i < 3; $i++) { + $database->createDocument($collection, new Document([ + '$id' => ID::unique(), + '$permissions' => [Permission::read(Role::any())], + 'score' => $i + 1, + ])); + } + + // Regression guard: count() used to crash inside withExplain because + // the context array called ->getId() on a string. + $plan = $database->withExplain(function () use ($database, $collection): void { + $database->count($collection); + $database->sum($collection, 'score'); + }); + + $entries = $plan->getAttribute('queries'); + $this->assertIsArray($entries); + $this->assertGreaterThanOrEqual(2, \count($entries)); + + $purposes = \array_column($entries, 'purpose'); + $this->assertContains('count', $purposes); + $this->assertContains('sum', $purposes); + + foreach ($entries as $entry) { + $this->assertSame($collection, $entry['context']['collection']); + if ($entry['purpose'] === 'sum') { + $this->assertSame('score', $entry['context']['attribute']); + } + } + + $database->deleteCollection($collection); + } + + public function testWithExplainWorksInsideTransactionOnPooledAdapter(): void + { + /** @var Database $database */ + $database = $this->getDatabase(); + + if (! $database->getAdapter() instanceof Pool) { + $this->markTestSkipped('Transaction-pinned adapter only matters when running through the Pool adapter.'); + } + + $database->getAuthorization()->addRole(Role::any()->toString()); + + $collection = 'explain_txn_' . \uniqid(); + $database->createCollection($collection, permissions: [ + Permission::create(Role::any()), + Permission::read(Role::any()), + ]); + $database->createAttribute($collection, 'title', Database::VAR_STRING, 32, true); + $database->createDocument($collection, new Document([ + '$id' => ID::unique(), + '$permissions' => [Permission::read(Role::any())], + 'title' => 'one', + ])); + + // Pin a connection by running inside a transaction, then capture + // explain on the *same* pinned connection. Regression guard: this used + // to silently return [] because the pinned-adapter early return + // bypassed the start/stop/drain logic. + $plan = $database->withExplain(function () use ($database, $collection) { + return $database->withTransaction(fn () => $database->find($collection, [ + Query::limit(5), + ])); + }); + + $entries = $plan->getAttribute('queries'); + $this->assertIsArray($entries); + $this->assertNotEmpty($entries, 'pinned-adapter explain capture must reach the pool buffer'); + $this->assertSame('find', $entries[0]['purpose']); + + $database->deleteCollection($collection); + } + + public function testNestedWithExplainThrows(): void + { + /** @var Database $database */ + $database = $this->getDatabase(); + + if (! $database->getAdapter() instanceof SQL) { + $this->markTestSkipped('Explain capture is only wired in the SQL adapter today.'); + } + + $this->expectException(DatabaseException::class); + $this->expectExceptionMessageMatches('/cannot be nested/i'); + + $database->withExplain(function () use ($database): void { + $database->withExplain(fn () => null); + }); + + // Even though the inner call threw, the outer scope's finally still + // runs and clears the buffer — verified separately to keep this test + // focused on the nesting guard itself. + } } From 939a4d3e985ce3996b1ed12793e7075cd82159f7 Mon Sep 17 00:00:00 2001 From: Prem Palanisamy Date: Mon, 1 Jun 2026 12:11:23 +0100 Subject: [PATCH 05/16] Add real execution stats and precise engine labels to explain plans - Add rowsReturned/executionTime to the normalized plan, measured from the real find/count/sum the explain scope already runs (no extra EXPLAIN pass) - Report a precise per-adapter engine label (mysql/mariadb/postgres/sqlite) via SQL::getExplainEngine() instead of a generic 'sql' - Fix Postgres plan extraction to recurse into child Plans so pgvector index scans under a Limit are reported (indexUsed/rowsScanned) - Capture actual nReturned/executionTimeMillis from Mongo executionStats - Document the display-only identifier substring rewrite caveat --- src/Database/Adapter.php | 49 +++++++++++ src/Database/Adapter/MariaDB.php | 5 ++ src/Database/Adapter/Mongo.php | 60 +++++++++++++ src/Database/Adapter/MySQL.php | 5 ++ src/Database/Adapter/Postgres.php | 90 +++++++++++++++++-- src/Database/Adapter/SQL.php | 32 ++++++- src/Database/Adapter/SQLite.php | 9 +- tests/e2e/Adapter/Scopes/ExplainTests.php | 10 ++- tests/unit/ExplainTest.php | 101 ++++++++++++++++++++++ 9 files changed, 351 insertions(+), 10 deletions(-) diff --git a/src/Database/Adapter.php b/src/Database/Adapter.php index 436ea299c..5433f0f7a 100644 --- a/src/Database/Adapter.php +++ b/src/Database/Adapter.php @@ -170,6 +170,36 @@ protected function capturePlan(string $sql, array $binds = [], string $purpose = ]; } + /** + * Attach the REAL execution stats to the most recently captured plan entry. + * + * The explain endpoint runs the same query listRows runs, so instead of + * paying for a second EXPLAIN ANALYZE pass we just measure the read that + * already happens: callers time their actual statement and report the + * actual rows it produced. No-op when not capturing, so the normal read + * path is untouched. + * + * @param int|null $rowsReturned actual rows the statement returned (null when not meaningful, e.g. an aggregate) + * @param float|null $executionTime actual wall time of the statement in milliseconds + */ + protected function recordPlanActuals(?int $rowsReturned, ?float $executionTime): void + { + if ($this->explainBuffer === null || $this->explainBuffer === []) { + return; + } + $last = \array_key_last($this->explainBuffer); + $plan = $this->explainBuffer[$last]['plan'] ?? null; + // capturePlan() stores the entry just before the real statement runs; + // only fill actuals when the captured plan is a well-formed array. A + // failed EXPLAIN is stored as ['error' => ...] — leave it untouched so + // an error entry never masquerades as a real plan with stats. + if (! \is_array($plan) || isset($plan['error'])) { + return; + } + $this->explainBuffer[$last]['plan']['rowsReturned'] = $rowsReturned; + $this->explainBuffer[$last]['plan']['executionTime'] = $executionTime; + } + /** * @param array $plan * @return array @@ -210,6 +240,11 @@ private function renameInternalIdentifier(string $name): string } // EXPLAIN tree string-values can embed internal identifiers (e.g. // index_condition: "main.`_uid` = '...'"). Substring-rewrite each. + // NOTE: this is a best-effort, display-only substring replace — a user + // column whose name happens to contain "_uid"/"_tenant"/etc. would be + // rewritten too. Acceptable because the output is for human reading of + // the plan, not for round-tripping back to a real column name; the raw + // `tree` is the same string pre-rename if an exact value is ever needed. if (\str_contains($name, '_')) { foreach (self::EXPLAIN_COLUMN_RENAMES as $internal => $public) { if (\str_contains($name, $internal)) { @@ -221,6 +256,18 @@ private function renameInternalIdentifier(string $name): string } /** + * Produce a normalized query plan for a single statement. + * + * Every adapter returns the same fixed shape so the public DTO can stay + * typed regardless of engine: + * engine precise backend label (mysql|mariadb|postgres|mongo|...) + * rowsScanned estimated rows the planner expects to examine (null if N/A) + * indexUsed index the chosen access path uses, user-facing name (null if none) + * estimatedCost planner cost estimate (null if the engine has none) + * rowsReturned ACTUAL rows produced when the plan was run with ANALYZE (null if not analyzed) + * executionTime ACTUAL wall time in milliseconds under ANALYZE (null if not analyzed) + * tree raw engine plan for maximum detail + * * @param string $sql * @param array $binds * @return array @@ -232,6 +279,8 @@ protected function explainSQL(string $sql, array $binds = []): array 'rowsScanned' => null, 'indexUsed' => null, 'estimatedCost' => null, + 'rowsReturned' => null, + 'executionTime' => null, 'tree' => null, ]; } diff --git a/src/Database/Adapter/MariaDB.php b/src/Database/Adapter/MariaDB.php index 8a8d2c90d..7f5adda7c 100644 --- a/src/Database/Adapter/MariaDB.php +++ b/src/Database/Adapter/MariaDB.php @@ -1970,6 +1970,11 @@ protected function explainSQL(string $sql, array $binds = []): array return parent::explainSQL($stripped ?? $sql, $binds); } + protected function getExplainEngine(): string + { + return 'mariadb'; + } + public function getInternalIndexesKeys(): array { return ['primary', '_created_at', '_updated_at', '_tenant_id']; diff --git a/src/Database/Adapter/Mongo.php b/src/Database/Adapter/Mongo.php index 3874c352c..9388bf1bb 100644 --- a/src/Database/Adapter/Mongo.php +++ b/src/Database/Adapter/Mongo.php @@ -3636,6 +3636,8 @@ protected function explainSQL(string $sql, array $binds = []): array 'rowsScanned' => null, 'indexUsed' => null, 'estimatedCost' => null, + 'rowsReturned' => null, + 'executionTime' => null, 'tree' => $captured, ]; } @@ -3659,6 +3661,8 @@ protected function explainSQL(string $sql, array $binds = []): array $tree = null; $rowsScanned = null; $indexUsed = null; + $rowsReturned = null; + $executionTime = null; try { $raw = $this->client->query([ 'explain' => (object) $command, @@ -3667,6 +3671,10 @@ protected function explainSQL(string $sql, array $binds = []): array $tree = \json_decode(\json_encode($raw), true); $rowsScanned = $this->extractMongoRowsScanned($tree); $indexUsed = $this->extractMongoIndexUsed($tree); + // executionStats actually runs the query, so the tree already holds + // the real actuals — no separate timing needed for Mongo. + $rowsReturned = $this->extractMongoRowsReturned($tree); + $executionTime = $this->extractMongoExecutionTime($tree); } catch (\Throwable $e) { // Fall back to the captured command on any explain failure so callers // still see what was attempted. @@ -3678,10 +3686,62 @@ protected function explainSQL(string $sql, array $binds = []): array 'rowsScanned' => $rowsScanned, 'indexUsed' => $indexUsed, 'estimatedCost' => null, + 'rowsReturned' => $rowsReturned, + 'executionTime' => $executionTime, 'tree' => $tree, ]; } + /** + * Actual documents returned, from a Mongo executionStats explain. + * + * @param array|null $tree + */ + private function extractMongoRowsReturned(?array $tree): ?int + { + if (! \is_array($tree)) { + return null; + } + // find: executionStats.nReturned + $find = $tree['executionStats']['nReturned'] ?? null; + if (\is_numeric($find)) { + return (int) $find; + } + // aggregate: last stage's $cursor.executionStats.nReturned + $total = null; + foreach (($tree['stages'] ?? []) as $stage) { + $n = $stage['$cursor']['executionStats']['nReturned'] ?? null; + if (\is_numeric($n)) { + $total = (int) $n; + } + } + return $total; + } + + /** + * Actual execution time in milliseconds, from a Mongo executionStats explain. + * + * @param array|null $tree + */ + private function extractMongoExecutionTime(?array $tree): ?float + { + if (! \is_array($tree)) { + return null; + } + $find = $tree['executionStats']['executionTimeMillis'] ?? null; + if (\is_numeric($find)) { + return (float) $find; + } + $total = null; + foreach (($tree['stages'] ?? []) as $stage) { + $n = $stage['$cursor']['executionStats']['executionTimeMillis'] ?? null; + if (\is_numeric($n)) { + $total = ($total ?? 0) + (float) $n; + } + } + return $total; + } + /** * Walk a Mongo explain executionStats tree and sum totalDocsExamined. * diff --git a/src/Database/Adapter/MySQL.php b/src/Database/Adapter/MySQL.php index 5aaa28107..0ea4c9dee 100644 --- a/src/Database/Adapter/MySQL.php +++ b/src/Database/Adapter/MySQL.php @@ -324,4 +324,9 @@ public function getSupportForTTLIndexes(): bool { return false; } + + protected function getExplainEngine(): string + { + return 'mysql'; + } } diff --git a/src/Database/Adapter/Postgres.php b/src/Database/Adapter/Postgres.php index befebd0a0..e2ff95743 100644 --- a/src/Database/Adapter/Postgres.php +++ b/src/Database/Adapter/Postgres.php @@ -1611,21 +1611,97 @@ protected function explainSQL(string $sql, array $binds = []): array ? $tree['Plan'] : null; + // Postgres nests the real work under the root node's `Plans`. A vector + // query (`ORDER BY emb <-> $1 LIMIT k`) plans as Limit → Index Scan, so + // the index name and scanned rows live on a CHILD, not the root. Walk + // the whole tree for those; cost is cumulative so the root carries it. return [ - 'engine' => 'sql', - 'rowsScanned' => (\is_array($rootPlan) && isset($rootPlan['Plan Rows']) && \is_numeric($rootPlan['Plan Rows'])) - ? (int) $rootPlan['Plan Rows'] - : null, - 'indexUsed' => (\is_array($rootPlan) && isset($rootPlan['Index Name']) && \is_string($rootPlan['Index Name'])) - ? $rootPlan['Index Name'] - : null, + 'engine' => $this->getExplainEngine(), + 'rowsScanned' => $this->extractPgPlanRows($rootPlan), + 'indexUsed' => $this->extractPgIndexUsed($rootPlan), 'estimatedCost' => (\is_array($rootPlan) && isset($rootPlan['Total Cost']) && \is_numeric($rootPlan['Total Cost'])) ? (float) $rootPlan['Total Cost'] : null, + 'rowsReturned' => null, + 'executionTime' => null, 'tree' => $tree, ]; } + protected function getExplainEngine(): string + { + return 'postgres'; + } + + /** + * Estimated rows examined by the deepest scan node — the leaf the access + * path actually reads, not the root (which for a Limit reports just `k`). + * + * @param array|null $plan + */ + private function extractPgPlanRows(?array $plan): ?int + { + $found = null; + $this->walkPgPlan($plan, function (array $node) use (&$found): void { + // Scan nodes touch storage; their `Plan Rows` is the meaningful + // "rows examined" figure. Prefer the first one encountered. + if ($found === null + && isset($node['Node Type']) + && \is_string($node['Node Type']) + && \str_contains($node['Node Type'], 'Scan') + && isset($node['Plan Rows']) + && \is_numeric($node['Plan Rows']) + ) { + $found = (int) $node['Plan Rows']; + } + }); + + // No scan node (e.g. Result/Values plan) — fall back to the root estimate. + if ($found === null && isset($plan['Plan Rows']) && \is_numeric($plan['Plan Rows'])) { + $found = (int) $plan['Plan Rows']; + } + + return $found; + } + + /** + * First index name in the plan tree (e.g. an HNSW/IVFFlat index on a + * pgvector `<->` scan), searched depth-first from the root. + * + * @param array|null $plan + */ + private function extractPgIndexUsed(?array $plan): ?string + { + $found = null; + $this->walkPgPlan($plan, function (array $node) use (&$found): void { + if ($found === null && isset($node['Index Name']) && \is_string($node['Index Name'])) { + $found = $node['Index Name']; + } + }); + return $found; + } + + /** + * Depth-first walk over a Postgres plan node and its nested `Plans`. + * + * @param array|null $node + * @param callable(array): void $visitor + */ + private function walkPgPlan(?array $node, callable $visitor): void + { + if (! \is_array($node)) { + return; + } + $visitor($node); + if (isset($node['Plans']) && \is_array($node['Plans'])) { + foreach ($node['Plans'] as $child) { + if (\is_array($child)) { + $this->walkPgPlan($child, $visitor); + } + } + } + } + /** * Handle distance spatial queries * diff --git a/src/Database/Adapter/SQL.php b/src/Database/Adapter/SQL.php index 9d45be00a..9c5f76c49 100644 --- a/src/Database/Adapter/SQL.php +++ b/src/Database/Adapter/SQL.php @@ -2555,14 +2555,23 @@ protected function explainSQL(string $sql, array $binds = []): array $tree = \is_array($tree) ? $tree : null; return [ - 'engine' => 'sql', + 'engine' => $this->getExplainEngine(), 'rowsScanned' => $this->extractRowsScanned($tree), 'indexUsed' => $this->extractIndexUsed($tree), 'estimatedCost' => $this->extractEstimatedCost($tree), + 'rowsReturned' => null, + 'executionTime' => null, 'tree' => $tree, ]; } + /** + * Precise engine label for the normalized plan (e.g. mysql, mariadb, + * postgres). Lets each surface report its real backend instead of a + * generic 'sql'. + */ + abstract protected function getExplainEngine(): string; + /** * @param array|null $tree */ @@ -3361,6 +3370,8 @@ public function find(Document $collection, array $queries = [], ?int $limit = 25 $this->capturePlan($sql, $binds, 'find', ['collection' => $collection]); } + $explainStart = $this->explainBuffer !== null ? \microtime(true) : null; + try { $stmt = $this->getPDO()->prepare($sql); @@ -3380,6 +3391,11 @@ public function find(Document $collection, array $queries = [], ?int $limit = 25 $results = $stmt->fetchAll(); $stmt->closeCursor(); + if ($explainStart !== null) { + // Real stats from the read that actually ran — no second pass. + $this->recordPlanActuals(\count($results), (\microtime(true) - $explainStart) * 1000); + } + foreach ($results as $index => $document) { if (\array_key_exists('_uid', $document)) { $results[$index]['$id'] = $document['_uid']; @@ -3492,6 +3508,8 @@ public function count(Document $collection, array $queries = [], ?int $max = nul $this->capturePlan($sql, $binds, 'count', ['collection' => $collection]); } + $explainStart = $this->explainBuffer !== null ? \microtime(true) : null; + $stmt = $this->getPDO()->prepare($sql); foreach ($binds as $key => $value) { @@ -3510,6 +3528,11 @@ public function count(Document $collection, array $queries = [], ?int $max = nul $result = $result[0]; } + if ($explainStart !== null) { + // Aggregate: one row out, so rowsReturned is not meaningful — record time only. + $this->recordPlanActuals(null, (\microtime(true) - $explainStart) * 1000); + } + return $result['sum'] ?? 0; } @@ -3592,6 +3615,8 @@ public function sum(Document $collection, string $attribute, array $queries = [] $this->capturePlan($sql, $binds, 'sum', ['collection' => $collection, 'attribute' => $attribute]); } + $explainStart = $this->explainBuffer !== null ? \microtime(true) : null; + $stmt = $this->getPDO()->prepare($sql); foreach ($binds as $key => $value) { @@ -3610,6 +3635,11 @@ public function sum(Document $collection, string $attribute, array $queries = [] $result = $result[0]; } + if ($explainStart !== null) { + // Aggregate: one row out, so rowsReturned is not meaningful — record time only. + $this->recordPlanActuals(null, (\microtime(true) - $explainStart) * 1000); + } + return $result['sum'] ?? 0; } diff --git a/src/Database/Adapter/SQLite.php b/src/Database/Adapter/SQLite.php index 4ce4d03ba..94957ea5b 100644 --- a/src/Database/Adapter/SQLite.php +++ b/src/Database/Adapter/SQLite.php @@ -112,14 +112,21 @@ protected function explainSQL(string $sql, array $binds = []): array $stmt->closeCursor(); return [ - 'engine' => 'sql', + 'engine' => $this->getExplainEngine(), 'rowsScanned' => null, 'indexUsed' => null, 'estimatedCost' => null, + 'rowsReturned' => null, + 'executionTime' => null, 'tree' => ['steps' => \is_array($rows) ? $rows : []], ]; } + protected function getExplainEngine(): string + { + return 'sqlite'; + } + /** * Toggle MariaDB/MySQL emulation. See $emulateMySQL for what this * actually changes. diff --git a/tests/e2e/Adapter/Scopes/ExplainTests.php b/tests/e2e/Adapter/Scopes/ExplainTests.php index 7a1584879..c8bce53d5 100644 --- a/tests/e2e/Adapter/Scopes/ExplainTests.php +++ b/tests/e2e/Adapter/Scopes/ExplainTests.php @@ -65,7 +65,8 @@ public function testWithExplainCapturesPlanForFind(): void $this->assertSame($collection, $entry['context']['collection']); $this->assertArrayHasKey('plan', $entry); - $this->assertSame('sql', $entry['plan']['engine']); + // Engine label is precise per adapter (mysql/mariadb/postgres/sqlite). + $this->assertContains($entry['plan']['engine'], ['mysql', 'mariadb', 'postgres', 'sqlite']); $this->assertArrayHasKey('tree', $entry['plan']); $this->assertNotNull($entry['plan']['tree']); @@ -73,6 +74,13 @@ public function testWithExplainCapturesPlanForFind(): void $this->assertArrayHasKey('indexUsed', $entry['plan']); $this->assertArrayHasKey('estimatedCost', $entry['plan']); + // Actual execution stats from the real find() that ran under explain. + $this->assertArrayHasKey('rowsReturned', $entry['plan']); + $this->assertArrayHasKey('executionTime', $entry['plan']); + // One document matches status=published, and find() rows are measured directly. + $this->assertSame(1, $entry['plan']['rowsReturned']); + $this->assertIsFloat($entry['plan']['executionTime']); + $rawTree = \json_encode($entry['plan']['tree']); $this->assertStringNotContainsString('_perms', $rawTree); diff --git a/tests/unit/ExplainTest.php b/tests/unit/ExplainTest.php index 37d911ca9..a1ff8ddb5 100644 --- a/tests/unit/ExplainTest.php +++ b/tests/unit/ExplainTest.php @@ -6,6 +6,7 @@ use Utopia\Cache\Adapter\None; use Utopia\Cache\Cache; use Utopia\Database\Adapter; +use Utopia\Database\Adapter\Postgres; use Utopia\Database\Database; use Utopia\Database\Document; @@ -93,4 +94,104 @@ public function testSanitizePlanHidesInternalTablesAndRenamesColumns(): void // _id is MySQL's auto-increment column; not renamed. $this->assertSame(['$id', '_id'], $sanitized['nested']['cols']); } + + public function testRecordPlanActualsFillsLastEntry(): void + { + $adapter = $this->getMockBuilder(Adapter::class) + ->onlyMethods([]) + ->getMockForAbstractClass(); + + $buffer = new \ReflectionProperty(Adapter::class, 'explainBuffer'); + $buffer->setValue($adapter, [[ + 'purpose' => 'find', + 'context' => ['collection' => 'movies'], + 'plan' => ['engine' => 'mariadb', 'rowsScanned' => 10], + ]]); + + (new \ReflectionMethod(Adapter::class, 'recordPlanActuals')) + ->invoke($adapter, 7, 1.5); + + $captured = $buffer->getValue($adapter); + $this->assertSame(7, $captured[0]['plan']['rowsReturned']); + $this->assertSame(1.5, $captured[0]['plan']['executionTime']); + } + + public function testRecordPlanActualsIgnoresFailedPlans(): void + { + $adapter = $this->getMockForAbstractClass(Adapter::class); + + $buffer = new \ReflectionProperty(Adapter::class, 'explainBuffer'); + // A failed EXPLAIN is stored as ['error' => ...]; actuals must not be + // grafted onto an error entry as if it were a real plan. + $buffer->setValue($adapter, [[ + 'purpose' => 'find', + 'context' => [], + 'plan' => ['error' => 'boom'], + ]]); + + (new \ReflectionMethod(Adapter::class, 'recordPlanActuals')) + ->invoke($adapter, 7, 1.5); + + $captured = $buffer->getValue($adapter); + $this->assertArrayNotHasKey('rowsReturned', $captured[0]['plan']); + $this->assertSame(['error' => 'boom'], $captured[0]['plan']); + } + + public function testRecordPlanActualsNoopWhenNotCapturing(): void + { + $adapter = $this->getMockForAbstractClass(Adapter::class); + + // explainBuffer defaults to null (not capturing) — must be a safe no-op. + (new \ReflectionMethod(Adapter::class, 'recordPlanActuals')) + ->invoke($adapter, 7, 1.5); + + $buffer = new \ReflectionProperty(Adapter::class, 'explainBuffer'); + $this->assertNull($buffer->getValue($adapter)); + } + + public function testPostgresExtractionRecursesIntoChildPlans(): void + { + // Canonical pgvector plan: Limit -> Index Scan. The index name and the + // scanned rows live on the CHILD; the root Limit only knows `k`. + $tree = [ + 'Plan' => [ + 'Node Type' => 'Limit', + 'Plan Rows' => 5, + 'Total Cost' => 42.7, + 'Plans' => [ + [ + 'Node Type' => 'Index Scan', + 'Index Name' => 'movies_embedding_hnsw', + 'Plan Rows' => 950, + 'Total Cost' => 41.0, + ], + ], + ], + ]; + + $adapter = (new \ReflectionClass(Postgres::class))->newInstanceWithoutConstructor(); + $root = $tree['Plan']; + + $rows = (new \ReflectionMethod(Postgres::class, 'extractPgPlanRows'))->invoke($adapter, $root); + $index = (new \ReflectionMethod(Postgres::class, 'extractPgIndexUsed'))->invoke($adapter, $root); + + // rowsScanned comes from the scan leaf (950), NOT the Limit's 5. + $this->assertSame(950, $rows); + $this->assertSame('movies_embedding_hnsw', $index); + } + + public function testPostgresExtractionFallsBackToRootRowsWithoutScan(): void + { + $adapter = (new \ReflectionClass(Postgres::class))->newInstanceWithoutConstructor(); + $root = [ + 'Node Type' => 'Result', + 'Plan Rows' => 1, + ]; + + $rows = (new \ReflectionMethod(Postgres::class, 'extractPgPlanRows'))->invoke($adapter, $root); + $index = (new \ReflectionMethod(Postgres::class, 'extractPgIndexUsed'))->invoke($adapter, $root); + + $this->assertSame(1, $rows); + $this->assertNull($index); + } } From 4176cef550b84f65bc74e75e93d73fdf67eca48b Mon Sep 17 00:00:00 2001 From: Prem Palanisamy Date: Mon, 1 Jun 2026 12:50:34 +0100 Subject: [PATCH 06/16] Fix phpstan errors and document withExplain return contract - Mongo explainSQL: guard json_encode result against false before decode - Rewrite extractMongoIndexUsed as a returning recursion so the index walk has no dead null-comparison and is easier to follow - Guard json_encode in the explain e2e assertion - Document that withExplain returns the plan, not the callback result --- src/Database/Adapter/Mongo.php | 34 ++++++++++------------- src/Database/Database.php | 12 ++++++-- tests/e2e/Adapter/Scopes/ExplainTests.php | 2 +- 3 files changed, 26 insertions(+), 22 deletions(-) diff --git a/src/Database/Adapter/Mongo.php b/src/Database/Adapter/Mongo.php index 9388bf1bb..58de8fbca 100644 --- a/src/Database/Adapter/Mongo.php +++ b/src/Database/Adapter/Mongo.php @@ -3668,7 +3668,7 @@ protected function explainSQL(string $sql, array $binds = []): array 'explain' => (object) $command, 'verbosity' => 'executionStats', ]); - $tree = \json_decode(\json_encode($raw), true); + $tree = \json_decode(\json_encode($raw) ?: 'null', true); $rowsScanned = $this->extractMongoRowsScanned($tree); $indexUsed = $this->extractMongoIndexUsed($tree); // executionStats actually runs the query, so the tree already holds @@ -3778,26 +3778,22 @@ private function extractMongoIndexUsed(?array $tree): ?string if (! \is_array($tree)) { return null; } - $found = null; - $walk = function ($node) use (&$walk, &$found): void { - if ($found !== null || ! \is_array($node)) { - return; - } - if (($node['stage'] ?? null) === 'IXSCAN' && isset($node['indexName']) && \is_string($node['indexName'])) { - $found = $node['indexName']; - return; - } - foreach ($node as $value) { - if (\is_array($value)) { - $walk($value); - if ($found !== null) { - return; - } + + if (($tree['stage'] ?? null) === 'IXSCAN' && isset($tree['indexName']) && \is_string($tree['indexName'])) { + return $tree['indexName']; + } + + // Depth-first: first IXSCAN's indexName wins. + foreach ($tree as $value) { + if (\is_array($value)) { + $found = $this->extractMongoIndexUsed($value); + if ($found !== null) { + return $found; } } - }; - $walk($tree); - return $found; + } + + return null; } protected function processException(\Throwable $e): \Throwable diff --git a/src/Database/Database.php b/src/Database/Database.php index baece1587..be863d4b6 100644 --- a/src/Database/Database.php +++ b/src/Database/Database.php @@ -1455,9 +1455,17 @@ public function withPreserveDates(callable $callback): mixed } /** + * Run $callback with explain capture enabled and return the captured plans. + * + * Every find/count/sum the callback issues is captured as a plan entry. The + * callback's own return value is intentionally NOT propagated — this method + * always returns the plan Document (`{ queries: [...] }`), not the query + * results. Callers wanting the rows should run the read separately; explain + * is a diagnostic that mirrors the read, not a replacement for it. + * * @param callable $callback - * @return Document - * @throws \Throwable + * @return Document plan document with a `queries` attribute (list of captured entries) + * @throws \Throwable rethrown from $callback; capture is always stopped first */ public function withExplain(callable $callback): Document { diff --git a/tests/e2e/Adapter/Scopes/ExplainTests.php b/tests/e2e/Adapter/Scopes/ExplainTests.php index c8bce53d5..dccc33dcd 100644 --- a/tests/e2e/Adapter/Scopes/ExplainTests.php +++ b/tests/e2e/Adapter/Scopes/ExplainTests.php @@ -81,7 +81,7 @@ public function testWithExplainCapturesPlanForFind(): void $this->assertSame(1, $entry['plan']['rowsReturned']); $this->assertIsFloat($entry['plan']['executionTime']); - $rawTree = \json_encode($entry['plan']['tree']); + $rawTree = \json_encode($entry['plan']['tree']) ?: ''; $this->assertStringNotContainsString('_perms', $rawTree); $database->deleteCollection($collection); From 9dbfdca57850547201a56db97801affb41ed878c Mon Sep 17 00:00:00 2001 From: Prem Palanisamy Date: Mon, 1 Jun 2026 13:10:11 +0100 Subject: [PATCH 07/16] Trim redundant explain comments to the essential why Drop the DTO field-table duplicated in the explainSQL docblock and the verbose recordPlanActuals/rename caveats; keep the design rationale and gotchas. --- src/Database/Adapter.php | 32 ++++++++++---------------------- 1 file changed, 10 insertions(+), 22 deletions(-) diff --git a/src/Database/Adapter.php b/src/Database/Adapter.php index 5433f0f7a..43d5b9be0 100644 --- a/src/Database/Adapter.php +++ b/src/Database/Adapter.php @@ -171,13 +171,10 @@ protected function capturePlan(string $sql, array $binds = [], string $purpose = } /** - * Attach the REAL execution stats to the most recently captured plan entry. + * Attach real execution stats to the most recently captured plan entry. * - * The explain endpoint runs the same query listRows runs, so instead of - * paying for a second EXPLAIN ANALYZE pass we just measure the read that - * already happens: callers time their actual statement and report the - * actual rows it produced. No-op when not capturing, so the normal read - * path is untouched. + * Avoids a second EXPLAIN ANALYZE pass by measuring the read that already + * runs inside the explain scope. * * @param int|null $rowsReturned actual rows the statement returned (null when not meaningful, e.g. an aggregate) * @param float|null $executionTime actual wall time of the statement in milliseconds @@ -238,13 +235,10 @@ private function renameInternalIdentifier(string $name): string if (isset(self::EXPLAIN_COLUMN_RENAMES[$name])) { return self::EXPLAIN_COLUMN_RENAMES[$name]; } - // EXPLAIN tree string-values can embed internal identifiers (e.g. - // index_condition: "main.`_uid` = '...'"). Substring-rewrite each. - // NOTE: this is a best-effort, display-only substring replace — a user - // column whose name happens to contain "_uid"/"_tenant"/etc. would be - // rewritten too. Acceptable because the output is for human reading of - // the plan, not for round-tripping back to a real column name; the raw - // `tree` is the same string pre-rename if an exact value is ever needed. + // Plan strings embed internal identifiers (e.g. index_condition: + // "main.`_uid` = '...'"). Best-effort, display-only substring rewrite: + // a user column containing "_uid"/"_tenant"/etc. is rewritten too, which + // is fine since this is for reading the plan, not round-tripping names. if (\str_contains($name, '_')) { foreach (self::EXPLAIN_COLUMN_RENAMES as $internal => $public) { if (\str_contains($name, $internal)) { @@ -258,15 +252,9 @@ private function renameInternalIdentifier(string $name): string /** * Produce a normalized query plan for a single statement. * - * Every adapter returns the same fixed shape so the public DTO can stay - * typed regardless of engine: - * engine precise backend label (mysql|mariadb|postgres|mongo|...) - * rowsScanned estimated rows the planner expects to examine (null if N/A) - * indexUsed index the chosen access path uses, user-facing name (null if none) - * estimatedCost planner cost estimate (null if the engine has none) - * rowsReturned ACTUAL rows produced when the plan was run with ANALYZE (null if not analyzed) - * executionTime ACTUAL wall time in milliseconds under ANALYZE (null if not analyzed) - * tree raw engine plan for maximum detail + * Every adapter returns the same fixed shape (engine, rowsScanned, + * indexUsed, estimatedCost, rowsReturned, executionTime, tree) so the + * public DTO stays typed regardless of engine. * * @param string $sql * @param array $binds From e97cac613f6763c8ca03bc7d97adee03cf1c0ba6 Mon Sep 17 00:00:00 2001 From: Prem Palanisamy Date: Mon, 1 Jun 2026 13:45:25 +0100 Subject: [PATCH 08/16] Fix withExplain return value and stop Mongo double-execution - withExplain now returns the callback's own result (matching withTenant/ withPreserveSequence); the plan is exposed via a by-ref out-param, so one call yields both rows and plan - Mongo explain uses queryPlanner verbosity instead of executionStats so it no longer executes every captured find/count/sum a second time; real rowsReturned/executionTime come from timing the actual read, as in SQL - Restrict Mongo index extraction to the winning plan so a rejected-plan IXSCAN is never reported when the query runs a COLLSCAN - Route the Postgres EXPLAIN through execute() so it inherits statement_timeout and the adapter's PDO error handling --- src/Database/Adapter/Mongo.php | 177 ++++++++++------------ src/Database/Adapter/Postgres.php | 13 +- src/Database/Database.php | 29 ++-- tests/e2e/Adapter/Scopes/ExplainTests.php | 22 ++- tests/unit/ExplainTest.php | 13 +- 5 files changed, 127 insertions(+), 127 deletions(-) diff --git a/src/Database/Adapter/Mongo.php b/src/Database/Adapter/Mongo.php index 58de8fbca..c3362cf0d 100644 --- a/src/Database/Adapter/Mongo.php +++ b/src/Database/Adapter/Mongo.php @@ -2205,6 +2205,8 @@ public function find(Document $collection, array $queries = [], ?int $limit = 25 ); } + $explainStart = $this->explainBuffer !== null ? \microtime(true) : null; + try { // Use proper cursor iteration with reasonable batch size $options['batchSize'] = self::DEFAULT_BATCH_SIZE; @@ -2263,6 +2265,12 @@ public function find(Document $collection, array $queries = [], ?int $limit = 25 } } + if ($explainStart !== null) { + // Real stats from the read that actually ran (queryPlanner explain + // above does not execute), mirroring the SQL adapter. + $this->recordPlanActuals(\count($found), (\microtime(true) - $explainStart) * 1000); + } + return $found; } @@ -2422,24 +2430,30 @@ public function count(Document $collection, array $queries = [], ?int $max = nul ); } - try { + $explainStart = $this->explainBuffer !== null ? \microtime(true) : null; + try { $result = $this->client->aggregate($name, $pipeline, $options); + } catch (MongoException $e) { + return 0; + } finally { + if ($explainStart !== null) { + // Aggregate: one row out, so rowsReturned is not meaningful — record time only. + $this->recordPlanActuals(null, (\microtime(true) - $explainStart) * 1000); + } + } - // Aggregation returns stdClass with cursor property containing firstBatch - if (isset($result->cursor) && !empty($result->cursor->firstBatch)) { - $firstResult = $result->cursor->firstBatch[0]; + // Aggregation returns stdClass with cursor property containing firstBatch + if (isset($result->cursor) && !empty($result->cursor->firstBatch)) { + $firstResult = $result->cursor->firstBatch[0]; - // Handle both $count and $group response formats - if (isset($firstResult->total)) { - return (int)$firstResult->total; - } + // Handle both $count and $group response formats + if (isset($firstResult->total)) { + return (int)$firstResult->total; } - - return 0; - } catch (MongoException $e) { - return 0; } + + return 0; } @@ -2506,7 +2520,16 @@ public function sum(Document $collection, string $attribute, array $queries = [] ); } - return $this->client->aggregate($name, $pipeline, $options)->cursor->firstBatch[0]->total ?? 0; + $explainStart = $this->explainBuffer !== null ? \microtime(true) : null; + + try { + return $this->client->aggregate($name, $pipeline, $options)->cursor->firstBatch[0]->total ?? 0; + } finally { + if ($explainStart !== null) { + // Aggregate: one row out, so rowsReturned is not meaningful — record time only. + $this->recordPlanActuals(null, (\microtime(true) - $explainStart) * 1000); + } + } } /** @@ -3659,22 +3682,17 @@ protected function explainSQL(string $sql, array $binds = []): array } $tree = null; - $rowsScanned = null; $indexUsed = null; - $rowsReturned = null; - $executionTime = null; try { + // queryPlanner, NOT executionStats: executionStats re-runs the + // query, double-executing every captured read. Actuals come from + // timing the real find/count/sum via recordPlanActuals(). $raw = $this->client->query([ 'explain' => (object) $command, - 'verbosity' => 'executionStats', + 'verbosity' => 'queryPlanner', ]); $tree = \json_decode(\json_encode($raw) ?: 'null', true); - $rowsScanned = $this->extractMongoRowsScanned($tree); - $indexUsed = $this->extractMongoIndexUsed($tree); - // executionStats actually runs the query, so the tree already holds - // the real actuals — no separate timing needed for Mongo. - $rowsReturned = $this->extractMongoRowsReturned($tree); - $executionTime = $this->extractMongoExecutionTime($tree); + $indexUsed = $this->extractMongoIndexUsed($tree); } catch (\Throwable $e) { // Fall back to the captured command on any explain failure so callers // still see what was attempted. @@ -3683,116 +3701,85 @@ protected function explainSQL(string $sql, array $binds = []): array return [ 'engine' => 'mongo', - 'rowsScanned' => $rowsScanned, + // rowsScanned is an execution stat Mongo only emits under + // executionStats; queryPlanner gives the plan shape, not counts. + 'rowsScanned' => null, 'indexUsed' => $indexUsed, 'estimatedCost' => null, - 'rowsReturned' => $rowsReturned, - 'executionTime' => $executionTime, + 'rowsReturned' => null, + 'executionTime' => null, 'tree' => $tree, ]; } /** - * Actual documents returned, from a Mongo executionStats explain. + * Find the IXSCAN indexName from the WINNING plan of a Mongo explain tree. * - * @param array|null $tree - */ - private function extractMongoRowsReturned(?array $tree): ?int - { - if (! \is_array($tree)) { - return null; - } - // find: executionStats.nReturned - $find = $tree['executionStats']['nReturned'] ?? null; - if (\is_numeric($find)) { - return (int) $find; - } - // aggregate: last stage's $cursor.executionStats.nReturned - $total = null; - foreach (($tree['stages'] ?? []) as $stage) { - $n = $stage['$cursor']['executionStats']['nReturned'] ?? null; - if (\is_numeric($n)) { - $total = (int) $n; - } - } - return $total; - } - - /** - * Actual execution time in milliseconds, from a Mongo executionStats explain. + * Only descends into `winningPlan` branches — never `rejectedPlans`, which + * can hold IXSCAN stages even when the winning plan is a COLLSCAN, so a + * blind walk would report an index that the query does not actually use. * * @param array|null $tree */ - private function extractMongoExecutionTime(?array $tree): ?float + private function extractMongoIndexUsed(?array $tree): ?string { if (! \is_array($tree)) { return null; } - $find = $tree['executionStats']['executionTimeMillis'] ?? null; - if (\is_numeric($find)) { - return (float) $find; - } - $total = null; - foreach (($tree['stages'] ?? []) as $stage) { - $n = $stage['$cursor']['executionStats']['executionTimeMillis'] ?? null; - if (\is_numeric($n)) { - $total = ($total ?? 0) + (float) $n; + + foreach ($this->findWinningPlans($tree) as $winningPlan) { + $found = $this->findIxscanIndex($winningPlan); + if ($found !== null) { + return $found; } } - return $total; + + return null; } /** - * Walk a Mongo explain executionStats tree and sum totalDocsExamined. + * Collect every `winningPlan` subtree, skipping rejectedPlans branches. * - * @param array|null $tree + * @param array $tree + * @return array> */ - private function extractMongoRowsScanned(?array $tree): ?int + private function findWinningPlans(array $tree): array { - if (! \is_array($tree)) { - return null; - } - // find: executionStats.totalDocsExamined - $find = $tree['executionStats']['totalDocsExamined'] ?? null; - if (\is_numeric($find)) { - return (int) $find; - } - // aggregate: stages[].$cursor.executionStats.totalDocsExamined - $total = null; - foreach (($tree['stages'] ?? []) as $stage) { - $n = $stage['$cursor']['executionStats']['totalDocsExamined'] ?? null; - if (\is_numeric($n)) { - $total = ($total ?? 0) + (int) $n; + $plans = []; + foreach ($tree as $key => $value) { + if (! \is_array($value)) { + continue; + } + if ($key === 'winningPlan') { + $plans[] = $value; + continue; } + if ($key === 'rejectedPlans') { + continue; + } + $plans = \array_merge($plans, $this->findWinningPlans($value)); } - return $total; + return $plans; } /** - * Find the winning IXSCAN indexName from a Mongo explain tree. + * First IXSCAN indexName within a single (winning) plan subtree. * - * @param array|null $tree + * @param array $plan */ - private function extractMongoIndexUsed(?array $tree): ?string + private function findIxscanIndex(array $plan): ?string { - if (! \is_array($tree)) { - return null; - } - - if (($tree['stage'] ?? null) === 'IXSCAN' && isset($tree['indexName']) && \is_string($tree['indexName'])) { - return $tree['indexName']; + if (($plan['stage'] ?? null) === 'IXSCAN' && isset($plan['indexName']) && \is_string($plan['indexName'])) { + return $plan['indexName']; } - - // Depth-first: first IXSCAN's indexName wins. - foreach ($tree as $value) { + foreach ($plan as $value) { if (\is_array($value)) { - $found = $this->extractMongoIndexUsed($value); + $found = $this->findIxscanIndex($value); if ($found !== null) { return $found; } } } - return null; } diff --git a/src/Database/Adapter/Postgres.php b/src/Database/Adapter/Postgres.php index e2ff95743..d8f352fba 100644 --- a/src/Database/Adapter/Postgres.php +++ b/src/Database/Adapter/Postgres.php @@ -1597,9 +1597,16 @@ protected function explainSQL(string $sql, array $binds = []): array } } - $stmt->execute(); - $raw = $stmt->fetchColumn(); - $stmt->closeCursor(); + // Route through execute() so the EXPLAIN inherits statement_timeout and + // the same PDO error handling as the real read it mirrors. + try { + $this->execute($stmt); + $raw = $stmt->fetchColumn(); + } catch (PDOException $e) { + throw $this->processException($e); + } finally { + $stmt->closeCursor(); + } $decoded = \is_string($raw) ? \json_decode($raw, true) : null; // Postgres wraps the plan in a one-element array. diff --git a/src/Database/Database.php b/src/Database/Database.php index be863d4b6..3e70765f2 100644 --- a/src/Database/Database.php +++ b/src/Database/Database.php @@ -1455,30 +1455,29 @@ public function withPreserveDates(callable $callback): mixed } /** - * Run $callback with explain capture enabled and return the captured plans. + * Run $callback with explain capture enabled. * - * Every find/count/sum the callback issues is captured as a plan entry. The - * callback's own return value is intentionally NOT propagated — this method - * always returns the plan Document (`{ queries: [...] }`), not the query - * results. Callers wanting the rows should run the read separately; explain - * is a diagnostic that mirrors the read, not a replacement for it. + * Returns the callback's own result (like withPreserveSequence/withTenant), + * so callers get their query output normally. The captured query plan is + * written to the by-reference $plan Document (`{ queries: [...] }`), letting + * one call yield both the rows and their plan. * - * @param callable $callback - * @return Document plan document with a `queries` attribute (list of captured entries) + * @template T + * @param callable(): T $callback + * @param Document|null $plan out-param: receives the captured plan document + * @return T the callback's return value * @throws \Throwable rethrown from $callback; capture is always stopped first */ - public function withExplain(callable $callback): Document + public function withExplain(callable $callback, ?Document &$plan = null): mixed { $this->adapter->startExplainCapture(); try { - $callback(); + return $callback(); } finally { - $captured = $this->adapter->stopExplainCapture(); + $plan = new Document([ + 'queries' => $this->adapter->stopExplainCapture(), + ]); } - - return new Document([ - 'queries' => $captured, - ]); } public function getPreserveSequence(): bool diff --git a/tests/e2e/Adapter/Scopes/ExplainTests.php b/tests/e2e/Adapter/Scopes/ExplainTests.php index dccc33dcd..93404ea26 100644 --- a/tests/e2e/Adapter/Scopes/ExplainTests.php +++ b/tests/e2e/Adapter/Scopes/ExplainTests.php @@ -47,11 +47,13 @@ public function testWithExplainCapturesPlanForFind(): void 'status' => 'draft', ])); - $plan = $database->withExplain(fn () => $database->find($collection, [ + $plan = null; + $rows = $database->withExplain(fn () => $database->find($collection, [ Query::equal('status', ['published']), Query::limit(10), - ])); + ]), $plan); + $this->assertIsArray($rows); $this->assertInstanceOf(Document::class, $plan); $entries = $plan->getAttribute('queries'); @@ -114,14 +116,16 @@ public function testWithExplainExceptionDoesNotLeaveBufferOpen(): void $this->markTestSkipped('Explain capture is only wired in the SQL adapter today.'); } + $propagated = false; try { $database->withExplain(function () { throw new \RuntimeException('boom'); }); - $this->fail('Expected RuntimeException to propagate'); } catch (\RuntimeException) { + $propagated = true; } + $this->assertTrue($propagated, 'Expected RuntimeException to propagate'); $this->assertFalse($database->getAdapter()->isExplainCapturing()); } @@ -153,10 +157,11 @@ public function testWithExplainCapturesCountAndSum(): void // Regression guard: count() used to crash inside withExplain because // the context array called ->getId() on a string. - $plan = $database->withExplain(function () use ($database, $collection): void { + $plan = null; + $database->withExplain(function () use ($database, $collection): void { $database->count($collection); $database->sum($collection, 'score'); - }); + }, $plan); $entries = $plan->getAttribute('queries'); $this->assertIsArray($entries); @@ -203,11 +208,14 @@ public function testWithExplainWorksInsideTransactionOnPooledAdapter(): void // explain on the *same* pinned connection. Regression guard: this used // to silently return [] because the pinned-adapter early return // bypassed the start/stop/drain logic. - $plan = $database->withExplain(function () use ($database, $collection) { + $plan = null; + $rows = $database->withExplain(function () use ($database, $collection) { return $database->withTransaction(fn () => $database->find($collection, [ Query::limit(5), ])); - }); + }, $plan); + + $this->assertIsArray($rows); $entries = $plan->getAttribute('queries'); $this->assertIsArray($entries); diff --git a/tests/unit/ExplainTest.php b/tests/unit/ExplainTest.php index a1ff8ddb5..2e3c266d4 100644 --- a/tests/unit/ExplainTest.php +++ b/tests/unit/ExplainTest.php @@ -36,15 +36,14 @@ public function testWithExplainTogglesCaptureAndWrapsResult(): void $db = new Database($adapter, new Cache(new None())); - $callbackRan = false; - $result = $db->withExplain(function () use (&$callbackRan) { - $callbackRan = true; - }); + // The callback result must propagate; the plan comes via the out-param. + $plan = null; + $result = $db->withExplain(fn () => 'callback-result', $plan); - $this->assertTrue($callbackRan); - $this->assertInstanceOf(Document::class, $result); + $this->assertSame('callback-result', $result); + $this->assertInstanceOf(Document::class, $plan); - $entries = $result->getAttribute('queries'); + $entries = $plan->getAttribute('queries'); $this->assertIsArray($entries); $this->assertCount(1, $entries); $this->assertSame('find', $entries[0]['purpose']); From 8707f19bd1aaa357a29baa770841988fd3afbf02 Mon Sep 17 00:00:00 2001 From: Prem Palanisamy Date: Mon, 1 Jun 2026 16:15:20 +0100 Subject: [PATCH 09/16] Route SQL and SQLite EXPLAIN through execute() for consistent error handling Align the base SQL and SQLite explainSQL cursor handling with the Postgres override: run the EXPLAIN via execute() so it inherits the timeout wrapper and processException mapping, and close the cursor in a finally. --- src/Database/Adapter/SQL.php | 13 ++++++++++--- src/Database/Adapter/SQLite.php | 11 ++++++++--- 2 files changed, 18 insertions(+), 6 deletions(-) diff --git a/src/Database/Adapter/SQL.php b/src/Database/Adapter/SQL.php index 9c5f76c49..3e696ba84 100644 --- a/src/Database/Adapter/SQL.php +++ b/src/Database/Adapter/SQL.php @@ -2547,9 +2547,16 @@ protected function explainSQL(string $sql, array $binds = []): array } } - $stmt->execute(); - $raw = $stmt->fetchColumn(); - $stmt->closeCursor(); + // Route through execute() so the EXPLAIN inherits the same timeout and + // PDO error handling as the real read it mirrors. + try { + $this->execute($stmt); + $raw = $stmt->fetchColumn(); + } catch (PDOException $e) { + throw $this->processException($e); + } finally { + $stmt->closeCursor(); + } $tree = \is_string($raw) ? \json_decode($raw, true) : null; $tree = \is_array($tree) ? $tree : null; diff --git a/src/Database/Adapter/SQLite.php b/src/Database/Adapter/SQLite.php index 94957ea5b..4cf28ea77 100644 --- a/src/Database/Adapter/SQLite.php +++ b/src/Database/Adapter/SQLite.php @@ -107,9 +107,14 @@ protected function explainSQL(string $sql, array $binds = []): array } } - $stmt->execute(); - $rows = $stmt->fetchAll(\PDO::FETCH_ASSOC); - $stmt->closeCursor(); + try { + $this->execute($stmt); + $rows = $stmt->fetchAll(\PDO::FETCH_ASSOC); + } catch (PDOException $e) { + throw $this->processException($e); + } finally { + $stmt->closeCursor(); + } return [ 'engine' => $this->getExplainEngine(), From 343e9c2c7101b0968142eb4d1db68c7a55575354 Mon Sep 17 00:00:00 2001 From: Prem Palanisamy Date: Mon, 1 Jun 2026 16:33:41 +0100 Subject: [PATCH 10/16] Preserve original Mongo count() body when adding explain timing MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Keep the result-processing inside the try and just add the finally for recordPlanActuals, instead of restructuring the method — minimises the diff. --- src/Database/Adapter/Mongo.php | 24 ++++++++++++------------ 1 file changed, 12 insertions(+), 12 deletions(-) diff --git a/src/Database/Adapter/Mongo.php b/src/Database/Adapter/Mongo.php index c3362cf0d..ca6739678 100644 --- a/src/Database/Adapter/Mongo.php +++ b/src/Database/Adapter/Mongo.php @@ -2434,6 +2434,18 @@ public function count(Document $collection, array $queries = [], ?int $max = nul try { $result = $this->client->aggregate($name, $pipeline, $options); + + // Aggregation returns stdClass with cursor property containing firstBatch + if (isset($result->cursor) && !empty($result->cursor->firstBatch)) { + $firstResult = $result->cursor->firstBatch[0]; + + // Handle both $count and $group response formats + if (isset($firstResult->total)) { + return (int)$firstResult->total; + } + } + + return 0; } catch (MongoException $e) { return 0; } finally { @@ -2442,18 +2454,6 @@ public function count(Document $collection, array $queries = [], ?int $max = nul $this->recordPlanActuals(null, (\microtime(true) - $explainStart) * 1000); } } - - // Aggregation returns stdClass with cursor property containing firstBatch - if (isset($result->cursor) && !empty($result->cursor->firstBatch)) { - $firstResult = $result->cursor->firstBatch[0]; - - // Handle both $count and $group response formats - if (isset($firstResult->total)) { - return (int)$firstResult->total; - } - } - - return 0; } From afee5a9f4f734410054ced37a8e9d389813402fa Mon Sep 17 00:00:00 2001 From: Prem Palanisamy Date: Mon, 1 Jun 2026 17:16:44 +0100 Subject: [PATCH 11/16] Add getSupportForExplain() capability and test Mongo explain Explain capture is wired in both SQL and Mongo, but the e2e tests gated on instanceof SQL with a stale 'only SQL' comment, so the engine-agnostic tests never ran on Mongo. Add getSupportForExplain() (false on base/Memory/Redis, true on SQL and Mongo, delegated by Pool) and gate the engine-agnostic tests on it. The find test keeps an instanceof SQL guard since it asserts the SQL-specific engine label and plan tree. --- src/Database/Adapter.php | 10 ++++++++++ src/Database/Adapter/Mongo.php | 5 +++++ src/Database/Adapter/Pool.php | 5 +++++ src/Database/Adapter/SQL.php | 5 +++++ tests/e2e/Adapter/Scopes/ExplainTests.php | 19 ++++++++++--------- 5 files changed, 35 insertions(+), 9 deletions(-) diff --git a/src/Database/Adapter.php b/src/Database/Adapter.php index 43d5b9be0..0c0a4a012 100644 --- a/src/Database/Adapter.php +++ b/src/Database/Adapter.php @@ -1779,6 +1779,16 @@ public function getSupportForTTLIndexes(): bool return false; } + /** + * Is query explain (plan capture via withExplain) supported? + * + * @return bool + */ + public function getSupportForExplain(): bool + { + return false; + } + /** * Does the adapter support transaction retries? * diff --git a/src/Database/Adapter/Mongo.php b/src/Database/Adapter/Mongo.php index ca6739678..6c828439f 100644 --- a/src/Database/Adapter/Mongo.php +++ b/src/Database/Adapter/Mongo.php @@ -3983,6 +3983,11 @@ public function getSupportForTTLIndexes(): bool return true; } + public function getSupportForExplain(): bool + { + return true; + } + public function getSupportForTransactionRetries(): bool { return false; diff --git a/src/Database/Adapter/Pool.php b/src/Database/Adapter/Pool.php index 950a99a19..20c240072 100644 --- a/src/Database/Adapter/Pool.php +++ b/src/Database/Adapter/Pool.php @@ -423,6 +423,11 @@ public function getSupportForSchemas(): bool return $this->delegate(__FUNCTION__, \func_get_args()); } + public function getSupportForExplain(): bool + { + return $this->delegate(__FUNCTION__, \func_get_args()); + } + public function getSupportForAttributes(): bool { return $this->delegate(__FUNCTION__, \func_get_args()); diff --git a/src/Database/Adapter/SQL.php b/src/Database/Adapter/SQL.php index 3e696ba84..ab3d9d585 100644 --- a/src/Database/Adapter/SQL.php +++ b/src/Database/Adapter/SQL.php @@ -2579,6 +2579,11 @@ protected function explainSQL(string $sql, array $binds = []): array */ abstract protected function getExplainEngine(): string; + public function getSupportForExplain(): bool + { + return true; + } + /** * @param array|null $tree */ diff --git a/tests/e2e/Adapter/Scopes/ExplainTests.php b/tests/e2e/Adapter/Scopes/ExplainTests.php index 93404ea26..77fe33cd0 100644 --- a/tests/e2e/Adapter/Scopes/ExplainTests.php +++ b/tests/e2e/Adapter/Scopes/ExplainTests.php @@ -19,8 +19,9 @@ public function testWithExplainCapturesPlanForFind(): void /** @var Database $database */ $database = $this->getDatabase(); + // SQL-only: asserts the precise engine label and a non-null plan tree. if (! $database->getAdapter() instanceof SQL) { - $this->markTestSkipped('Explain capture is only wired in the SQL adapter today.'); + $this->markTestSkipped('Engine label and plan tree assertions are SQL-specific.'); } $database->getAuthorization()->addRole(Role::any()->toString()); @@ -94,8 +95,8 @@ public function testWithExplainBufferIsClearedAfterScope(): void /** @var Database $database */ $database = $this->getDatabase(); - if (! $database->getAdapter() instanceof SQL) { - $this->markTestSkipped('Explain capture is only wired in the SQL adapter today.'); + if (! $database->getAdapter()->getSupportForExplain()) { + $this->markTestSkipped('Adapter does not support explain.'); } $this->assertFalse($database->getAdapter()->isExplainCapturing()); @@ -112,8 +113,8 @@ public function testWithExplainExceptionDoesNotLeaveBufferOpen(): void /** @var Database $database */ $database = $this->getDatabase(); - if (! $database->getAdapter() instanceof SQL) { - $this->markTestSkipped('Explain capture is only wired in the SQL adapter today.'); + if (! $database->getAdapter()->getSupportForExplain()) { + $this->markTestSkipped('Adapter does not support explain.'); } $propagated = false; @@ -134,8 +135,8 @@ public function testWithExplainCapturesCountAndSum(): void /** @var Database $database */ $database = $this->getDatabase(); - if (! $database->getAdapter() instanceof SQL) { - $this->markTestSkipped('Explain capture is only wired in the SQL adapter today.'); + if (! $database->getAdapter()->getSupportForExplain()) { + $this->markTestSkipped('Adapter does not support explain.'); } $database->getAuthorization()->addRole(Role::any()->toString()); @@ -230,8 +231,8 @@ public function testNestedWithExplainThrows(): void /** @var Database $database */ $database = $this->getDatabase(); - if (! $database->getAdapter() instanceof SQL) { - $this->markTestSkipped('Explain capture is only wired in the SQL adapter today.'); + if (! $database->getAdapter()->getSupportForExplain()) { + $this->markTestSkipped('Adapter does not support explain.'); } $this->expectException(DatabaseException::class); From ff60421ef76411cad9304e243df3bb40dcd4ab9a Mon Sep 17 00:00:00 2001 From: Prem Palanisamy Date: Mon, 1 Jun 2026 18:19:28 +0100 Subject: [PATCH 12/16] Fix re-entrant explain capture on pinned pool adapter MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit While the pool is capturing, a nested delegate() on the pinned transaction adapter — e.g. a before(find) transformation issuing its own query — re-called startExplainCapture() on the already-capturing adapter and threw 'cannot be nested', breaking withExplain + withTransaction for apps with such listeners. Only start (and own the stop/drain of) capture when the adapter isn't already capturing; nested calls accumulate into the same buffer. Adds a unit test that fails on the old behavior. --- src/Database/Adapter/Pool.php | 12 +++++++++--- tests/unit/ExplainTest.php | 29 +++++++++++++++++++++++++++++ 2 files changed, 38 insertions(+), 3 deletions(-) diff --git a/src/Database/Adapter/Pool.php b/src/Database/Adapter/Pool.php index 20c240072..8ff37c26e 100644 --- a/src/Database/Adapter/Pool.php +++ b/src/Database/Adapter/Pool.php @@ -46,8 +46,14 @@ public function delegate(string $method, array $args): mixed // captures aggregate back into the pool buffer — needed for both the // pinned-transaction and pooled paths. $invoke = function (Adapter $adapter) use ($method, $args): mixed { - $capturing = $this->isExplainCapturing(); - if ($capturing) { + // Only start (and own the stop/drain of) capture when the adapter + // isn't already capturing. A pinned adapter is reused across nested + // delegate() calls — e.g. a before()-listener firing its own query + // inside the read — so re-starting would wrongly throw "cannot be + // nested". Nested calls just let their plans accumulate into the + // same buffer, drained once by the outermost call. + $startedCapture = $this->isExplainCapturing() && ! $adapter->isExplainCapturing(); + if ($startedCapture) { $adapter->startExplainCapture(); } try { @@ -58,7 +64,7 @@ public function delegate(string $method, array $args): mixed } return $adapter->{$method}(...$args); } finally { - if ($capturing) { + if ($startedCapture) { foreach ($adapter->stopExplainCapture() as $entry) { $this->explainBuffer[] = $entry; } diff --git a/tests/unit/ExplainTest.php b/tests/unit/ExplainTest.php index 2e3c266d4..68056d2d0 100644 --- a/tests/unit/ExplainTest.php +++ b/tests/unit/ExplainTest.php @@ -6,6 +6,7 @@ use Utopia\Cache\Adapter\None; use Utopia\Cache\Cache; use Utopia\Database\Adapter; +use Utopia\Database\Adapter\Pool; use Utopia\Database\Adapter\Postgres; use Utopia\Database\Database; use Utopia\Database\Document; @@ -193,4 +194,32 @@ public function testPostgresExtractionFallsBackToRootRowsWithoutScan(): void $this->assertSame(1, $rows); $this->assertNull($index); } + + public function testPoolDoesNotRestartCaptureOnAlreadyCapturingPinnedAdapter(): void + { + // Reproduces the re-entrancy bug: while the pool is capturing, a nested + // delegate() on the pinned (transaction) adapter — e.g. a before(find) + // transformation issuing its own query — must NOT call + // startExplainCapture() again, which would throw "cannot be nested". + $inner = $this->getMockBuilder(Adapter::class) + ->onlyMethods(['startExplainCapture', 'isExplainCapturing', 'ping']) + ->getMockForAbstractClass(); + + // The inner adapter is already mid-capture from the outer find(). + $inner->method('isExplainCapturing')->willReturn(true); + $inner->method('ping')->willReturn(true); + // The guard must prevent any re-start on the already-capturing adapter. + $inner->expects($this->never())->method('startExplainCapture'); + + $pool = (new \ReflectionClass(Pool::class))->newInstanceWithoutConstructor(); + + // Pin the inner adapter (as withTransaction does) and turn on pool-level + // capture so delegate() takes the capturing branch. + (new \ReflectionProperty(Pool::class, 'pinnedAdapter'))->setValue($pool, $inner); + (new \ReflectionProperty(Adapter::class, 'explainBuffer'))->setValue($pool, []); + + $result = $pool->delegate('ping', []); + + $this->assertTrue($result); + } } From 7049eb9e87922be7f47902278f770e41d818f572 Mon Sep 17 00:00:00 2001 From: Prem Palanisamy Date: Tue, 2 Jun 2026 05:35:35 +0100 Subject: [PATCH 13/16] Sanitize embedded perms/metadata table tokens in explain plan strings The sanitizer renamed standalone _perms/__metadata identifiers but missed them when embedded inside plan strings (e.g. a MariaDB attached_condition like "db_x_collection_y_perms.`_permission` = 'read'"), leaking the internal permission/metadata table names once the raw tree is exposed. Substring-rewrite those embedded physical-table tokens too. --- src/Database/Adapter.php | 11 ++++++++++- tests/unit/ExplainTest.php | 6 ++++++ 2 files changed, 16 insertions(+), 1 deletion(-) diff --git a/src/Database/Adapter.php b/src/Database/Adapter.php index 0c0a4a012..7ae9b7bf6 100644 --- a/src/Database/Adapter.php +++ b/src/Database/Adapter.php @@ -235,7 +235,16 @@ private function renameInternalIdentifier(string $name): string if (isset(self::EXPLAIN_COLUMN_RENAMES[$name])) { return self::EXPLAIN_COLUMN_RENAMES[$name]; } - // Plan strings embed internal identifiers (e.g. index_condition: + // The permission/metadata tables also appear embedded inside plan + // strings — e.g. a MariaDB attached_condition like + // "`db_x_collection_y_perms`.`_permission` in (...)". The suffix checks + // above only catch standalone identifiers, so rewrite the embedded + // physical-table tokens here too. Match the longest run of + // identifier/backtick chars ending in the internal suffix. + $name = \preg_replace('/[`\w]*__metadata/', '', $name) ?? $name; + $name = \preg_replace('/[`\w]*_perms/', '', $name) ?? $name; + + // Plan strings embed internal column identifiers (e.g. index_condition: // "main.`_uid` = '...'"). Best-effort, display-only substring rewrite: // a user column containing "_uid"/"_tenant"/etc. is rewritten too, which // is fine since this is for reading the plan, not round-tripping names. diff --git a/tests/unit/ExplainTest.php b/tests/unit/ExplainTest.php index 68056d2d0..2e1d85904 100644 --- a/tests/unit/ExplainTest.php +++ b/tests/unit/ExplainTest.php @@ -78,6 +78,8 @@ public function testSanitizePlanHidesInternalTablesAndRenamesColumns(): void 'meta_table' => 'appwrite__metadata', 'projection' => ['_uid', '_createdAt', '_updatedAt', '_permissions', 'title'], 'tenant_col' => '_tenant', + // The perms/metadata tables also appear embedded in condition strings. + 'attached_condition' => "_45_abc123_perms._permission = 'read' and project_1__metadata._uid = '1'", 'nested' => [ 'inner_table' => 'project_1__metadata', 'cols' => ['_uid', '_id'], @@ -91,6 +93,10 @@ public function testSanitizePlanHidesInternalTablesAndRenamesColumns(): void $this->assertSame(['$id', '$createdAt', '$updatedAt', '$permissions', 'title'], $sanitized['projection']); $this->assertSame('$tenant', $sanitized['tenant_col']); + // Embedded physical table tokens inside a condition string are rewritten too. + $this->assertStringNotContainsString('_perms', $sanitized['attached_condition']); + $this->assertStringNotContainsString('__metadata', $sanitized['attached_condition']); + // _id is MySQL's auto-increment column; not renamed. $this->assertSame(['$id', '_id'], $sanitized['nested']['cols']); } From ebedb0ac98c1ef09cf79e61dc29cd348d16042ed Mon Sep 17 00:00:00 2001 From: Prem Palanisamy Date: Tue, 2 Jun 2026 12:27:39 +0100 Subject: [PATCH 14/16] Clear stale pool adapter timeouts --- src/Database/Adapter.php | 2 ++ src/Database/Adapter/Pool.php | 14 ++++++++++---- tests/unit/ExplainTest.php | 22 ++++++++++++++++++++++ 3 files changed, 34 insertions(+), 4 deletions(-) diff --git a/src/Database/Adapter.php b/src/Database/Adapter.php index 7ae9b7bf6..2fc0955ab 100644 --- a/src/Database/Adapter.php +++ b/src/Database/Adapter.php @@ -525,6 +525,8 @@ public function getTimeout(): int */ public function clearTimeout(string $event): void { + $this->timeout = 0; + // Clear existing callback $this->before($event, 'timeout'); } diff --git a/src/Database/Adapter/Pool.php b/src/Database/Adapter/Pool.php index 8ff37c26e..415b29002 100644 --- a/src/Database/Adapter/Pool.php +++ b/src/Database/Adapter/Pool.php @@ -84,8 +84,11 @@ public function delegate(string $method, array $args): mixed $adapter->setTenant($this->getTenant()); $adapter->setAuthorization($this->authorization); - if ($this->getTimeout() > 0) { - $adapter->setTimeout($this->getTimeout()); + $timeout = $this->getTimeout(); + if ($timeout > 0) { + $adapter->setTimeout($timeout); + } else { + $adapter->clearTimeout(Database::EVENT_ALL); } $adapter->resetDebug(); foreach ($this->getDebug() as $key => $value) { @@ -167,8 +170,11 @@ public function withTransaction(callable $callback): mixed $adapter->setTenant($this->getTenant()); $adapter->setAuthorization($this->authorization); - if ($this->getTimeout() > 0) { - $adapter->setTimeout($this->getTimeout()); + $timeout = $this->getTimeout(); + if ($timeout > 0) { + $adapter->setTimeout($timeout); + } else { + $adapter->clearTimeout(Database::EVENT_ALL); } $adapter->resetDebug(); foreach ($this->getDebug() as $key => $value) { diff --git a/tests/unit/ExplainTest.php b/tests/unit/ExplainTest.php index 2e1d85904..2974e2897 100644 --- a/tests/unit/ExplainTest.php +++ b/tests/unit/ExplainTest.php @@ -10,6 +10,9 @@ use Utopia\Database\Adapter\Postgres; use Utopia\Database\Database; use Utopia\Database\Document; +use Utopia\Database\Validator\Authorization; +use Utopia\Pools\Adapter\Stack; +use Utopia\Pools\Pool as UtopiaPool; class ExplainTest extends TestCase { @@ -228,4 +231,23 @@ public function testPoolDoesNotRestartCaptureOnAlreadyCapturingPinnedAdapter(): $this->assertTrue($result); } + + public function testPoolClearsStaleTimeoutOnBorrowedAdapters(): void + { + $inner = $this->getMockBuilder(Adapter::class) + ->onlyMethods(['clearTimeout', 'ping']) + ->getMockForAbstractClass(); + + $inner + ->expects($this->once()) + ->method('clearTimeout') + ->with(Database::EVENT_ALL); + $inner->method('ping')->willReturn(true); + + $pool = new UtopiaPool(new Stack(), 'mock', 1, fn () => $inner); + $adapter = new Pool($pool); + $adapter->setAuthorization(new Authorization()); + + $this->assertTrue($adapter->ping()); + } } From 177e593f84aa3bbb2f13ad353b370afb7dbd6c29 Mon Sep 17 00:00:00 2001 From: Prem Palanisamy Date: Tue, 2 Jun 2026 12:33:44 +0100 Subject: [PATCH 15/16] Strip internal schema name from explain plan condition strings SQL plans qualify columns with the schema name (e.g. a MariaDB condition "`appwrite`.`main`.`status` = '...'"), exposing the internal database name in the raw tree. Drop the leading ``. qualifier during sanitization. --- src/Database/Adapter.php | 8 ++++++++ tests/unit/ExplainTest.php | 7 +++++++ 2 files changed, 15 insertions(+) diff --git a/src/Database/Adapter.php b/src/Database/Adapter.php index 2fc0955ab..d4cbeafdc 100644 --- a/src/Database/Adapter.php +++ b/src/Database/Adapter.php @@ -244,6 +244,14 @@ private function renameInternalIdentifier(string $name): string $name = \preg_replace('/[`\w]*__metadata/', '', $name) ?? $name; $name = \preg_replace('/[`\w]*_perms/', '', $name) ?? $name; + // SQL plans qualify columns with the schema name (e.g. a MariaDB + // condition "`appwrite`.`main`.`status` = '...'"). Drop the leading + // schema qualifier so the internal database name is not exposed. + $database = $this->getDatabase(); + if ($database !== '') { + $name = \str_replace('`'.$database.'`.', '', $name); + } + // Plan strings embed internal column identifiers (e.g. index_condition: // "main.`_uid` = '...'"). Best-effort, display-only substring rewrite: // a user column containing "_uid"/"_tenant"/etc. is rewritten too, which diff --git a/tests/unit/ExplainTest.php b/tests/unit/ExplainTest.php index 2974e2897..b9bd64578 100644 --- a/tests/unit/ExplainTest.php +++ b/tests/unit/ExplainTest.php @@ -73,6 +73,7 @@ public function testStopExplainCaptureIsCalledEvenWhenCallbackThrows(): void public function testSanitizePlanHidesInternalTablesAndRenamesColumns(): void { $adapter = $this->createMock(Adapter::class); + $adapter->method('getDatabase')->willReturn('appwrite'); $sanitize = (new \ReflectionMethod(Adapter::class, 'sanitizePlan')) ->getClosure($adapter); @@ -83,6 +84,8 @@ public function testSanitizePlanHidesInternalTablesAndRenamesColumns(): void 'tenant_col' => '_tenant', // The perms/metadata tables also appear embedded in condition strings. 'attached_condition' => "_45_abc123_perms._permission = 'read' and project_1__metadata._uid = '1'", + // SQL plans qualify columns with the schema name. + 'index_condition' => "(`appwrite`.`main`.`status` = 'published')", 'nested' => [ 'inner_table' => 'project_1__metadata', 'cols' => ['_uid', '_id'], @@ -100,6 +103,10 @@ public function testSanitizePlanHidesInternalTablesAndRenamesColumns(): void $this->assertStringNotContainsString('_perms', $sanitized['attached_condition']); $this->assertStringNotContainsString('__metadata', $sanitized['attached_condition']); + // The internal schema name is stripped from qualified column references. + $this->assertStringNotContainsString('`appwrite`', $sanitized['index_condition']); + $this->assertSame("(`main`.`status` = 'published')", $sanitized['index_condition']); + // _id is MySQL's auto-increment column; not renamed. $this->assertSame(['$id', '_id'], $sanitized['nested']['cols']); } From 97707670096efdc9fee6ab88ffe88a014d0c95af Mon Sep 17 00:00:00 2001 From: "claude[bot]" <41898282+claude[bot]@users.noreply.github.com> Date: Tue, 2 Jun 2026 11:47:07 +0000 Subject: [PATCH 16/16] =?UTF-8?q?(fix):=20CI=20=E2=80=94=20preserve=20Pool?= =?UTF-8?q?::setTimeout=20state=20across=20delegate()=20calls?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Pool::setTimeout delegated to the borrowed inner adapter but never updated Pool's own $timeout. The next delegate() call (e.g. find()) read $this->getTimeout() = 0 and hit the new else branch added in ebedb0ac, calling clearTimeout(EVENT_ALL) on the borrowed adapter and removing the timeout callback that was just registered. Query ran to completion, no TimeoutException, testQueryTimeout failed. Record the timeout on the Pool before delegating so subsequent borrows re-apply it instead of clearing it. Add a regression test. --- src/Database/Adapter/Pool.php | 3 +++ tests/unit/ExplainTest.php | 26 ++++++++++++++++++++++++++ 2 files changed, 29 insertions(+) diff --git a/src/Database/Adapter/Pool.php b/src/Database/Adapter/Pool.php index 415b29002..a9e7b0c03 100644 --- a/src/Database/Adapter/Pool.php +++ b/src/Database/Adapter/Pool.php @@ -122,6 +122,9 @@ protected function trigger(string $event, mixed $query): mixed public function setTimeout(int $milliseconds, string $event = Database::EVENT_ALL): void { + // Record on Pool first so delegate()'s borrow logic re-applies the timeout + // (instead of clearing it as stale) on this and every subsequent call. + $this->timeout = $milliseconds; $this->delegate(__FUNCTION__, \func_get_args()); } diff --git a/tests/unit/ExplainTest.php b/tests/unit/ExplainTest.php index b9bd64578..3e849cc74 100644 --- a/tests/unit/ExplainTest.php +++ b/tests/unit/ExplainTest.php @@ -257,4 +257,30 @@ public function testPoolClearsStaleTimeoutOnBorrowedAdapters(): void $this->assertTrue($adapter->ping()); } + + public function testPoolReappliesTimeoutAcrossDelegatedCalls(): void + { + // Regression: after setTimeout() on the Pool, a subsequent delegated call + // (e.g. find) must re-apply the timeout to whatever adapter is borrowed + // — not clear it because the Pool itself forgot the timeout was set. + $inner = $this->getMockBuilder(Adapter::class) + ->onlyMethods(['setTimeout', 'clearTimeout', 'ping']) + ->getMockForAbstractClass(); + + // Every setTimeout invocation must carry the live timeout, never clear it. + $inner + ->method('setTimeout') + ->with(1000, Database::EVENT_ALL); + // clearTimeout must NOT be called while the Pool still has a positive timeout. + $inner->expects($this->never())->method('clearTimeout'); + $inner->method('ping')->willReturn(true); + + $pool = new UtopiaPool(new Stack(), 'mock', 1, fn () => $inner); + $adapter = new Pool($pool); + $adapter->setAuthorization(new Authorization()); + + $adapter->setTimeout(1000); + $this->assertSame(1000, $adapter->getTimeout()); + $this->assertTrue($adapter->ping()); + } }