From a449366b6678d8f52862f9c8b2f4289df40bd98d Mon Sep 17 00:00:00 2001 From: Daniel Bachhuber Date: Thu, 25 Aug 2016 07:00:39 -0700 Subject: [PATCH 1/4] First pass at profiling hook execution --- inc/class-profile-command.php | 109 +++++++++++++++++++++++++++++++++- 1 file changed, 106 insertions(+), 3 deletions(-) diff --git a/inc/class-profile-command.php b/inc/class-profile-command.php index 1bd5287..694a011 100644 --- a/inc/class-profile-command.php +++ b/inc/class-profile-command.php @@ -12,6 +12,10 @@ class Profile_Command { private $focus_scope; private $focus_start_time; private $focus_log = array(); + private $hook_scope; + private $hook_log = array(); + private $backup_wp_filter = null; + private $backup_wp_filter_callbacks = array(); private $query_offset = 0; private $focus_query_offset = 0; private $hook_offset = 0; @@ -48,6 +52,9 @@ class Profile_Command { * - template * --- * + * [--hook=] + * : Drill down into a specific hook. + * * [--fields=] * : Display one or more fields. * @@ -88,6 +95,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(){ @@ -121,6 +129,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 +165,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 +182,86 @@ 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->backup_wp_filter = $current_filter; + $this->backup_wp_filter_callbacks = $wp_filter[ $current_filter ]; + unset( $wp_filter[ $current_filter ] ); + call_user_func_array( array( $this, 'do_action' ), func_get_args() ); + } + + 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->backup_wp_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 ] ) ) { + if ( is_array( $the_['function'] ) && is_object( $the_['function'][0] ) ) { + $callback = get_class( $the_['function'][0] ) . '->' . $the_['function'][1]; + } elseif ( is_array( $the_['function'] ) && method_exists( $the_['function'][0], $the_['function'][1] ) ) { + $callback = $the_['function'][0] . '::' . $the_['function'][1]; + } elseif ( is_object( $the_['function'] ) && is_a( $the_['function'], 'Closure' ) ) { + $callback = 'function(){}'; + } + $this->hook_log[ $i ] = array( + 'callback' => $callback, + '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 ) ) { @@ -177,6 +274,12 @@ class Profile_Command { $this->focus_query_offset = count( $wpdb->queries ); } + if ( ! empty( $this->backup_wp_filter ) ) { + // $wp_filter[ $current_filter ] = $this->backup_wp_filter_callbacks; + unset( $this->backup_wp_filter ); + unset( $this->backup_wp_filter_callbacks ); + } + $this->hook_time += microtime( true ) - $this->hook_start_time; return $filter_value; } From 785c83949e463e4e124952e1e40443f48dac8a1b Mon Sep 17 00:00:00 2001 From: Daniel Bachhuber Date: Thu, 25 Aug 2016 07:13:40 -0700 Subject: [PATCH 2/4] Abstract to a dedicated helper method --- inc/class-profile-command.php | 26 ++++++++++++++++++-------- 1 file changed, 18 insertions(+), 8 deletions(-) diff --git a/inc/class-profile-command.php b/inc/class-profile-command.php index 694a011..a427986 100644 --- a/inc/class-profile-command.php +++ b/inc/class-profile-command.php @@ -228,15 +228,8 @@ class Profile_Command { foreach ( (array) current($wp_filter[$tag]) as $i => $the_ ) if ( !is_null($the_['function']) ) { if ( ! isset( $this->hook_log[ $i ] ) ) { - if ( is_array( $the_['function'] ) && is_object( $the_['function'][0] ) ) { - $callback = get_class( $the_['function'][0] ) . '->' . $the_['function'][1]; - } elseif ( is_array( $the_['function'] ) && method_exists( $the_['function'][0], $the_['function'][1] ) ) { - $callback = $the_['function'][0] . '::' . $the_['function'][1]; - } elseif ( is_object( $the_['function'] ) && is_a( $the_['function'], 'Closure' ) ) { - $callback = 'function(){}'; - } $this->hook_log[ $i ] = array( - 'callback' => $callback, + 'callback' => self::get_name_from_callback( $the_['function'] ), 'execution_time' => 0, 'query_count' => 0, 'query_time' => 0, @@ -371,4 +364,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; + } + } From 10a7f500e98dfaaf90e56c78eecfe46747ac9e83 Mon Sep 17 00:00:00 2001 From: Daniel Bachhuber Date: Thu, 25 Aug 2016 07:17:47 -0700 Subject: [PATCH 3/4] Throw an exception, because there's no way we can restore the hooks --- inc/class-profile-command.php | 88 +++++++++++++++++------------------ 1 file changed, 43 insertions(+), 45 deletions(-) diff --git a/inc/class-profile-command.php b/inc/class-profile-command.php index a427986..d8df4e5 100644 --- a/inc/class-profile-command.php +++ b/inc/class-profile-command.php @@ -14,8 +14,7 @@ class Profile_Command { private $focus_log = array(); private $hook_scope; private $hook_log = array(); - private $backup_wp_filter = null; - private $backup_wp_filter_callbacks = array(); + private $current_filter_callbacks = array(); private $query_offset = 0; private $focus_query_offset = 0; private $hook_offset = 0; @@ -183,10 +182,10 @@ class Profile_Command { } if ( $this->focus_hook && $current_filter === $this->focus_hook ) { - $this->backup_wp_filter = $current_filter; - $this->backup_wp_filter_callbacks = $wp_filter[ $current_filter ]; + $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 ); @@ -198,7 +197,7 @@ class Profile_Command { private function do_action( $tag, $arg = '' ) { global $wp_actions, $merged_filters, $wp_current_filter, $wpdb; $wp_filter = array(); - $wp_filter[ $tag ] = $this->backup_wp_filter_callbacks; + $wp_filter[ $tag ] = $this->current_filter_callbacks; if ( ! isset($wp_actions[$tag]) ) $wp_actions[$tag] = 1; @@ -267,12 +266,6 @@ class Profile_Command { $this->focus_query_offset = count( $wpdb->queries ); } - if ( ! empty( $this->backup_wp_filter ) ) { - // $wp_filter[ $current_filter ] = $this->backup_wp_filter_callbacks; - unset( $this->backup_wp_filter ); - unset( $this->backup_wp_filter_callbacks ); - } - $this->hook_time += microtime( true ) - $this->hook_start_time; return $filter_value; } @@ -283,41 +276,46 @@ class Profile_Command { private function load_wordpress_with_template() { global $wp_query; - $this->scope_track_begin( 'total' ); - $this->scope_track_begin( 'bootstrap' ); - if ( 'bootstrap' === $this->focus_scope ) { - $this->fill_hooks( array( - 'muplugins_loaded', - 'plugins_loaded', - 'setup_theme', - 'after_setup_theme', - 'init', - 'wp_loaded', - ) ); + try { + + $this->scope_track_begin( 'total' ); + $this->scope_track_begin( 'bootstrap' ); + if ( 'bootstrap' === $this->focus_scope ) { + $this->fill_hooks( array( + 'muplugins_loaded', + 'plugins_loaded', + 'setup_theme', + 'after_setup_theme', + 'init', + 'wp_loaded', + ) ); + } + WP_CLI::get_runner()->load_wordpress(); + $this->scope_track_end( 'bootstrap' ); + + // Set up the main WordPress query. + $this->current_scope = 'main_query'; + $this->scope_track_begin( 'main_query' ); + wp(); + $this->scope_track_end( 'main_query' ); + + define( 'WP_USE_THEMES', true ); + + // Template is normally loaded in global scope, so we need to replicate + foreach( $GLOBALS as $key => $value ) { + global $$key; + } + + // Load the theme template. + $this->scope_track_begin( 'template' ); + ob_start(); + require_once( ABSPATH . WPINC . '/template-loader.php' ); + ob_get_clean(); + $this->scope_track_end( 'template' ); + $this->scope_track_end( 'total' ); + } catch( Exception $e ) { + return; } - WP_CLI::get_runner()->load_wordpress(); - $this->scope_track_end( 'bootstrap' ); - - // Set up the main WordPress query. - $this->current_scope = 'main_query'; - $this->scope_track_begin( 'main_query' ); - wp(); - $this->scope_track_end( 'main_query' ); - - define( 'WP_USE_THEMES', true ); - - // Template is normally loaded in global scope, so we need to replicate - foreach( $GLOBALS as $key => $value ) { - global $$key; - } - - // Load the theme template. - $this->scope_track_begin( 'template' ); - ob_start(); - require_once( ABSPATH . WPINC . '/template-loader.php' ); - ob_get_clean(); - $this->scope_track_end( 'template' ); - $this->scope_track_end( 'total' ); } /** From 1ea2fd2a92c31c7efa4b91ac781376493b0b5da0 Mon Sep 17 00:00:00 2001 From: Daniel Bachhuber Date: Thu, 25 Aug 2016 07:19:16 -0700 Subject: [PATCH 4/4] Better place to put the Exception handling --- inc/class-profile-command.php | 79 +++++++++++++++++------------------ 1 file changed, 39 insertions(+), 40 deletions(-) diff --git a/inc/class-profile-command.php b/inc/class-profile-command.php index d8df4e5..0a1f8a7 100644 --- a/inc/class-profile-command.php +++ b/inc/class-profile-command.php @@ -105,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( @@ -276,46 +280,41 @@ class Profile_Command { private function load_wordpress_with_template() { global $wp_query; - try { - - $this->scope_track_begin( 'total' ); - $this->scope_track_begin( 'bootstrap' ); - if ( 'bootstrap' === $this->focus_scope ) { - $this->fill_hooks( array( - 'muplugins_loaded', - 'plugins_loaded', - 'setup_theme', - 'after_setup_theme', - 'init', - 'wp_loaded', - ) ); - } - WP_CLI::get_runner()->load_wordpress(); - $this->scope_track_end( 'bootstrap' ); - - // Set up the main WordPress query. - $this->current_scope = 'main_query'; - $this->scope_track_begin( 'main_query' ); - wp(); - $this->scope_track_end( 'main_query' ); - - define( 'WP_USE_THEMES', true ); - - // Template is normally loaded in global scope, so we need to replicate - foreach( $GLOBALS as $key => $value ) { - global $$key; - } - - // Load the theme template. - $this->scope_track_begin( 'template' ); - ob_start(); - require_once( ABSPATH . WPINC . '/template-loader.php' ); - ob_get_clean(); - $this->scope_track_end( 'template' ); - $this->scope_track_end( 'total' ); - } catch( Exception $e ) { - return; + $this->scope_track_begin( 'total' ); + $this->scope_track_begin( 'bootstrap' ); + if ( 'bootstrap' === $this->focus_scope ) { + $this->fill_hooks( array( + 'muplugins_loaded', + 'plugins_loaded', + 'setup_theme', + 'after_setup_theme', + 'init', + 'wp_loaded', + ) ); } + WP_CLI::get_runner()->load_wordpress(); + $this->scope_track_end( 'bootstrap' ); + + // Set up the main WordPress query. + $this->current_scope = 'main_query'; + $this->scope_track_begin( 'main_query' ); + wp(); + $this->scope_track_end( 'main_query' ); + + define( 'WP_USE_THEMES', true ); + + // Template is normally loaded in global scope, so we need to replicate + foreach( $GLOBALS as $key => $value ) { + global $$key; + } + + // Load the theme template. + $this->scope_track_begin( 'template' ); + ob_start(); + require_once( ABSPATH . WPINC . '/template-loader.php' ); + ob_get_clean(); + $this->scope_track_end( 'template' ); + $this->scope_track_end( 'total' ); } /**