WordPress.org

Make WordPress Core

Opened 4 years ago

Closed 3 years ago

Last modified 3 years ago

#14859 closed enhancement (wontfix)

WP-DB Add query_done Action for Performance Logging Plugins

Reported by: sexytyranno Owned by:
Milestone: Priority: normal
Severity: normal Version: 3.0.1
Component: Database Keywords:
Focuses: Cc:

Description

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.

Attachments (1)

wp-db.patch (711 bytes) - added by sexytyranno 4 years ago.
Performance logging action - patch

Download all attachments as: .zip

Change History (6)

sexytyranno4 years ago

Performance logging action - patch

comment:1 nacin4 years ago

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

comment:2 sexytyranno4 years ago

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.

comment:3 sexytyranno4 years ago

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.

comment:4 nacin3 years ago

  • Milestone Awaiting Review deleted
  • Resolution set to wontfix
  • Status changed from new to closed

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.

comment:5 westi3 years ago

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.

Note: See TracTickets for help on using tickets.