Profile WordPress hooks (action or filter) and log any taking more than 0.5 seconds

whatisslow-extended.php

<?php
/**
 * This little class records how long it takes each WordPress action or filter
 * to execute which gives a good indicator of what hooks are being slow.
 * You can then debug those hooks to see what hooked functions are causing problems.
 *
 * This class does NOT time the core WordPress code that is being run between hooks.
 * You could use similar code to this that doesn't have an end processor to do that.
 *
 * @version 0.4
 * @author Alex Mills (Viper007Bond)
 *
 * This code is released under the same license as WordPress:
 * http://wordpress.org/about/license/
 *
 * https://gist.github.com/Viper007Bond/5192117
 */

/*
INSTALLATION:
Easiest way to integrate is to place this file in the active theme and add
the following to functions.php:

// Get execution times for all filter and action hooks running.
function whatissoslow() {
	// Restrict to just AJAX calls for now.
	if ( defined( 'DOING_AJAX' ) && DOING_AJAX ) {
		require_once( dirname( __FILE__ ) . '/whatissoslow.php' );
	}
}
add_action( 'after_setup_theme', 'whatissoslow' );

EXTRA STEPS:
To time individual callbacks hooked into a specific action/filter, do the
following core monkeypatches:

* Add to class variables in /wp-includes/class-wp-hook.php:

public $debug = false;

* Add to apply_filters() function in /wp-includes/class-wp-hook.php, at the
beginning of the foreach loop:

// ### DEBUG
if ( $this->debug ) {
	$start = microtime( true );
}// ### DEBUG END

* And at the end of the foreach loop:

// ### DEBUG
if ( $this->debug ) {
	$func = '(closure)';
	if ( isset( $the_['function'] ) && is_string( $the_['function'] ) ) {
		$func = $the_['function'];
	} elseif ( isset( $the_['function'] ) && is_array( $the_['function'] ) ) {
		$func = '';
		foreach ( $the_['function'] as $f ) {
			if ( is_string( $f ) ) {
				$func .= ' (' . $f . ')';
			} elseif ( is_object( $f ) ) {
				$func .= get_class( $f );
			}
		}
	}
	error_log( '  # ' . sprintf( '%0.3f seconds', microtime( true ) - $start ) . ': ' . $func );
}// ### DEBUG END

* Enable reporting on a specific hook by adding this to do_action() in
/wp-includes/plugin.php, right before the $wp_filter[$tag]->do_action() call:

// ### DEBUG
if ( $tag === 'init' && defined( 'DOING_AJAX' ) && DOING_AJAX ) {
	$wp_filter[$tag]->debug = true;
}// ### DEBUG END

Note that this example only fires on 'init' action fired in an AJAX request.

That's it!
*/

// Here's a test to make sure it's working. wp_footer action should be logged as taking 2 seconds.
add_action( 'wp_footer', function() { sleep( 2 ); } );

class WhatIsSoSlow {
	public $data = array();

	function __construct() {
		add_action( 'all', array( $this, 'filter_start' ) );
		add_action( 'shutdown', array( $this, 'results' ) );
	}

	// This runs first for all actions and filters.
	// It starts a timer for this hook.
	public function filter_start() {
		$current_filter = current_filter();
		$this->data[ $current_filter ][]['start'] = microtime( true );
		add_filter( $current_filter, array( $this, 'filter_end' ), 99999 );
	}

	// This runs last (hopefully) for each hook and records the end time.
	// This has problems if a hook fires inside of itself since it assumes
	// the last entry in the data key for this hook is the matching pair.
	public function filter_end( $filter_data = null ) {
		$current_filter = current_filter();
		remove_filter( $current_filter, array( $this, 'filter_end' ), 99999 );
		end( $this->data[ $current_filter ] );
		$last_key = key( $this->data[ $current_filter ] );
		$this->data[ $current_filter ][ $last_key ]['stop'] = microtime( true );
		return $filter_data;
	}

	// Processes the results and var_dump()'s them. TODO: Debug bar panel?
	public function results() {
		$results = array();
		foreach ( $this->data as $filter => $calls ) {
			foreach ( $calls as $call ) {
				// Skip filters with no end point (i.e. the hook this function is hooked into)
				if ( ! isset( $call['stop'] ) ) {
					continue;
				}
				if ( ! isset( $results[ $filter ] ) ) {
					$results[ $filter ] = 0;
				}
				$results[ $filter ] = $results[ $filter ] + ( $call['stop'] - $call['start'] );
			}
		}

		asort( $results, SORT_NUMERIC );
		$results = array_reverse( $results );

		// error_log(print_r($_SERVER,true));
		// error_log(print_r($results,true));
		// var_dump( $results );
		foreach ( $results as $hook => $time ) {
			if ( $time >= 0.5 ) {
				$time = sprintf( '%0.2f', $time );
				error_log( "### Slow hook: $hook ($time seconds) (${_SERVER['PHP_SELF']})." );
			}
		}
	}
}

new WhatIsSoSlow();