[DBAL-11] Improve API of Sqllogger Created: 06/Nov/09  Updated: 20/Jun/10  Resolved: 20/Jun/10

Status: Resolved
Project: Doctrine DBAL
Component/s: None
Affects Version/s: None
Fix Version/s: 2.0.0-BETA3

Type: Improvement Priority: Minor
Reporter: Benjamin Eberlei Assignee: Benjamin Eberlei
Resolution: Fixed Votes: 3
Labels: None


 Description   

The SqlLogger currently has a very simple API, which lacks for example the possibilty to log the execution time of queries. This would require a second call of the logger however, but i made some performance tests on the current implementation. Its using the following check to look if logging is enabled:

if($this->_config->getSqlLogger())

However:

if($this->_hasLogger)

Only takes half the time. See the test at the bottom.

We could switch to a boolean flag and use the "saved" time to enhance the SQL Logger API to include the following information:

1. SQL (Have already)
2. Params (Have already)
3. Elapsed Time (Start Time and End Time)
4. Query Type (SELECT, INSERT, UPDATE, DELETE, OTHER)

This would benefit both Symfony and ZF since they could hook into the logger for their respective debugging facilities (sf Web Toolbar, Zend Firebug SQL Profiling).

<?php                                                                                             
class Config                                                                                      
{                                                                                                 
    protected $_logger;                                                                           
    public function __construct()                                                                 
    {                                                                                             
        $this->_logger = new stdClass();
    }
    public function getLogger()
    {
        return $this->_logger;
    }
}

class Foo
{
    protected $_config = null;
    public function __construct()
    {
         $this->_config = new Config();
    }
    public function execute()
    {
         if($this->_config->getLogger()) {
         }
    }
}

class Bar
{
    protected $_config = null;
    protected $_loggerExists = false;
    public function __construct()
    {
         $this->_config = new stdClass();
         $this->_loggerExists = true;
    }
    public function execute()
    {
        if($this->_loggerExists) {

        }
    }
}

$f = new Foo();
$s = microtime(true);
for($i = 0; $i < 100; $i++) {
    $f->execute();
}
echo (microtime(true)-$s)."s\n";

$f = new Bar();
$s = microtime(true);
for($i = 0; $i < 100; $i++) {
    $f->execute();
}
echo (microtime(true)-$s)."s\n"

benny@benny-pc:~/code/php/wsnetbeans/Doctrine/trunk/tests$ php /tmp/boolvsmethod.php                
0.00055313110351562s                                                                                  
0.00025200843811035s                                                                                  
benny@benny-pc:~/code/php/wsnetbeans/Doctrine/trunk/tests$ php /tmp/boolvsmethod.php                
0.00051999092102051s                                                                                
0.00025200843811035s                                                                                
benny@benny-pc:~/code/php/wsnetbeans/Doctrine/trunk/tests$ php /tmp/boolvsmethod.php                
0.00036001205444336s                                                                                
0.00017309188842773s                                                                                
benny@benny-pc:~/code/php/wsnetbeans/Doctrine/trunk/tests$ php /tmp/boolvsmethod.php                
0.0005180835723877s                                                                                 
0.00025010108947754s


 Comments   
Comment by Roman S. Borschel [ 07/Nov/09 ]

Yea, its currently a known limitation that the times do not get logged. However, I have real doubts as to whether that is actually useful as such measurements from PHP are very inaccurate. Its much better to copy+paste a SQL query to a SQL console and run it with ANALYZE/EXPLAIN ... to see its performance.

sfDoctrine2Plugin already uses this logger for its debug toolbar.

Comment by David Abdemoulaie [ 10/Apr/10 ]

Such timings are very useful. The accuracy isn't really the point. If you have N queries executing on a slow request, you have to check N queries to find the problem. With a simple "inaccurate" time measurement you'd be able to quickly identify the problem query(ies) and take further action.

Comment by Roman S. Borschel [ 14/May/10 ]

I think timings can be added.

Comment by Benjamin Eberlei [ 13/Jun/10 ]

Schedule for BETA 3

Comment by Benjamin Eberlei [ 20/Jun/10 ]

Implemented this change, the interface of the SQL Logger changed to:

function logSQL($sql, array $params = null, $executionMS = null);

Additionally the contract of loggers changed, they are now invoked AFTER a query is executed therefore queries that cause failures do not appear on the logs.

Generated at Sun May 26 02:55:42 UTC 2013 using JIRA 5.2.7#850-sha1:b2af0c8dc8537b36121c6a579fabbdf79fc919e5.