Details

    • Type: Improvement Improvement
    • Status: Resolved
    • Priority: Minor Minor
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 2.0.0-BETA3
    • Component/s: None
    • 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 
      

        Activity

        Benjamin Eberlei created issue -
        Hide
        Roman S. Borschel added a comment -

        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.

        Show
        Roman S. Borschel added a comment - 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.
        Roman S. Borschel made changes -
        Field Original Value New Value
        Priority Major [ 3 ] Minor [ 4 ]
        Hide
        David Abdemoulaie added a comment -

        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.

        Show
        David Abdemoulaie added a comment - 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.
        Hide
        Roman S. Borschel added a comment -

        I think timings can be added.

        Show
        Roman S. Borschel added a comment - I think timings can be added.
        Roman S. Borschel made changes -
        Fix Version/s 2.0 [ 10021 ]
        Benjamin Eberlei made changes -
        Project Doctrine 2 - ORM [ 10032 ] Doctrine DBAL [ 10040 ]
        Key DDC-124 DBAL-11
        Affects Version/s 2.0-ALPHA2 [ 10028 ]
        Component/s DBAL [ 10011 ]
        Fix Version/s 2.0 [ 10021 ]
        Hide
        Benjamin Eberlei added a comment -

        Schedule for BETA 3

        Show
        Benjamin Eberlei added a comment - Schedule for BETA 3
        Benjamin Eberlei made changes -
        Assignee Roman S. Borschel [ romanb ] Benjamin Eberlei [ beberlei ]
        Fix Version/s 2.0.0-BETA2 [ 10062 ]
        Roman S. Borschel made changes -
        Fix Version/s 2.0.0-BETA3 [ 10066 ]
        Fix Version/s 2.0.0-BETA2 [ 10062 ]
        Hide
        Benjamin Eberlei added a comment -

        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.

        Show
        Benjamin Eberlei added a comment - 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.
        Benjamin Eberlei made changes -
        Status Open [ 1 ] Resolved [ 5 ]
        Resolution Fixed [ 1 ]
        Benjamin Eberlei made changes -
        Workflow jira [ 10358 ] jira-feedback2 [ 17621 ]
        Benjamin Eberlei made changes -
        Workflow jira-feedback2 [ 17621 ] jira-feedback3 [ 19976 ]

        This list may be incomplete, as errors occurred whilst retrieving source from linked applications:

        • Request to http://www.doctrine-project.org/fisheye/ failed: Error in remote call to 'FishEye 0 (http://www.doctrine-project.org/fisheye/)' (http://www.doctrine-project.org/fisheye) [AbstractRestCommand{path='/rest-service-fe/search-v1/crossRepositoryQuery', params={query=DBAL-11, expand=changesets[0:20].revisions[0:29],reviews}, methodType=GET}] : Received status code 503 (Service Temporarily Unavailable)

          People

          • Assignee:
            Benjamin Eberlei
            Reporter:
            Benjamin Eberlei
          • Votes:
            3 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: