DBAL-11 - Changed Interface of SQLLogger to allow for timing variable…

…s, added tests for logging. Contract of Loggers changed, they are not called before the query but after the query they are logging, which means queries that fail wont appear in the logs.
doctrine · Jun 20, 2010 · fe0f0e4 · fe0f0e4 · mridgway · Aug 4, 2010
1 parent 93ad4c2
commit fe0f0e4
Show file tree

Hide file tree

Showing 9 changed files with 94 additions and 17 deletions.
diff --git a/lib/Doctrine/DBAL/Connection.php b/lib/Doctrine/DBAL/Connection.php
@@ -552,8 +552,9 @@ public function executeQuery($query, array $params = array(), $types = array())
     {
         $this->connect();
 
-        if ($this->_config->getSQLLogger() !== null) {
-            $this->_config->getSQLLogger()->logSQL($query, $params);
+        $hasLogger = $this->_config->getSQLLogger() !== null;
+        if ($hasLogger) {
+            $queryStart = microtime(true);
         }
 
         if ($params) {
@@ -568,6 +569,10 @@ public function executeQuery($query, array $params = array(), $types = array())
             $stmt = $this->_conn->query($query);
         }
 
+        if ($hasLogger) {
+            $this->_config->getSQLLogger()->logSQL($query, $params, microtime(true) - $queryStart);
+        }
+
         return $stmt;
     }
 
@@ -624,8 +629,9 @@ public function executeUpdate($query, array $params = array(), array $types = ar
     {
         $this->connect();
 
-        if ($this->_config->getSQLLogger() !== null) {
-            $this->_config->getSQLLogger()->logSQL($query, $params);
+        $hasLogger = $this->_config->getSQLLogger() !== null;
+        if ($hasLogger) {
+            $queryStart = microtime(true);
         }
 
         if ($params) {
@@ -641,6 +647,10 @@ public function executeUpdate($query, array $params = array(), array $types = ar
             $result = $this->_conn->exec($query);
         }
 
+        if ($hasLogger) {
+            $this->_config->getSQLLogger()->logSQL($query, $params, microtime(true) - $queryStart);
+        }
+
         return $result;
     }
 

diff --git a/lib/Doctrine/DBAL/Logging/DebugStack.php b/lib/Doctrine/DBAL/Logging/DebugStack.php
@@ -44,10 +44,10 @@ class DebugStack implements SQLLogger
     /**
      * {@inheritdoc}
      */
-    public function logSQL($sql, array $params = null)
+    public function logSQL($sql, array $params = null, $executionMS = null)
     {
         if ($this->enabled) {
-            $this->queries[] = array('sql' => $sql, 'params' => $params);
+            $this->queries[] = array('sql' => $sql, 'params' => $params, 'executionMS' => $executionMS);
         }
     }
 }

diff --git a/lib/Doctrine/DBAL/Logging/EchoSQLLogger.php b/lib/Doctrine/DBAL/Logging/EchoSQLLogger.php
@@ -38,12 +38,14 @@ class EchoSQLLogger implements SQLLogger
     /**
      * {@inheritdoc}
      */
-    public function logSQL($sql, array $params = null)
+    public function logSQL($sql, array $params = null, $executionMS = null)
     {
     	echo $sql . PHP_EOL;
 
         if ($params) {
             var_dump($params);
     	}
+
+        echo "Took " . number_format($executionMS, 4) . " seconds" . PHP_EOL;
     }
 }
diff --git a/lib/Doctrine/DBAL/Logging/SQLLogger.php b/lib/Doctrine/DBAL/Logging/SQLLogger.php
@@ -23,7 +23,7 @@
 
 /**
  * Interface for SQL loggers.
- * 
+ *
  * @license http://www.opensource.org/licenses/lgpl-license.php LGPL
  * @link    www.doctrine-project.org
  * @since   2.0
@@ -40,6 +40,8 @@ interface SQLLogger
      *
      * @param string $sql The SQL to be executed.
      * @param array $params The SQL parameters.
+     * @param float $executionMS The microtime difference it took to execute this query.
+     * @return void
      */
-    function logSQL($sql, array $params = null);
+    function logSQL($sql, array $params = null, $executionMS = null);
 }
diff --git a/lib/Doctrine/DBAL/Statement.php b/lib/Doctrine/DBAL/Statement.php
@@ -123,11 +123,18 @@ public function bindParam($name, &$var, $type = PDO::PARAM_STR)
      */
     public function execute($params = null)
     {
-        if ($this->_conn->getConfiguration()->getSQLLogger()) {
-            $this->_conn->getConfiguration()->getSQLLogger()->logSQL($this->_sql, $this->_params);
-        }
         $this->_params = array();
-        return $this->_stmt->execute($params);
+        $hasLogger = $this->_conn->getConfiguration()->getSQLLogger();
+        if ($hasLogger) {
+            $queryStart = microtime(true);
+        }
+
+        $stmt = $this->_stmt->execute($params);
+
+        if ($hasLogger) {
+            $this->_conn->getConfiguration()->getSQLLogger()->logSQL($this->_sql, $this->_params, microtime(true) - $queryStart);
+        }
+        return $stmt;
     }
 
     /**

diff --git a/tests/Doctrine/Tests/DBAL/ConnectionTest.php b/tests/Doctrine/Tests/DBAL/ConnectionTest.php
@@ -115,4 +115,28 @@ public function testConnectDispatchEvent()
         $conn = new Connection(array('platform' => $platform), $driverMock, new Configuration(), $eventManager);
         $conn->connect();
     }
+
+    /**
+     * Pretty dumb test, however we want to check that the EchoSQLLogger correctly implements the interface.
+     *
+     * @group DBAL-11
+     */
+    public function testEchoSQLLogger()
+    {
+        $logger = new \Doctrine\DBAL\Logging\EchoSQLLogger();
+        $this->_conn->getConfiguration()->setSQLLogger($logger);
+        $this->assertSame($logger, $this->_conn->getConfiguration()->getSQLLogger());
+    }
+
+    /**
+     * Pretty dumb test, however we want to check that the DebugStack correctly implements the interface.
+     *
+     * @group DBAL-11
+     */
+    public function testDebugSQLStack()
+    {
+        $logger = new \Doctrine\DBAL\Logging\DebugStack();
+        $this->_conn->getConfiguration()->setSQLLogger($logger);
+        $this->assertSame($logger, $this->_conn->getConfiguration()->getSQLLogger());
+    }
 }
diff --git a/tests/Doctrine/Tests/DBAL/Functional/AllTests.php b/tests/Doctrine/Tests/DBAL/Functional/AllTests.php
@@ -29,6 +29,7 @@ public static function suite()
         $suite->addTestSuite('Doctrine\Tests\DBAL\Functional\ConnectionTest');
         $suite->addTestSuite('Doctrine\Tests\DBAL\Functional\DataAccessTest');
         $suite->addTestSuite('Doctrine\Tests\DBAL\Functional\WriteTest');
+        $suite->addTestSuite('Doctrine\Tests\DBAL\Functional\LoggingTest');
 
         return $suite;
     }

diff --git a/tests/Doctrine/Tests/DBAL/Functional/LoggingTest.php b/tests/Doctrine/Tests/DBAL/Functional/LoggingTest.php
@@ -0,0 +1,34 @@
+<?php
+
+namespace Doctrine\Tests\DBAL\Functional;
+
+require_once __DIR__ . '/../../TestInit.php';
+
+class LoggingTest extends \Doctrine\Tests\DbalFunctionalTestCase
+{
+    public function testLogExecuteQuery()
+    {
+        $sql = $this->_conn->getDatabasePlatform()->getDummySelectSQL();
+
+        $logMock = $this->getMock('Doctrine\DBAL\Logging\SQLLogger');
+        $logMock->expects($this->once())
+                ->method('logSQL')
+                ->with($this->equalTo($sql), $this->equalTo(array()), $this->isType('float'));
+        $this->_conn->getConfiguration()->setSQLLogger($logMock);
+        $this->_conn->executeQuery($sql, array());
+    }
+
+    public function testLogPrepareExecute()
+    {
+        $sql = $this->_conn->getDatabasePlatform()->getDummySelectSQL();
+
+        $logMock = $this->getMock('Doctrine\DBAL\Logging\SQLLogger');
+        $logMock->expects($this->once())
+                ->method('logSQL')
+                ->with($this->equalTo($sql), $this->equalTo(array()), $this->isType('float'));
+        $this->_conn->getConfiguration()->setSQLLogger($logMock);
+
+        $stmt = $this->_conn->prepare($sql);
+        $stmt->execute();
+    }
+}
diff --git a/tests/Doctrine/Tests/DBAL/Functional/Schema/SchemaManagerFunctionalTestCase.php b/tests/Doctrine/Tests/DBAL/Functional/Schema/SchemaManagerFunctionalTestCase.php
@@ -23,13 +23,10 @@ protected function setUp()
         $testClass = end($e);
         $dbms = strtolower(str_replace('SchemaManagerTest', null, $testClass));
 
-        if ($this->_conn->getDatabasePlatform()->getName() !== $dbms)
-        {
+        if ($this->_conn->getDatabasePlatform()->getName() !== $dbms) {
             $this->markTestSkipped('The ' . $testClass .' requires the use of ' . $dbms);
         }
 
-        #$this->_conn->getConfiguration()->setSQLLogger(new \Doctrine\DBAL\Logging\EchoSQLLogger);
-
         $this->_sm = $this->_conn->getSchemaManager();
     }