DBAL-11: Improve API of Sqllogger #1037

Closed
doctrinebot opened this Issue Nov 6, 2009 · 6 comments

2 participants

@doctrinebot

Jira issue originally created by user @beberlei:

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<ins></ins>) {
    $f->execute();
}
echo (microtime(true)-$s)."s\n";

$f = new Bar();
$s = microtime(true);
for($i = 0; $i < 100; $i<ins></ins>) {
    $f->execute();
}
echo (microtime(true)-$s)."s\n"
benny@benny-pc:<sub>/code/php/wsnetbeans/Doctrine/trunk/tests$ php /tmp/boolvsmethod.php                
0.00055313110351562s                                                                                  
0.00025200843811035s                                                                                  
benny@benny-pc:</sub>/code/php/wsnetbeans/Doctrine/trunk/tests$ php /tmp/boolvsmethod.php                
0.00051999092102051s                                                                                
0.00025200843811035s                                                                                
benny@benny-pc:<sub>/code/php/wsnetbeans/Doctrine/trunk/tests$ php /tmp/boolvsmethod.php                
0.00036001205444336s                                                                                
0.00017309188842773s                                                                                
benny@benny-pc:</sub>/code/php/wsnetbeans/Doctrine/trunk/tests$ php /tmp/boolvsmethod.php                
0.0005180835723877s                                                                                 
0.00025010108947754s 
@doctrinebot

Comment created by romanb:

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.

@doctrinebot

Comment created by @hobodave:

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.

@doctrinebot

Comment created by romanb:

I think timings can be added.

@doctrinebot

Comment created by @beberlei:

Schedule for BETA 3

@doctrinebot

Comment created by @beberlei:

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.

@doctrinebot

Issue was closed with resolution "Fixed"

@beberlei beberlei was assigned by doctrinebot Dec 6, 2015
@doctrinebot doctrinebot added this to the 2.0.0-BETA3 milestone Dec 6, 2015
@doctrinebot doctrinebot closed this Dec 6, 2015
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment