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
all action that will fire for every other action. - In the
all callback, we make sure we’re looking for the correct hook. - We then build an
array to store some data, use the $wp_filter global 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 an int for the priority, it will also accept a string. We add new hooks, and re-prioritze all of the existing hooks with floats that 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() {
if ( $this->hook !== current_filter() ) {
return;
}
global $wp_filter;
foreach( $wp_filter[ $this->hook ] as $priority => $callback ) {
if ( ! isset( $this->callback_mods[ $priority ] ) ) {
$this->callback_mods[ $priority ] = $priority - $this->callback_mod;
}
if ( ! is_array( $this->callbacks[ $priority ] ) ) {
$this->callbacks[ $priority ] = [];
}
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 ) {
$human_callback = $this->get_human_callback( $wp_filter[ $this->hook ][ $priority ][$callback_func] );
$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;
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_action( $this->hook, function( $value = null ) use ( $callback_func, $priority, $human_callback ) {
$this->callbacks[ $priority ][ $callback_func ]['start'] = microtime( true );
return $value;
}, strval( $pre_callback_priority ) );
add_action( $this->hook, function( $value = null ) use ( $callback_func, $priority, $human_callback ) {
$this->callbacks[ $priority ][ $callback_func ]['stop'] = microtime( true );
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'] ) ) {
$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 );
if ( $seconds >= 1 || $seconds == 0 ) {
return number_format( $seconds, 3 ) . 's';
}
if ( $seconds >= .001 ) {
return number_format( $seconds * 1000, 3 ) . 'ms';
}
if ( $seconds >= .000001 ) {
return number_format( $seconds * 1000000, 3 ) . 'μs';
}
if ( $seconds >= .000000001 ) {
return number_format( $seconds * 1000000000, 3 ) . 'ns';
}
return $seconds . 's?';
}
}
new VIP_Hook_Timeline( 'save_post' );Code language: PHP (php)
