Issue Details (XML | Word | Printable)

Key: DBAL-11
Type: Improvement Improvement
Status: Resolved Resolved
Resolution: Fixed
Priority: Minor Minor
Assignee: Benjamin Eberlei
Reporter: Benjamin Eberlei
Votes: 3
Watchers: 2
Operations

If you were logged in you would be able to see more operations.
Doctrine DBAL

Improve API of Sqllogger

Created: 06/Nov/09 06:04 PM   Updated: 20/Jun/10 10:52 AM
Component/s: None
Affects Version/s: None
Fix Version/s: 2.0.0-BETA3


 Description  « Hide
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


 All   Comments   Change History   FishEye      Sort Order: Ascending order - Click to sort in descending order
Roman S. Borschel added a comment - 07/Nov/09 12:16 PM
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.


David Abdemoulaie added a comment - 10/Apr/10 03:14 AM
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.

Roman S. Borschel added a comment - 14/May/10 08:47 AM
I think timings can be added.

Benjamin Eberlei added a comment - 13/Jun/10 02:27 PM
Schedule for BETA 3

Benjamin Eberlei added a comment - 20/Jun/10 10:52 AM
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.