Debugging hook performance

class-wp-hook.php.diff

diff --git src/wp-includes/class-wp-hook.php src/wp-includes/class-wp-hook.php
index 823b4b5..eebd5fe 100755
--- src/wp-includes/class-wp-hook.php
+++ src/wp-includes/class-wp-hook.php
@@ -62,6 +62,8 @@ final class WP_Hook implements Iterator, ArrayAccess {
 	 */
 	private $doing_action = false;
 
+	public $tag;
+
 	/**
 	 * Hooks a function or method to a specific filter action.
 	 *
@@ -77,6 +79,7 @@ final class WP_Hook implements Iterator, ArrayAccess {
 	 * @param int      $accepted_args   The number of arguments the function accepts.
 	 */
 	public function add_filter( $tag, $function_to_add, $priority, $accepted_args ) {
+		$this->tag = $tag;
 		$idx = _wp_filter_build_unique_id( $tag, $function_to_add, $priority );
 		$priority_existed = isset( $this->callbacks[ $priority ] );
 
@@ -263,6 +266,8 @@ final class WP_Hook implements Iterator, ArrayAccess {
 		}
 	}
 
+	static $filter_stats = array();
+
 	/**
 	 * Calls the callback functions added to a filter hook.
 	 *
@@ -283,6 +288,11 @@ final class WP_Hook implements Iterator, ArrayAccess {
 		$this->iterations[ $nesting_level ] = array_keys( $this->callbacks );
 		$num_args = count( $args );
 
+		if ( ! isset( self::$filter_stats[ $this->tag ] ) ) {
+			self::$filter_stats[ $this->tag ] = array();
+		}
+
+		$callbacks = array();
 		do {
 			$this->current_priority[ $nesting_level ] = $priority = current( $this->iterations[ $nesting_level ] );
 
@@ -291,6 +301,8 @@ final class WP_Hook implements Iterator, ArrayAccess {
 					$args[ 0 ] = $value;
 				}
 
+				$start_time = microtime( true );
+
 				// Avoid the array_slice if possible.
 				if ( $the_['accepted_args'] == 0 ) {
 					$value = call_user_func_array( $the_['function'], array() );
@@ -299,6 +311,12 @@ final class WP_Hook implements Iterator, ArrayAccess {
 				} else {
 					$value = call_user_func_array( $the_['function'], array_slice( $args, 0, (int)$the_['accepted_args'] ) );
 				}
+
+				$end_time = microtime( true );
+				self::$filter_stats[ $this->tag ][] = array(
+					'duration' => $end_time - $start_time,
+					'callback' => $the_['function'],
+				);
 			}
 		} while ( false !== next( $this->iterations[ $nesting_level ] ) );
 
@@ -307,6 +325,11 @@ final class WP_Hook implements Iterator, ArrayAccess {
 
 		$this->nesting_level--;
 
+//		array_push( self::$filter_stats[ $this->tag ]['durations'], $end_time - $start_time );
+//		self::$filter_stats[ $this->tag ]['callbacks'] = array_merge(
+//			self::$filter_stats[ $this->tag ]['callbacks'],
+//		);
+
 		return $value;
 	}
 

dump-wp-hooks-stats.php

<?php
/**
 * Plugin name: Dump WP_Hook Stats
 */

add_action( 'shutdown', function() {
	if ( ! isset( WP_Hook::$filter_stats ) ) {
		return;
	}
	$stats = array();
	foreach ( WP_Hook::$filter_stats as $tag => $hook_stat ) {
		$stats[ $tag ] = array(
			'durations' => array_sum( wp_list_pluck( $hook_stat, 'duration' ) ),
			'count' => count( $hook_stat ),
			'callbacks' => wp_list_pluck( $hook_stat, 'callback' ),
		);
	}
	uasort( $stats, function( $a, $b ) {
		return $a['durations'] - $b['durations'];
	} );

	echo "\n\n";
	foreach ( $stats as $tag => $hook_stats ) {
		if ( $hook_stats['durations'] < 1 ) {
			continue;
		}
		print "tag: $tag\n";
		printf( "\tduration sum: %f\n", $hook_stats['durations'] );
		printf( "\tcount: %d\n", $hook_stats['count'] );
		foreach ( WP_Hook::$filter_stats[ $tag ] as $call ) {
			if ( is_string( $call['callback'] ) ) {
				$callback_name = $call['callback'];
			} elseif ( is_array( $call['callback'] ) ) {
				$callback_name = get_class( $call['callback'][0] ) . '::' . $call['callback'][1];
			} else {
				$callback_name = 'Closure';
			}
			printf( "-- %f: %s\n", round( $call['duration'], 3 ), $callback_name );
		}
	}

} );