If you google debugging WordPress hooks you’ll find a lot of information.
About 1,180,000 results
Let’s add another one.
WordPress hooks are powerful, but also complex under the hood. There’s plenty of topics I could talk about here, but right now I’m only going to talk about speed. How long does it take for a hook to fire and return?
Some cool work in this area has already been done thanks to Debug Bar Slow Actions and Query Monitor, but outside of something like Xdebug or New Relic, you’ll have a hard time figuring out how long each individual hook callback takes without modifying either WordPress core or each hook call.
… or maybe not …
While doing some client debugging for my job at WordPress VIP (did I mention we’re hiring?) I came across the need to do this exact thing. I’ve just finished the code that will make this happen, and I’m releasing it into the wild for everyone to benefit.
What’s the problem we’re trying to solve? Well, this client has a sporadic issue where posts saving in the admin time out and sometimes fail. We’ve ruled out some potential issues, and are looking at a save_post hook going haywire.
Now I can capture every single save_post action, what the callback was, and how long it took. Here’s an example for this exact post:
START: 10:save_post, (Callback: `delete_get_calendar_cache`)
STOP: 10:save_post, Taken 132.084μs (Callback: `delete_get_calendar_cache`)
START: 10:save_post, (Callback: `sharing_meta_box_save`)
STOP: 10:save_post, Taken 15.974μs (Callback: `sharing_meta_box_save`)
START: 10:save_post, (Callback: `Jetpack_Likes_Settings::meta_box_save`)
STOP: 10:save_post, Taken 19.073μs (Callback: `Jetpack_Likes_Settings::meta_box_save`)
START: 10:save_post, (Callback: `SyntaxHighlighter::mark_as_encoded`)
STOP: 10:save_post, Taken 19.073μs (Callback: `SyntaxHighlighter::mark_as_encoded`)
START: 10:save_post, (Callback: `AMP_Post_Meta_Box::save_amp_status`)
STOP: 10:save_post, Taken 16.928μs (Callback: `AMP_Post_Meta_Box::save_amp_status`)
START: 20:save_post, (Callback: `Publicize::save_meta`)
STOP: 20:save_post, Taken 428.915μs (Callback: `Publicize::save_meta`)
START: 9000:save_post, (Callback: `Debug_Bar_Slow_Actions::time_stop`)
STOP: 9000:save_post, Taken 11.921μs (Callback: `Debug_Bar_Slow_Actions::time_stop`)
START: 1:save_post, (Callback: `The_SEO_Framework\Load::_update_post_meta`)
STOP: 1:save_post, Taken 6.016ms (Callback: `The_SEO_Framework\Load::_update_post_meta`)
START: 1:save_post, (Callback: `The_SEO_Framework\Load::_save_inpost_primary_term`)
STOP: 1:save_post, Taken 1.535ms (Callback: `The_SEO_Framework\Load::_save_inpost_primary_term`)
START: 10:save_post, (Callback: `delete_get_calendar_cache`)
STOP: 10:save_post, Taken 179.052μs (Callback: `delete_get_calendar_cache`)
START: 10:save_post, (Callback: `sharing_meta_box_save`)
STOP: 10:save_post, Taken 247.002μs (Callback: `sharing_meta_box_save`)
START: 10:save_post, (Callback: `Jetpack_Likes_Settings::meta_box_save`)
STOP: 10:save_post, Taken 25.988μs (Callback: `Jetpack_Likes_Settings::meta_box_save`)
START: 10:save_post, (Callback: `The_SEO_Framework\Load::delete_excluded_ids_cache`)
STOP: 10:save_post, Taken 185.966μs (Callback: `The_SEO_Framework\Load::delete_excluded_ids_cache`)
START: 10:save_post, (Callback: `SyntaxHighlighter::mark_as_encoded`)
STOP: 10:save_post, Taken 15.020μs (Callback: `SyntaxHighlighter::mark_as_encoded`)
START: 10:save_post, (Callback: `AMP_Post_Meta_Box::save_amp_status`)
STOP: 10:save_post, Taken 12.875μs (Callback: `AMP_Post_Meta_Box::save_amp_status`)
START: 20:save_post, (Callback: `Publicize::save_meta`)
STOP: 20:save_post, Taken 377.893μs (Callback: `Publicize::save_meta`)
START: 9000:save_post, (Callback: `Debug_Bar_Slow_Actions::time_stop`)
STOP: 9000:save_post, Taken 14.067μs (Callback: `Debug_Bar_Slow_Actions::time_stop`)Code language: CSS (css)So how does it work?
- We add an
allaction that will fire for every other action. - In the
allcallback, we make sure we’re looking for the correct hook. - We then build an
arrayto store some data, use the$wp_filterglobal to fill out information such as the priority and the callback, and store the start time. - Next we have to add a new action to run for our hook right before the callback we want to time. We use the fact that, even though
add_action()is supposed to use anintfor the priority, it will also accept astring. We add new hooks, and re-prioritze all of the existing hooks withfloatsthat are stringified. - This allows us to capture the start time and end time of each individual callback, instead of the priority group as a whole.
Of course, this does add a tiny bit of overhead, and could cause some problems if any other plugins use stringified hook priorities, or other odd issues–so be careful 🙂
Finally, here’s the code:
class VIP_Hook_Timeline {
public $hook;
public $callbacks = [];
public $callback_mod = 0.0001;
public $callback_mods = [];
public function __construct( $hook ) {
$this->hook = $hook;
add_action( 'all', array( $this, 'start' ) );
}
public function start() {
// We only want to get a timeline for one hook.
if ( $this->hook !== current_filter() ) {
return;
}
global $wp_filter;
// Iterate over each priority level and set up array.
foreach( $wp_filter[ $this->hook ] as $priority => $callback ) {
// Make the mod counter if not exists.
if ( ! isset( $this->callback_mods[ $priority ] ) ) {
$this->callback_mods[ $priority ] = $priority - $this->callback_mod;
}
// Make the array if not exists.
if ( ! is_array( $this->callbacks[ $priority ] ) ) {
$this->callbacks[ $priority ] = [];
}
// Iterate over each callback and set up array.
foreach( array_keys( $callback ) as $callback_func ) {
if ( ! is_array( $this->callbacks[ $priority ][ $callback_func ] ) ) {
$this->callbacks[ $priority ][ $callback_func ] = [ 'start' => 0, 'stop' => 0 ];
}
}
}
foreach( $this->callbacks as $priority => $callback ) {
foreach ( array_keys( $callback ) as $callback_func ) {
// Get data befmore we move things around.
$human_callback = $this->get_human_callback( $wp_filter[ $this->hook ][ $priority ][$callback_func] );
// Modify the priorities.
$pre_callback_priority = $this->callback_mods[ $priority ];
$this->callback_mods[ $priority ] = $this->callback_mods[ $priority ] + $this->callback_mod;
$new_callback_priority = $this->callback_mods[ $priority ];
$this->callback_mods[ $priority ] = $this->callback_mods[ $priority ] + $this->callback_mod;
$post_callback_priority = $this->callback_mods[ $priority ];
$this->callback_mods[ $priority ] = $this->callback_mods[ $priority ] + $this->callback_mod;
// Move the callback to our "new" priority.
if ( $new_callback_priority != $priority ) {
$wp_filter[ $this->hook ]->callbacks[ strval( $new_callback_priority ) ][ $callback_func ] = $wp_filter[ $this->hook ]->callbacks[ $priority ][ $callback_func ];
unset( $wp_filter[ $this->hook ]->callbacks[ $priority ][ $callback_func ] );
if ( empty( $wp_filter[ $this->hook ]->callbacks[ $priority ] ) ) {
unset( $wp_filter[ $this->hook ]->callbacks[ $priority ] );
}
}
// Add a new action right before the one we want to debug to capture start time.
add_action( $this->hook, function( $value = null ) use ( $callback_func, $priority, $human_callback ) {
$this->callbacks[ $priority ][ $callback_func ]['start'] = microtime( true );
// Uncomment this if you just want to dump data to the PHP error log, otherwise add your own logic.
//$message = 'START: %d:%s, (Callback: `%s`)';
// phpcs:ignore WordPress.PHP.DevelopmentFunctions.error_log_error_log
//error_log( sprintf( $message,
// $priority,
// $this->hook,
// $human_callback,
//) );
// Just in case it's a filter, return.
return $value;
}, strval( $pre_callback_priority ) );
// Add a new action right after the one we want to debug to capture end time.
add_action( $this->hook, function( $value = null ) use ( $callback_func, $priority, $human_callback ) {
$this->callbacks[ $priority ][ $callback_func ]['stop'] = microtime( true );
// Uncomment this if you just want to dump data to the PHP error log, otherwise add your own logic.
//$message = 'STOP: %d:%s, Taken %s (Callback: `%s`)';
// phpcs:ignore WordPress.PHP.DevelopmentFunctions.error_log_error_log
//error_log( sprintf( $message,
// $priority,
// $this->hook,
// $this->get_human_diff( $priority, $callback_func ),
// $human_callback,
//) );
// Just in case it's a filter, return.
return $value;
}, strval( $post_callback_priority ) );
}
}
}
public function get_human_callback( $callback ) {
$human_callback = '[UNKNOWN HOOK]';
if ( is_array( $callback['function'] ) && count( $callback['function'] ) == 2 ) {
list( $object_or_class, $method ) = $callback['function'];
if ( is_object( $object_or_class ) ) {
$object_or_class = get_class( $object_or_class );
}
$human_callback = sprintf( '%s::%s', $object_or_class, $method );
} elseif ( is_object( $callback['function'] ) ) {
// Probably an anonymous function.
$human_callback = get_class( $callback['function'] );
} else {
$human_callback = $callback['function'];
}
return $human_callback;
}
public function get_start( $priority, $callback_func ) {
return (float) $this->callbacks[ $priority ][ $callback_func ]['start'];
}
public function get_stop( $priority, $callback_func ) {
return (float) $this->callbacks[ $priority ][ $callback_func ]['stop'];
}
public function get_diff( $priority, $callback_func ) {
return (float) ( $this->get_stop( $priority, $callback_func ) - $this->get_start( $priority, $callback_func ) );
}
public function get_human_diff( $priority, $callback_func ) {
$seconds = $this->get_diff( $priority, $callback_func );
// Seconds.
if ( $seconds >= 1 || $seconds == 0 ) {
return number_format( $seconds, 3 ) . 's';
}
// Milliseconds.
if ( $seconds >= .001 ) {
return number_format( $seconds * 1000, 3 ) . 'ms';
}
// Microseconds.
if ( $seconds >= .000001 ) {
return number_format( $seconds * 1000000, 3 ) . 'μs';
}
// Nanoseconds.
if ( $seconds >= .000000001 ) {
// WOW THAT'S FAST!
return number_format( $seconds * 1000000000, 3 ) . 'ns';
}
return $seconds . 's?';
}
}
new VIP_Hook_Timeline( 'save_post' );Code language: PHP (php)
Leave a Reply