DBAL-11 - Changed Interface of SQLLogger to allow for timing variables, added...

DBAL-11 - Changed Interface of SQLLogger to allow for timing variables, 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.

lib/Doctrine/DBAL/Connection.php

@@ -552,8 +552,9 @@ class Connection implements DriverConnection
     {
         $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 @@ class Connection implements DriverConnection
             $stmt = $this->_conn->query($query);
         }
 
+        if ($hasLogger) {
+            $this->_config->getSQLLogger()->logSQL($query, $params, microtime(true) - $queryStart);
+        }
+
         return $stmt;
     }
 
@@ -624,8 +629,9 @@ class Connection implements DriverConnection
     {
         $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 @@ class Connection implements DriverConnection
             $result = $this->_conn->exec($query);
         }
 
+        if ($hasLogger) {
+            $this->_config->getSQLLogger()->logSQL($query, $params, microtime(true) - $queryStart);
+        }
+
         return $result;
     }
 

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);
         }
     }
 }

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;
     }
 }
\ No newline at end of file

lib/Doctrine/DBAL/Logging/SQLLogger.php

@@ -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);
 }
\ No newline at end of file

lib/Doctrine/DBAL/Statement.php

@@ -123,11 +123,18 @@ class Statement implements DriverStatement
      */
     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;
     }
 
     /**

tests/Doctrine/Tests/DBAL/ConnectionTest.php

@@ -115,4 +115,28 @@ class ConnectionTest extends \Doctrine\Tests\DbalTestCase
         $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());
+    }
 }
\ No newline at end of file

tests/Doctrine/Tests/DBAL/Functional/AllTests.php

@@ -29,6 +29,7 @@ class AllTests
         $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;
     }

tests/Doctrine/Tests/DBAL/Functional/LoggingTest.php

+<?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();
+    }
+}
\ No newline at end of file

tests/Doctrine/Tests/DBAL/Functional/Schema/SchemaManagerFunctionalTestCase.php

@@ -23,13 +23,10 @@ class SchemaManagerFunctionalTestCase extends \Doctrine\Tests\DbalFunctionalTest
         $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();
     }