diff --git a/core/lib/Drupal/Core/Database/Log.php b/core/lib/Drupal/Core/Database/Log.php index f7f0286da9..5fe27ec5dc 100644 --- a/core/lib/Drupal/Core/Database/Log.php +++ b/core/lib/Drupal/Core/Database/Log.php @@ -108,9 +108,13 @@ public function end($logging_key) { * @param $args * The arguments passed to the statement object. * @param $time - * The time in milliseconds the query took to execute. + * The time the query took to execute as a float (in seconds with + * microsecond precision). + * @param $start + * The time the query started as a float (in seconds since the Unix epoch + * with microsecond precision). */ - public function log(StatementInterface $statement, $args, $time) { + public function log(StatementInterface $statement, $args, $time, $start = NULL) { foreach (array_keys($this->queryLog) as $key) { $this->queryLog[$key][] = [ 'query' => $statement->getQueryString(), @@ -118,6 +122,7 @@ public function log(StatementInterface $statement, $args, $time) { 'target' => $statement->dbh->getTarget(), 'caller' => $this->findCaller(), 'time' => $time, + 'start' => $start, ]; } } diff --git a/core/lib/Drupal/Core/Database/Statement.php b/core/lib/Drupal/Core/Database/Statement.php index 3de4537fb2..7a52c35cee 100644 --- a/core/lib/Drupal/Core/Database/Statement.php +++ b/core/lib/Drupal/Core/Database/Statement.php @@ -68,7 +68,7 @@ public function execute($args = [], $options = []) { if (!empty($logger)) { $query_end = microtime(TRUE); - $logger->log($this, $args, $query_end - $query_start); + $logger->log($this, $args, $query_end - $query_start, $query_start); } return $return; diff --git a/core/lib/Drupal/Core/Database/StatementPrefetch.php b/core/lib/Drupal/Core/Database/StatementPrefetch.php index 3f6efdf364..b7a8fd22b2 100644 --- a/core/lib/Drupal/Core/Database/StatementPrefetch.php +++ b/core/lib/Drupal/Core/Database/StatementPrefetch.php @@ -186,7 +186,7 @@ public function execute($args = [], $options = []) { if (!empty($logger)) { $query_end = microtime(TRUE); - $logger->log($this, $args, $query_end - $query_start); + $logger->log($this, $args, $query_end - $query_start, $query_start); } // Initialize the first row in $this->currentRow. diff --git a/core/lib/Drupal/Core/Database/StatementWrapper.php b/core/lib/Drupal/Core/Database/StatementWrapper.php index eff40102f4..dcc074604c 100644 --- a/core/lib/Drupal/Core/Database/StatementWrapper.php +++ b/core/lib/Drupal/Core/Database/StatementWrapper.php @@ -117,7 +117,7 @@ public function execute($args = [], $options = []) { if (!empty($logger)) { $query_end = microtime(TRUE); - $logger->log($this, $args, $query_end - $query_start); + $logger->log($this, $args, $query_end - $query_start, $query_start); } return $return; diff --git a/core/tests/Drupal/KernelTests/Core/Database/LoggingTest.php b/core/tests/Drupal/KernelTests/Core/Database/LoggingTest.php index 662f3ebbdb..449894c845 100644 --- a/core/tests/Drupal/KernelTests/Core/Database/LoggingTest.php +++ b/core/tests/Drupal/KernelTests/Core/Database/LoggingTest.php @@ -20,6 +20,7 @@ class LoggingTest extends DatabaseTestBase { public function testEnableLogging() { Database::startLog('testing'); + $start = microtime(TRUE); $this->connection->query('SELECT [name] FROM {test} WHERE [age] > :age', [':age' => 25])->fetchCol(); $this->connection->query('SELECT [age] FROM {test} WHERE [name] = :name', [':name' => 'Ringo'])->fetchCol(); @@ -32,6 +33,9 @@ public function testEnableLogging() { foreach ($queries as $query) { $this->assertEqual(__FUNCTION__, $query['caller']['function'], 'Correct function in query log.'); + $this->assertIsFloat($query['start']); + $this->assertGreaterThanOrEqual($start, $query['start']); + $start = $query['start']; } }