diff --git a/README.md b/README.md index 8d5b2abc..92789069 100644 --- a/README.md +++ b/README.md @@ -298,6 +298,75 @@ current theme. | 0.1009s | 100% | 1 | +---------+-------------+---------------+ + + +### wp profile queries + +Profile database queries and their execution time. + +~~~ +wp profile queries [--url=] [--hook=] [--callback=] [--time_threshold=] [--fields=] [--format=] [--order=] [--orderby=] +~~~ + +Displays all database queries executed during a WordPress request, +along with their execution time and caller information. You can filter +queries to only show those executed during a specific hook or by a +specific callback. + +**OPTIONS** + + [--url=] + Execute a request against a specified URL. Defaults to the home URL. + + [--hook=] + Filter queries to only show those executed during a specific hook. + + [--callback=] + Filter queries to only show those executed by a specific callback. + + [--time_threshold=] + Filter queries to only show those that took longer than or equal to a certain number of seconds. + + [--fields=] + Limit the output to specific fields. + + [--format=] + Render output in a particular format. + --- + default: table + options: + - table + - json + - yaml + - csv + --- + + [--order=] + Ascending or Descending order. + --- + default: ASC + options: + - ASC + - DESC + --- + + [--orderby=] + Set orderby which field. + +**EXAMPLES** + + # Show all queries with their execution time + $ wp profile queries --fields=query,time + + # Show queries executed during the 'init' hook + $ wp profile queries --hook=init --fields=query,time,caller + + # Show queries executed by a specific callback + $ wp profile queries --callback='WP_Query->get_posts()' --fields=query,time + + # Show queries ordered by execution time + $ wp profile queries --fields=query,time --orderby=time --order=DESC + ## Installing Installing this package requires WP-CLI v2.13 or greater. Update to the latest stable release with `wp cli update`. diff --git a/composer.json b/composer.json index 2ccef999..df286ea3 100644 --- a/composer.json +++ b/composer.json @@ -29,7 +29,8 @@ "profile stage", "profile hook", "profile eval", - "profile eval-file" + "profile eval-file", + "profile queries" ], "readme": { "sections": [ diff --git a/features/profile-hook.feature b/features/profile-hook.feature index bb30ccbc..20dc8287 100644 --- a/features/profile-hook.feature +++ b/features/profile-hook.feature @@ -36,7 +36,6 @@ Feature: Profile a specific hook | total (0) | And STDERR should be empty - @require-wp-4.0 Scenario: Profile a hook that has actions with output Given a WP install diff --git a/features/profile-queries.feature b/features/profile-queries.feature new file mode 100644 index 00000000..9db89fa6 --- /dev/null +++ b/features/profile-queries.feature @@ -0,0 +1,188 @@ +Feature: Profile database queries + + Scenario: Show all database queries + Given a WP install + And a wp-content/mu-plugins/test-queries.php file: + """ + query( "SELECT 1 as test_query_one" ); + $wpdb->query( "SELECT 2 as test_query_two" ); + }); + """ + + When I run `wp profile queries --fields=query,time` + Then STDOUT should contain: + """ + query + """ + And STDOUT should contain: + """ + time + """ + And STDOUT should contain: + """ + SELECT 1 as test_query_one + """ + And STDOUT should contain: + """ + SELECT 2 as test_query_two + """ + And STDOUT should contain: + """ + total + """ + And STDERR should be empty + + Scenario: Show queries with specific fields + Given a WP install + + When I run `wp profile queries --fields=query,time` + Then STDOUT should contain: + """ + query + """ + And STDOUT should contain: + """ + time + """ + And STDOUT should contain: + """ + SELECT + """ + And STDERR should be empty + + Scenario: Order queries by execution time + Given a WP install + + When I run `wp profile queries --fields=time --orderby=time --order=DESC` + Then STDOUT should contain: + """ + time + """ + And STDERR should be empty + + Scenario: Display queries in JSON format + Given a WP install + + When I run `wp profile queries --format=json --fields=query,time` + Then STDOUT should contain: + """ + "query" + """ + And STDOUT should contain: + """ + "time" + """ + And STDERR should be empty + + Scenario: Filter queries by hook + Given a WP install + And a wp-content/mu-plugins/query-test.php file: + """ + query( "SELECT 1 as test_query" ); + }); + """ + + When I run `wp profile queries --hook=init --fields=query,callback` + Then STDOUT should contain: + """ + SELECT 1 as test_query + """ + And STDERR should be empty + + Scenario: Filter queries by callback + Given a WP install + And a wp-content/mu-plugins/callback-test.php file: + """ + query( "SELECT 2 as callback_test" ); + } + add_action( 'init', 'my_test_callback' ); + """ + + When I run `wp profile queries --callback=my_test_callback --fields=query,hook` + Then STDOUT should contain: + """ + SELECT 2 as callback_test + """ + And STDERR should be empty + + Scenario: Filter queries by time threshold + Given a WP install + And a wp-content/mu-plugins/test-threshold.php file: + """ + queries[] = array( 'SELECT 1 as test_query_fast', 0.01, 'caller' ); + $wpdb->queries[] = array( 'SELECT 2 as test_query_slow', 0.2, 'caller' ); + }); + """ + + When I run `wp profile queries --fields=query --time_threshold=0.1` + Then STDOUT should contain: + """ + SELECT 2 as test_query_slow + """ + And STDOUT should not contain: + """ + SELECT 1 as test_query_fast + """ + And STDERR should be empty + + Scenario: Format caller with newlines + Given a WP install + And a wp-content/mu-plugins/test-caller.php file: + """ + queries[] = array( 'SELECT 3 as test_caller', 0.01, 'frame1, frame2, frame3' ); + } + add_action( 'init', 'my_test_function' ); + """ + + When I run `wp profile queries --callback=my_test_function --fields=caller --format=json` + Then STDOUT should be JSON containing: + """ + [ + { + "caller": "frame1\nframe2\nframe3" + } + ] + """ + And STDERR should be empty + + Scenario: Format caller with newlines and strip WP-CLI frames + Given a WP install + And a wp-content/mu-plugins/test-caller-strip.php file: + """ + queries[] = array( 'SELECT 4 as test_caller_strip_1', 0.01, 'WP_CLI\Main, WP_CLI\Profile\Profiler->load_wordpress_with_template(), frame1, frame2' ); + $wpdb->queries[] = array( 'SELECT 5 as test_caller_strip_2', 0.01, 'WP_CLI\Main, WP_CLI\Profile\Profiler->load_wordpress_with_template, frame3, frame4' ); + } + add_action( 'init', 'my_test_function_strip' ); + """ + + When I run `wp profile queries --callback=my_test_function_strip --fields=caller --format=json` + Then STDOUT should be JSON containing: + """ + [ + { + "caller": "frame1\nframe2" + }, + { + "caller": "frame3\nframe4" + } + ] + """ + And STDERR should be empty diff --git a/features/profile-stage.feature b/features/profile-stage.feature index ee993ca1..54588cd4 100644 --- a/features/profile-stage.feature +++ b/features/profile-stage.feature @@ -1,6 +1,5 @@ Feature: Profile the template render stage - @require-wp-4.0 Scenario: Profiler loads a summary table Given a WP install @@ -11,7 +10,6 @@ Feature: Profile the template render stage | main_query | | template | - @require-wp-4.0 Scenario: Profiler loads a table with the correct hooks Given a WP install @@ -81,7 +79,6 @@ Feature: Profile the template render stage | loop_end:before | | loop_end | - @require-wp-4.0 Scenario: Use --all flag to profile all stages Given a WP install @@ -134,7 +131,6 @@ Feature: Profile the template render stage Error: Invalid stage. Must be one of bootstrap, main_query, template, or use --all. """ - @require-wp-4.0 Scenario: Invalid field name supplied to --fields Given a WP install @@ -145,7 +141,6 @@ Feature: Profile the template render stage """ And the return code should be 1 - @require-wp-4.0 Scenario: Identify callback_count for each hook Given a WP install @@ -154,7 +149,6 @@ Feature: Profile the template render stage | hook | callback_count | | muplugins_loaded | 2 | - @require-wp-4.0 Scenario: Use spotlight mode to filter out the zero-ish values Given a WP install diff --git a/features/profile.feature b/features/profile.feature index a5b95c98..62cdce9d 100644 --- a/features/profile.feature +++ b/features/profile.feature @@ -9,6 +9,7 @@ Feature: Basic profile usage usage: wp profile eval [--hook[=]] [--fields=] [--format=] [--order=] [--orderby=] or: wp profile eval-file [--hook[=]] [--fields=] [--format=] [--order=] [--orderby=] or: wp profile hook [] [--all] [--spotlight] [--url=] [--fields=] [--format=] [--order=] [--orderby=] [--search=] + or: wp profile queries [--url=] [--hook=] [--callback=] [--time_threshold=] [--fields=] [--format=] [--order=] [--orderby=] or: wp profile stage [] [--all] [--spotlight] [--url=] [--fields=] [--format=] [--order=] [--orderby=] See 'wp help profile ' for more information on a specific command. @@ -36,7 +37,6 @@ Feature: Basic profile usage Error: 'SAVEQUERIES' is defined as false, and must be true. Please check your wp-config.php """ - @require-wp-4.0 Scenario: Profile a hook without any callbacks Given a WP install @@ -46,7 +46,6 @@ Feature: Basic profile usage | total (0) | | And STDERR should be empty - @require-wp-4.0 Scenario: Trailingslash provided URL to avoid canonical redirect Given a WP install diff --git a/src/Command.php b/src/Command.php index b644a3cd..1f7d4463 100644 --- a/src/Command.php +++ b/src/Command.php @@ -540,6 +540,201 @@ private static function include_file( $file ) { include $file; } + /** + * Profile database queries and their execution time. + * + * Displays all database queries executed during a WordPress request, + * along with their execution time and caller information. You can filter + * queries to only show those executed during a specific hook or by a + * specific callback. + * + * ## OPTIONS + * + * [--url=] + * : Execute a request against a specified URL. Defaults to the home URL. + * + * [--hook=] + * : Filter queries to only show those executed during a specific hook. + * + * [--callback=] + * : Filter queries to only show those executed by a specific callback. + * + * [--time_threshold=] + * : Filter queries to only show those that took longer than or equal to a certain number of seconds. + * + * [--fields=] + * : Limit the output to specific fields. + * + * [--format=] + * : Render output in a particular format. + * --- + * default: table + * options: + * - table + * - json + * - yaml + * - csv + * --- + * + * [--order=] + * : Ascending or Descending order. + * --- + * default: ASC + * options: + * - ASC + * - DESC + * --- + * + * [--orderby=] + * : Set orderby which field. + * + * ## EXAMPLES + * + * # Show all queries with their execution time + * $ wp profile queries --fields=query,time + * + * # Show queries executed during the 'init' hook + * $ wp profile queries --hook=init --fields=query,time,caller + * + * # Show queries executed by a specific callback + * $ wp profile queries --callback='WP_Query->get_posts()' --fields=query,time + * + * # Show queries ordered by execution time + * $ wp profile queries --fields=query,time --orderby=time --order=DESC + * + * @skipglobalargcheck + * @when before_wp_load + * + * @param array $args Positional arguments. Unused + * @param array{url?: string, hook?: string, callback?: string, time_threshold?: string, fields?: string, format: string, order: string, orderby: string} $assoc_args Associative arguments. + * @return void + */ + public function queries( $args, $assoc_args ) { + global $wpdb; + + $hook = Utils\get_flag_value( $assoc_args, 'hook' ); + $callback = Utils\get_flag_value( $assoc_args, 'callback' ); + $time_threshold = Utils\get_flag_value( $assoc_args, 'time_threshold' ); + $order = Utils\get_flag_value( $assoc_args, 'order', 'ASC' ); + $orderby = Utils\get_flag_value( $assoc_args, 'orderby', null ); + + // Set up profiler to track hooks and callbacks + $type = false; + $focus = null; + if ( $hook && $callback ) { + // When both are provided, profile all hooks to find the specific callback + $type = 'hook'; + $focus = true; + } elseif ( $hook ) { + $type = 'hook'; + $focus = $hook; + } elseif ( $callback ) { + $type = 'hook'; + $focus = true; // Profile all hooks to find the specific callback + } + + $profiler = new Profiler( $type, $focus ); + $profiler->run(); + + // Build a map of query indices to hooks/callbacks + // This is O(N*Q + M) where N=loggers, Q=queries per logger, M=total queries + // For typical WordPress sites, this performs well with the array-based lookups + $query_map = array(); + if ( $hook || $callback ) { + $loggers = $profiler->get_loggers(); + foreach ( $loggers as $logger ) { + // Skip if filtering by callback and this logger doesn't have a callback + if ( $callback && ! isset( $logger->callback ) ) { + continue; + } + + // Skip if filtering by callback and this isn't the right one + if ( $callback && isset( $logger->callback ) ) { + // Normalize callback for comparison + $normalized_callback = trim( (string) $logger->callback ); + $normalized_filter = trim( $callback ); + if ( false === stripos( $normalized_callback, $normalized_filter ) ) { + continue; + } + } + + // Skip if filtering for a specific hook and this isn't the right one + if ( $hook && isset( $logger->hook ) && $logger->hook !== $hook ) { + continue; + } + + // Skip if filtering for a specific hook and the logger has no hook property + if ( $hook && ! isset( $logger->hook ) ) { + continue; + } + + // Get the query indices for this logger + if ( ! empty( $logger->query_indices ) ) { + foreach ( $logger->query_indices as $query_index ) { + // Use last-logger-wins to get the most specific hook/callback + $query_map[ $query_index ] = array( + 'hook' => isset( $logger->hook ) ? $logger->hook : null, + 'callback' => isset( $logger->callback ) ? $logger->callback : null, + ); + } + } + } + } + + // Get all queries + $queries = array(); + if ( ! empty( $wpdb->queries ) ) { + foreach ( $wpdb->queries as $index => $query_data ) { + // If filtering by hook/callback, only include queries in the map + if ( ( $hook || $callback ) && ! isset( $query_map[ $index ] ) ) { + continue; + } + + $query_time = $query_data[1]; + if ( null !== $time_threshold && $query_time < (float) $time_threshold ) { + continue; + } + + $caller = isset( $query_data[2] ) ? $query_data[2] : ''; + + // Exclude WP-CLI frames up to load_wordpress_with_template + $marker = 'WP_CLI\Profile\Profiler->load_wordpress_with_template'; + $pos = strpos( $caller, $marker ); + if ( false !== $pos ) { + $caller = substr( $caller, $pos + strlen( $marker ) ); + if ( 0 === strpos( $caller, '()' ) ) { + $caller = substr( $caller, 2 ); + } + $caller = ltrim( $caller, ', ' ); + } + + $caller = str_replace( ', ', "\n", $caller ); + + $query_obj = new QueryLogger( + $query_data[0], // SQL query + $query_time, // Time + $caller, // Caller + isset( $query_map[ $index ]['hook'] ) ? $query_map[ $index ]['hook'] : null, + isset( $query_map[ $index ]['callback'] ) ? $query_map[ $index ]['callback'] : null + ); + $queries[] = $query_obj; + } + } + + // Set up fields for output + $fields = array( 'query', 'time', 'caller' ); + if ( $hook && ! $callback ) { + $fields = array( 'query', 'time', 'callback', 'caller' ); + } elseif ( $callback && ! $hook ) { + $fields = array( 'query', 'time', 'hook', 'caller' ); + } elseif ( $hook && $callback ) { + $fields = array( 'query', 'time', 'hook', 'callback', 'caller' ); + } + + $formatter = new Formatter( $assoc_args, $fields ); + $formatter->display_items( $queries, true, $order, $orderby ); + } + /** * Filter loggers with zero-ish values. * diff --git a/src/Formatter.php b/src/Formatter.php index f5e49a9c..4829d26b 100644 --- a/src/Formatter.php +++ b/src/Formatter.php @@ -79,10 +79,10 @@ function ( $val ) { /** * Display multiple items according to the output arguments. * - * @param array<\WP_CLI\Profile\Logger> $items - * @param bool $include_total - * @param string $order - * @param string|null $orderby + * @param array<\WP_CLI\Profile\Logger|\WP_CLI\Profile\QueryLogger> $items + * @param bool $include_total + * @param string $order + * @param string|null $orderby * @return void */ public function display_items( $items, $include_total, $order, $orderby ) { @@ -118,11 +118,11 @@ private function compare_float( $a, $b ) { /** * Show items in a \cli\Table. * - * @param string $order - * @param string|null $orderby - * @param array<\WP_CLI\Profile\Logger> $items - * @param array $fields - * @param bool $include_total + * @param string $order + * @param string|null $orderby + * @param array<\WP_CLI\Profile\Logger|\WP_CLI\Profile\QueryLogger> $items + * @param array $fields + * @param bool $include_total * @return void */ private function show_table( $order, $orderby, $items, $fields, $include_total ) { @@ -157,7 +157,8 @@ function ( $a, $b ) use ( $order, $orderby ) { ); } - $location_index = array_search( 'location', $fields, true ); + $location_index = array_search( 'location', $fields, true ); + $non_numeric_fields = array( 'query', 'caller', 'hook', 'callback' ); foreach ( $items as $item ) { $values = array_values( \WP_CLI\Utils\pick_fields( $item, $fields ) ); foreach ( $values as $i => $value ) { @@ -170,6 +171,11 @@ function ( $a, $b ) use ( $order, $orderby ) { continue; } + // Ignore non-numeric fields (query, caller, hook, callback) + if ( in_array( $fields[ $i ], $non_numeric_fields, true ) ) { + continue; + } + if ( null === $totals[ $i ] ) { if ( stripos( $fields[ $i ], '_ratio' ) ) { $totals[ $i ] = array(); @@ -182,10 +188,8 @@ function ( $a, $b ) use ( $order, $orderby ) { assert( is_array( $totals[ $i ] ) ); $totals[ $i ][] = $value; } - } else { - $current_total = is_numeric( $totals[ $i ] ) ? $totals[ $i ] : 0; - $add_value = is_numeric( $value ) ? $value : 0; - $totals[ $i ] = $current_total + $add_value; + } elseif ( is_numeric( $value ) && is_numeric( $totals[ $i ] ) ) { + $totals[ $i ] += $value; } if ( stripos( $fields[ $i ], '_time' ) || 'time' === $fields[ $i ] ) { $value_num = is_numeric( $value ) ? (float) $value : 0.0; diff --git a/src/Logger.php b/src/Logger.php index f6e53ecb..ff2882bb 100644 --- a/src/Logger.php +++ b/src/Logger.php @@ -7,15 +7,21 @@ * * @property string $callback * @property string $location + * @property string $hook */ class Logger { /** @var float */ - public $time = 0; + public $time = 0.0; /** @var int */ public $query_count = 0; /** @var float */ - public $query_time = 0; + public $query_time = 0.0; + /** + * @var array Array of query indices tracked during this logger's execution. + */ + public $query_indices = array(); + /** @var int */ public $cache_hits = 0; /** @var int */ @@ -142,6 +148,7 @@ public function stop() { for ( $i = $this->query_offset; $i < $query_total_count; $i++ ) { $this->query_time += $wpdb->queries[ $i ][1]; ++$this->query_count; + $this->query_indices[] = $i; } } diff --git a/src/Profiler.php b/src/Profiler.php index bb5a6585..37ae2ef8 100644 --- a/src/Profiler.php +++ b/src/Profiler.php @@ -314,10 +314,11 @@ private function wrap_current_filter_callbacks( $current_filter ) { if ( is_array( $the_ ) && isset( $the_['function'] ) && isset( $the_['accepted_args'] ) ) { $func = $the_['function']; $new_priority_callbacks[ $i ] = array( - 'function' => function () use ( $func, $i ) { + 'function' => function () use ( $func, $i, $current_filter ) { if ( ! isset( $this->loggers[ $i ] ) ) { $this->loggers[ $i ] = new Logger( array( + 'hook' => $current_filter, 'callback' => $func, ) ); diff --git a/src/QueryLogger.php b/src/QueryLogger.php new file mode 100644 index 00000000..0684bdbb --- /dev/null +++ b/src/QueryLogger.php @@ -0,0 +1,41 @@ +query = $query; + $this->time = $time; + $this->caller = $caller; + $this->hook = $hook; + $this->callback = $callback; + } +}