From 8e5daca9de6823d83e98541985927358a8fe0f96 Mon Sep 17 00:00:00 2001 From: Tim Hurd Date: Wed, 26 Aug 2026 14:40:03 -0700 Subject: [PATCH 1/3] MysqliStmtWrapper was not timing executes individually, but cumulatively. Moved $startTime into execute with microtime(). Added test for this change. All passed. --- src/MysqliStmtWrapper.php | 9 ++++++--- tests/MysqliWrapper/MysqliStmtWrapperTest.php | 19 +++++++++++++++++++ 2 files changed, 25 insertions(+), 3 deletions(-) diff --git a/src/MysqliStmtWrapper.php b/src/MysqliStmtWrapper.php index 1bcc191..b07b7b9 100644 --- a/src/MysqliStmtWrapper.php +++ b/src/MysqliStmtWrapper.php @@ -9,7 +9,7 @@ use RuntimeException; // import built-ins so calls resolve at compile time instead of per-call lookups; NamespacedCallsTest keeps this list exact -use function class_exists, json_encode, method_exists; +use function class_exists, json_encode, method_exists, microtime; use const JSON_INVALID_UTF8_SUBSTITUTE, JSON_UNESCAPED_SLASHES, JSON_UNESCAPED_UNICODE; /** @@ -55,14 +55,17 @@ public function execute(?array $params = null): bool $paramsJson = json_encode($params, JSON_INVALID_UTF8_SUBSTITUTE | JSON_UNESCAPED_SLASHES | JSON_UNESCAPED_UNICODE) ?: '(params not JSON-encodable)'; } + $startTime = $this->startTime ?: ($this->mysqliWrapper->queryLogger ? microtime(true) : 0.0); + $this->startTime = 0.0; + try { $result = parent::execute($params); } catch (mysqli_sql_exception $e) { - $this->mysqliWrapper->logQuery("$this->query /* params: $paramsJson */", $this->startTime, $e); + $this->mysqliWrapper->logQuery("$this->query /* params: $paramsJson */", $startTime, $e); throw $e; } - $this->mysqliWrapper->logQuery("$this->query /* params: $paramsJson */", $this->startTime); + $this->mysqliWrapper->logQuery("$this->query /* params: $paramsJson */", $startTime); return $result; } diff --git a/tests/MysqliWrapper/MysqliStmtWrapperTest.php b/tests/MysqliWrapper/MysqliStmtWrapperTest.php index 7e5b64e..fd8651b 100644 --- a/tests/MysqliWrapper/MysqliStmtWrapperTest.php +++ b/tests/MysqliWrapper/MysqliStmtWrapperTest.php @@ -159,4 +159,23 @@ public function testPolyfillFetchArrayWithNoFields(): void $result = new MysqliResultPolyfill($stmt); $this->assertNull($result->fetch_array()); } + + public function testExecuteLogsOwnDurationNotTimeSincePrepare(): void + { + $logs = []; + $conn = new Connection(array_merge(self::$configDefaults, [ + 'queryLogger' => function ($query, $duration, $error) use (&$logs) { + $logs[] = [$query, $duration]; + }, + ])); + + $stmt = $conn->mysqli->prepare("SELECT ? AS n"); + $stmt->execute([1]); + usleep(200_000); // idle time between executes must not be counted + $stmt->execute([2]); + + $durations = array_column(array_values(array_filter($logs, fn($log) => str_contains($log[0], 'SELECT ? AS n'))), 1); + $this->assertCount(2, $durations); + $this->assertLessThan(0.1, $durations[1], 'second execute() must log its own runtime, not time since prepare()'); + } } From 660112fcdfa78fdce76b7e78d58bc61fb752b0b8 Mon Sep 17 00:00:00 2001 From: Dave Date: Fri, 16 Oct 2026 13:40:03 -0700 Subject: [PATCH 2/3] MysqliStmtWrapper: comment the first-execute timing --- src/MysqliStmtWrapper.php | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/src/MysqliStmtWrapper.php b/src/MysqliStmtWrapper.php index b07b7b9..ad7aeba 100644 --- a/src/MysqliStmtWrapper.php +++ b/src/MysqliStmtWrapper.php @@ -55,7 +55,8 @@ public function execute(?array $params = null): bool $paramsJson = json_encode($params, JSON_INVALID_UTF8_SUBSTITUTE | JSON_UNESCAPED_SLASHES | JSON_UNESCAPED_UNICODE) ?: '(params not JSON-encodable)'; } - $startTime = $this->startTime ?: ($this->mysqliWrapper->queryLogger ? microtime(true) : 0.0); + // the first execute() counts from prepare(); later ones time only themselves + $startTime = $this->startTime ?:($this->mysqliWrapper->queryLogger ? microtime(true) : 0.0); $this->startTime = 0.0; try { From bebb02ac65fe9a6e1b5d7367b0590dd00f61866c Mon Sep 17 00:00:00 2001 From: Dave Date: Fri, 16 Oct 2026 13:40:20 -0700 Subject: [PATCH 3/3] MysqliStmtWrapper: restore the space after ?: --- src/MysqliStmtWrapper.php | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/MysqliStmtWrapper.php b/src/MysqliStmtWrapper.php index ad7aeba..4c3a8d0 100644 --- a/src/MysqliStmtWrapper.php +++ b/src/MysqliStmtWrapper.php @@ -56,7 +56,7 @@ public function execute(?array $params = null): bool } // the first execute() counts from prepare(); later ones time only themselves - $startTime = $this->startTime ?:($this->mysqliWrapper->queryLogger ? microtime(true) : 0.0); + $startTime = $this->startTime ?: ($this->mysqliWrapper->queryLogger ? microtime(true) : 0.0); $this->startTime = 0.0; try {