Uploaded image for project: 'CiviCRM'
  1. CiviCRM
  2. CRM-18093

Provide speed information on queries when CIVICRM_DEBUG_LOG_QUERY is on

    Details

    • Type: Bug
    • Status: Done/Fixed
    • Priority: Trivial
    • Resolution: Fixed/Completed
    • Affects Version/s: 4.7.2
    • Fix Version/s: 4.7.3
    • Component/s: None
    • Labels:
    • Documentation Required?:
      Developer Doc
    • Funding Source:
      Contributed Code

      Description

      When CIVICRM_DEBUG_LOG_QUERY is defined all queries are logged to the ConfigAndLog directory.

      This patch (originally written by Adam Wight) adds information about how long it took and what was retrieved.
      ie

      Feb 23 23:35:48 [info]
      $Query = SELECT * FROM civicrm_navigation ; WHERE ( civicrm_navigation.domain_id = 1 ) AND ( civicrm_navigation.name = "Home" )

      Feb 23 23:35:48 [info] QUERY DONE IN 0.001260 seconds. Result is 1 rows by 11 columns.

      I am tempted to add 2 further things:

      1) I think I would prefer to add a prefix in & have the queries output to a different file - ie. normally it goes to CiviCRM.50d7cb3f17721c535a5d17223e02b5dd.log but if you pass a prefix to the debug function then all 'query_logging' debug lines would go to CiviCRM.query.50d7cb3f17721c535a5d17223e02b5dd.log

      I'm proposing this change to affect all cases where CIVICRM_DEBUG_LOG_QUERY is enabled

      2) I'm inclined to change this
      QUERY DONE IN 0.001260 seconds. Result is 1 rows by 11 columns.

      to prepend a number of starts depending on Query length - in order to make it easier for people to grep the file for long queries

      '* QUERY DONE IN 1.001260 seconds. Result is 1 rows by 11 columns.
      '** QUERY DONE IN 5.001260 seconds. Result is 1 rows by 11 columns.
      '*** QUERY DONE IN 10.001260 seconds. Result is 1 rows by 11 columns.
      '**** QUERY DONE IN 20.001260 seconds. Result is 1 rows by 11 columns.

      we probably don't need to keep going up

      AN interesting additional option would be to print a backtrace for any query that takes longer than a certain amount of time in normal operation - however, all the other options are specific to when query debugging is on - ie a dev or staging instance

        Attachments

          Activity

            People

            • Assignee:
              eileen Eileen McNaughton
              Reporter:
              eileen Eileen McNaughton
            • Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: