theme-plugin-profiling.php.diff

diff --git a/wp-includes/plugin.php b/wp-includes/plugin.php
index df4ba8d..3a703de 100644
--- a/wp-includes/plugin.php
+++ b/wp-includes/plugin.php
@@ -196,7 +196,9 @@ function apply_filters( $tag, $value ) {
 		foreach( (array) current($wp_filter[$tag]) as $the_ )
 			if ( !is_null($the_['function']) ){
 				$args[1] = $value;
+				xteam_push_plugin_hook_profile( $tag, $the_['function'] );
 				$value = call_user_func_array($the_['function'], array_slice($args, 1, (int) $the_['accepted_args']));
+				xteam_pop_plugin_hook_profile();
 			}
 
 	} while ( next($wp_filter[$tag]) !== false );
@@ -252,8 +254,11 @@ function apply_filters_ref_array($tag, $args) {
 
 	do {
 		foreach( (array) current($wp_filter[$tag]) as $the_ )
-			if ( !is_null($the_['function']) )
+			if ( !is_null($the_['function']) ) {
+				xteam_push_plugin_hook_profile( $tag, $the_['function'] );
 				$args[0] = call_user_func_array($the_['function'], array_slice($args, 0, (int) $the_['accepted_args']));
+				xteam_pop_plugin_hook_profile();
+			}
 
 	} while ( next($wp_filter[$tag]) !== false );
 
@@ -425,8 +430,11 @@ function do_action($tag, $arg = '') {
 
 	do {
 		foreach ( (array) current($wp_filter[$tag]) as $the_ )
-			if ( !is_null($the_['function']) )
+			if ( !is_null($the_['function']) ) {
+				xteam_push_plugin_hook_profile( $tag, $the_['function'] );
 				call_user_func_array($the_['function'], array_slice($args, 0, (int) $the_['accepted_args']));
+				xteam_pop_plugin_hook_profile();
+			}
 
 	} while ( next($wp_filter[$tag]) !== false );
 
@@ -503,8 +511,11 @@ function do_action_ref_array($tag, $args) {
 
 	do {
 		foreach( (array) current($wp_filter[$tag]) as $the_ )
-			if ( !is_null($the_['function']) )
+			if ( !is_null($the_['function']) ) {
+				xteam_push_plugin_hook_profile( $tag, $the_['function'] );
 				call_user_func_array($the_['function'], array_slice($args, 0, (int) $the_['accepted_args']));
+				xteam_pop_plugin_hook_profile();
+			}
 
 	} while ( next($wp_filter[$tag]) !== false );
 
@@ -735,8 +746,11 @@ function _wp_call_all_hook($args) {
 	reset( $wp_filter['all'] );
 	do {
 		foreach( (array) current($wp_filter['all']) as $the_ )
-			if ( !is_null($the_['function']) )
+			if ( !is_null($the_['function']) ) {
+				xteam_push_plugin_hook_profile( 'all', $the_['function'] );
 				call_user_func_array($the_['function'], $args);
+				xteam_pop_plugin_hook_profile();
+			}
 
 	} while ( next($wp_filter['all']) !== false );
 }
@@ -807,3 +821,79 @@ function _wp_filter_build_unique_id($tag, $function, $priority) {
 		return $function[0] . '::' . $function[1];
 	}
 }
+
+
+global $xteam_hook_profiling;
+$xteam_hook_profiling = array();
+
+global $xteam_hook_profile_stack;
+$xteam_hook_profile_stack = array();
+
+function xteam_get_reflection( $callable ) {
+	try {
+		if ( is_array( $callable ) ) {
+			list( $class, $method ) = $callable;
+			return new ReflectionMethod( $class, $method );
+		} else {
+			return new ReflectionFunction( $callable );
+		}
+	}
+	catch ( ReflectionException $e ) {
+		return null;
+	}
+}
+
+function xteam_push_plugin_hook_profile( $hook, $function ) {
+	global $xteam_hook_profile_stack;
+	$reflection = xteam_get_reflection( $function );
+	$xteam_hook_profile_stack[] = array(
+		'reflection' => $reflection,
+		'start_time' => microtime( true ),
+		'hook' => $hook,
+		'function' => $function,
+	);
+
+}
+function xteam_pop_plugin_hook_profile() {
+	global $xteam_hook_profiling;
+	global $xteam_hook_profile_stack;
+	$end_time = microtime( true );
+	$entry = array_pop( $xteam_hook_profile_stack );
+	$hook = $entry['hook'];
+
+	$is_introspected = (
+		! empty( $entry['reflection'] )
+		&&
+		$entry['reflection']->getFileName()
+		&&
+		preg_match( '#/wp-content/(mu-plugins|plugins|themes)/([^/]+)#', $entry['reflection']->getFileName(), $matches )
+	);
+	if ( $is_introspected ) {
+		if ( empty( $xteam_hook_profiling[ $hook ] ) ) {
+			$xteam_hook_profiling[ $hook ] = array();
+		}
+		$profile = array(
+			'time' => $end_time - $entry['start_time'],
+			'type' => $matches[1],
+			'slug' => $matches[2],
+		);
+		$xteam_hook_profiling[ $hook ][] = $profile;
+	}
+}
+
+register_shutdown_function( function () use ( &$xteam_hook_profiling )  {
+	$total_cost = array();
+	foreach ( $xteam_hook_profiling as $hook => $invocations ) {
+		foreach ( $invocations as $invocation ) {
+			$slug = $invocation['type'] . ':' . $invocation['slug'];
+			if ( ! isset( $total_cost[$slug] ) ) {
+				$total_cost[$slug] = 0;
+			}
+			$total_cost[$slug] += $invocation['time'];
+		}
+	}
+
+	krsort($total_cost);
+
+	error_log( print_r( $total_cost, true ) );
+} );

@weston Checking out Debug bar Slow Actions plugin, i think it hooks into the 'all' hook, and thus runs on all filters/actions, and starts the count there, and from inside that function, i presume, it again registers itself with high priority to the same (current) filter/action to end the timer.
Wouldn't that achieve the same result we're trying to achieve with this edit ?
Actually no, it calculate the total time of all executed actions, not individual ones. Got it.