From c377d26143a9e63b4853403ed67de34cb0509986 Mon Sep 17 00:00:00 2001
From: Alex Pott <alex.a.pott@googlemail.com>
Date: Mon, 8 Feb 2021 16:27:06 +0000
Subject: [PATCH] Issue #3089326 by mfb, ankithashetty, ayushmishra206,
ravi.shankar, agrochal, krystalcode, daffie, alexpott: Query start time in
database log
---
core/lib/Drupal/Core/Database/Log.php | 19 ++++++++++++-------
core/lib/Drupal/Core/Database/Statement.php | 2 +-
.../Core/Database/StatementPrefetch.php | 2 +-
.../Drupal/Core/Database/StatementWrapper.php | 2 +-
.../KernelTests/Core/Database/LoggingTest.php | 3 +++
5 files changed, 18 insertions(+), 10 deletions(-)
diff --git a/core/lib/Drupal/Core/Database/Log.php b/core/lib/Drupal/Core/Database/Log.php
index f7f0286da9ec..191a3493ac9d 100644
--- a/core/lib/Drupal/Core/Database/Log.php
+++ b/core/lib/Drupal/Core/Database/Log.php
@@ -22,8 +22,8 @@ class Log {
*
* array(
* $logging_key = array(
- * array('query' => '', 'args' => array(), 'caller' => '', 'target' => '', 'time' => 0),
- * array('query' => '', 'args' => array(), 'caller' => '', 'target' => '', 'time' => 0),
+ * array('query' => '', 'args' => array(), 'caller' => '', 'target' => '', 'time' => 0, 'start' => 0),
+ * array('query' => '', 'args' => array(), 'caller' => '', 'target' => '', 'time' => 0, 'start' => 0),
* ),
* );
*
@@ -103,14 +103,18 @@ public function end($logging_key) {
/**
* Log a query to all active logging keys.
*
- * @param $statement
+ * @param \Drupal\Core\Database\StatementInterface $statement
* The prepared statement object to log.
- * @param $args
+ * @param array $args
* The arguments passed to the statement object.
- * @param $time
- * The time in milliseconds the query took to execute.
+ * @param float $time
+ * The time the query took to execute as a float (in seconds with
+ * microsecond precision).
+ * @param float $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, float $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 3de4537fb2cd..7a52c35cee2f 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 5e71c0947894..3b672739d1ec 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 d770964f07ce..7132efb62791 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 662f3ebbdb03..840c537c760e 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,8 @@ 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']);
}
}
--
GitLab