diff --git a/inc/class-profile-command.php b/inc/class-profile-command.php index 1bd5287..0a1f8a7 100644 --- a/inc/class-profile-command.php +++ b/inc/class-profile-command.php @@ -12,6 +12,9 @@ class Profile_Command { private $focus_scope; private $focus_start_time; private $focus_log = array(); + private $hook_scope; + private $hook_log = array(); + private $current_filter_callbacks = array(); private $query_offset = 0; private $focus_query_offset = 0; private $hook_offset = 0; @@ -48,6 +51,9 @@ class Profile_Command { * - template * --- * + * [--hook=] + * : Drill down into a specific hook. + * * [--fields=] * : Display one or more fields. * @@ -88,6 +94,7 @@ class Profile_Command { } $this->focus_scope = WP_CLI\Utils\get_flag_value( $assoc_args, 'scope' ); + $this->focus_hook = WP_CLI\Utils\get_flag_value( $assoc_args, 'hook' ); if ( ! isset( \WP_CLI::get_runner()->config['url'] ) ) { WP_CLI::add_wp_hook( 'muplugins_loaded', function(){ @@ -98,7 +105,11 @@ class Profile_Command { define( 'SAVEQUERIES', true ); } WP_CLI::add_wp_hook( 'all', array( $this, 'wp_hook_begin' ) ); - $this->load_wordpress_with_template(); + try { + $this->load_wordpress_with_template(); + } catch( Exception $e ) { + // pass through + } if ( $this->focus_scope ) { $focus_fields = array( @@ -121,6 +132,23 @@ class Profile_Command { } $formatter = new \WP_CLI\Formatter( $assoc_args, $focus_fields ); $formatter->display_items( $this->focus_log ); + } else if ( $this->focus_hook ) { + $hook_fields = array( + 'callback', + 'execution_time', + 'query_time', + 'query_count', + ); + foreach( $this->hook_log as $id => $data ) { + foreach( $data as $key => $value ) { + // Round times to 4 decimal points + if ( stripos( $key,'_time' ) ) { + $this->hook_log[ $id ][ $key ] = round( $value, 4 ) . 's'; + } + } + } + $formatter = new \WP_CLI\Formatter( $assoc_args, $hook_fields ); + $formatter->display_items( $this->hook_log ); } else { foreach( $this->scope_log as $scope => $data ) { @@ -140,7 +168,7 @@ class Profile_Command { * Profiling verbosity at the beginning of every action and filter */ public function wp_hook_begin() { - global $wpdb; + global $wpdb, $wp_filter; $this->scope_log['total']['hook_count']++; $this->scope_log[ $this->current_scope ]['hook_count']++; @@ -157,14 +185,79 @@ class Profile_Command { $this->focus_query_offset = count( $wpdb->queries ); } - WP_CLI::add_wp_hook( current_filter(), array( $this, 'wp_hook_end' ), 999 ); + if ( $this->focus_hook && $current_filter === $this->focus_hook ) { + $this->current_filter_callbacks = $wp_filter[ $current_filter ]; + unset( $wp_filter[ $current_filter ] ); + call_user_func_array( array( $this, 'do_action' ), func_get_args() ); + throw new Exception( "Need to bail, because can't restore the hooks" ); + } + + WP_CLI::add_wp_hook( $current_filter, array( $this, 'wp_hook_end' ), 999 ); + } + + /** + * Instrumented version of do_action() + */ + private function do_action( $tag, $arg = '' ) { + global $wp_actions, $merged_filters, $wp_current_filter, $wpdb; + $wp_filter = array(); + $wp_filter[ $tag ] = $this->current_filter_callbacks; + + if ( ! isset($wp_actions[$tag]) ) + $wp_actions[$tag] = 1; + else + ++$wp_actions[$tag]; + + if ( !isset($wp_filter['all']) ) + $wp_current_filter[] = $tag; + + $args = array(); + if ( is_array($arg) && 1 == count($arg) && isset($arg[0]) && is_object($arg[0]) ) // array(&$this) + $args[] =& $arg[0]; + else + $args[] = $arg; + for ( $a = 2, $num = func_num_args(); $a < $num; $a++ ) + $args[] = func_get_arg($a); + + // Sort + if ( !isset( $merged_filters[ $tag ] ) ) { + ksort($wp_filter[$tag]); + $merged_filters[ $tag ] = true; + } + + reset( $wp_filter[ $tag ] ); + + do { + foreach ( (array) current($wp_filter[$tag]) as $i => $the_ ) + if ( !is_null($the_['function']) ) { + if ( ! isset( $this->hook_log[ $i ] ) ) { + $this->hook_log[ $i ] = array( + 'callback' => self::get_name_from_callback( $the_['function'] ), + 'execution_time' => 0, + 'query_count' => 0, + 'query_time' => 0, + ); + } + $start_time = microtime( true ); + $query_offset = count( $wpdb->queries ); + call_user_func_array($the_['function'], array_slice($args, 0, (int) $the_['accepted_args'])); + $this->hook_log[ $i ]['execution_time'] = microtime( true ) - $start_time; + for ( $j = $query_offset; $j < count( $wpdb->queries ); $j++ ) { + $this->hook_log[ $i ]['query_time'] += $wpdb->queries[ $i ][1]; + $this->hook_log[ $i ]['query_count']++; + } + } + + } while ( next($wp_filter[$tag]) !== false ); + + array_pop($wp_current_filter); } /** * Profiling verbosity at the end of every action and filter */ public function wp_hook_end( $filter_value = null ) { - global $wpdb; + global $wpdb, $wp_filter; $current_filter = current_filter(); if ( array_key_exists( $current_filter, $this->focus_log ) ) { @@ -268,4 +361,21 @@ class Profile_Command { $this->focus_start_time = microtime( true ); } + /** + * Get a human-readable name from a callback + */ + private static function get_name_from_callback( $callback ) { + $name = ''; + if ( is_array( $callback ) && is_object( $callback[0] ) ) { + $name = get_class( $callback[0] ) . '->' . $callback[1] . '()'; + } elseif ( is_array( $callback ) && method_exists( $callback[0], $callback[1] ) ) { + $name = $callback[0] . '::' . $callback[1] . '()'; + } elseif ( is_object( $callback ) && is_a( $callback, 'Closure' ) ) { + $name = 'function(){}'; + } else if ( is_string( $callback ) ) { + $name = $callback . '()'; + } + return $name; + } + }