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