WP-DB Add query_done Action for Performance Logging Plugins

[sexytyranno]

Attached is a patch I'm using locally to implement some performance logging with WP queries. I often use this in combination with a plug-in to determine what's causing a site to slow down (in cases where it's hard to reproduce it).

I've also extended the logged query data to have a "time_start" value as the 4th parameter to the logged query data (wpdb::queries), as knowing when a query started running can add perspective to page loads, which could otherwise be lost. The additional cost of this fourth parameter is nominal. (1000 queries results in maybe 10KB memory, assuming a 64-bit decimal encoding, plus the potential added array overhead)

This additional tidbit of information can be useful in narrowing down where exactly a slow-down is occurring if it's not database related, as it lets someone analyzing the data know between these two queries there was a large delay somewhere within the PHP code, and we have the two caller values to understand what was happening at the time.

PLUGIN DEVELOPER CONCERNS:
Due to the potential issues developers may encounter, it should be documented that any responder to query_done should

• USE IT ONLY WHEN ABSOLUTELY NECESSARY. Additionally, PROCESSING DONE WITHIN A QUERY_DONE RESPONDER SHOULD BE *MINIMAL*. query_done has the potential to be called many times after plug-ins are all loaded, and misuse of it can cause severe performance issues.

• Not use the calling $wpdb, as it will corrupt the state of wpdb, breaking the site (including the admin log-in section). If you want to log to the database, you must not even use the wpdb::dbh. You should instantiate your own "local" wpdb, or spin your own simple mysql_connect + mysql_select_db + mysql_query.

• If they're using an instance of WPDB to log the performance output, they MUST use a handler-specific flag indicating that they're currently responding to one, to avoid creating infinite recursion. Not using such a flag will cause PHP to crash.

Performance logging action - patch

I'm +1 on time_start. The other action definitely causes me to pause, due to the concerns you outlined.

The newly create action will only actually work when SAVEQUERIES is define()d, so on most production sites using sane plug-ins, shouldn't cause any performance impact.

Really, I've not ever seen SAVEQUERIES defined before, except in the context of debugging issues, so the impact should be pretty narrowed.

If the core WP group would prefer, we could also add another low-publicity define() into wp-config.php to enable the query_done action, so as to make it one of those things where a site administrator would have manually and knowingly enable it.

To this extent, perhaps we can insert a warning near the top of wp-admin somewhere outlining that:

• It's enabled. It's typically defined in wp-config.php, but it may be defined in a plug-in or theme. (Silly and bad plug-in/theme author!)

• Debugging only feature. Should not be used on live sites.

• Possible performance impact while it's enabled.

Some of the above may be ported to a "What does this mean?" link, rather than having a really large warning box.

As a point of reference, basically how my query_done action handler that works well for this is written as follows:

// This dbh is set up on initialization, with new_link=true passed to the mysql_connect call.
$PREFIX_dbh = null;

function handle_query_done($query_data) {
	// Only log slowness that an admin user sees, to avoid logging gigs of records.
	if (!current_user_can('manage_options'))
		return true;
	
	// NB: WE MUST AVOID INFINITE RECURSION. And so this flag exists.
	// NB(2): DO NOT USE THE GLOBAL $wpdb. Using it will corrupt the state and cause almost ALL functionality of the site to cease.
	global $PREFIX_in_query_done;
	if($PREFIX_in_query_done)
		return true;
	$PREFIX_in_query_done = true;
	// YOUR CODE STARTS HERE.
	
	// Log it in some way. Optionally, only log it when some interesting condition is met (i.e., query_time > 200ms).
	
	// YOUR CODE SHOULD NOT EXIST BELOW HERE
	return !($PREFIX_in_query_done = false);
}

Probably not the best way to do it, given I'm still new to WP plugin dev, but it sanely avoids the issues described above.

Since you're only going to want to do this on testing, then you should just extend the DB class. Let's see this as a plugin first. I'm not really a fan of this overall -- it's very arbitrary for debugging something non-database-related through database info. You could always use the 'all' hook.

Note the standard query logging code in wpdb logs query time and you can get a good feel for which is the slow query using this and the debug bar plugin.