diff --git a/README.md b/README.md index e0b95f96..808b2a9f 100644 --- a/README.md +++ b/README.md @@ -181,6 +181,91 @@ will need to execute during the course of the request. +### wp profile queries + +Profile database queries and their execution time. + +~~~ +wp profile queries [--url=] [--hook=] [--callback=] [--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. + + [--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 + +--------------------------------------+---------+ + | query | time | + +--------------------------------------+---------+ + | SELECT option_value FROM wp_options | 0.0001s | + | SELECT * FROM wp_posts WHERE ID = 1 | 0.0003s | + +--------------------------------------+---------+ + | total (2) | 0.0004s | + +--------------------------------------+---------+ + + # Show queries executed during the 'init' hook + $ wp profile queries --hook=init --fields=query,time,callback + +--------------------------------------+---------+------------------+ + | query | time | callback | + +--------------------------------------+---------+------------------+ + | SELECT * FROM wp_users | 0.0002s | my_init_func() | + +--------------------------------------+---------+------------------+ + | total (1) | 0.0002s | | + +--------------------------------------+---------+------------------+ + + # Show queries executed by a specific callback + $ wp profile queries --callback='WP_Query->get_posts()' --fields=query,time + +--------------------------------------+---------+ + | query | time | + +--------------------------------------+---------+ + | SELECT * FROM wp_posts | 0.0004s | + +--------------------------------------+---------+ + | total (1) | 0.0004s | + +--------------------------------------+---------+ + + + ### wp profile eval Profile arbitrary code execution. diff --git a/composer.json b/composer.json index 7c2eee3a..0b5e4c27 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-queries.feature b/features/profile-queries.feature new file mode 100644 index 00000000..ab15af04 --- /dev/null +++ b/features/profile-queries.feature @@ -0,0 +1,121 @@ +Feature: Profile database queries + + @require-wp-4.0 + 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 + + @require-wp-4.0 + 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 + + @require-wp-4.0 + 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 + + @require-wp-4.0 + 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 + + @require-wp-4.0 + 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 + + @require-wp-4.0 + 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 diff --git a/features/profile.feature b/features/profile.feature index 459d7d3b..a57b73fb 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=] + or: wp profile queries [--url=] [--hook=] [--callback=] [--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. diff --git a/src/Command.php b/src/Command.php index b3d6936d..8e1830db 100644 --- a/src/Command.php +++ b/src/Command.php @@ -493,6 +493,166 @@ 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. + * + * [--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 + * + * @when before_wp_load + */ + public function queries( $args, $assoc_args ) { + global $wpdb; + + $hook = Utils\get_flag_value( $assoc_args, 'hook' ); + $callback = Utils\get_flag_value( $assoc_args, 'callback' ); + $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 = null; + $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 + $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; + } + + // Get the query indices for this logger + if ( isset( $logger->query_indices ) && ! empty( $logger->query_indices ) ) { + foreach ( $logger->query_indices as $query_index ) { + if ( ! isset( $query_map[ $query_index ] ) ) { + $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_obj = new QueryLogger( + $query_data[0], // SQL query + $query_data[1], // Time + isset( $query_data[2] ) ? $query_data[2] : '', // 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 d09101e4..7ea5ef55 100644 --- a/src/Formatter.php +++ b/src/Formatter.php @@ -107,6 +107,7 @@ function ( $a, $b ) use ( $order, $orderby ) { } $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 ) { @@ -119,6 +120,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(); @@ -131,7 +137,10 @@ function ( $a, $b ) use ( $order, $orderby ) { $totals[ $i ][] = $value; } } else { - $totals[ $i ] += $value; + // Only add numeric values to prevent warnings + if ( is_numeric( $value ) ) { + $totals[ $i ] += $value; + } } if ( stripos( $fields[ $i ], '_time' ) || 'time' === $fields[ $i ] ) { $values[ $i ] = round( $value, 4 ) . 's'; diff --git a/src/Logger.php b/src/Logger.php index 0c3ab116..03c2d4e3 100644 --- a/src/Logger.php +++ b/src/Logger.php @@ -4,9 +4,13 @@ class Logger { - public $time = 0; - public $query_count = 0; - public $query_time = 0; + public $time = 0; + public $query_count = 0; + public $query_time = 0; + /** + * @var array Array of query indices tracked during this logger's execution. + */ + public $query_indices = array(); public $cache_hits = 0; public $cache_misses = 0; public $cache_ratio = null; @@ -87,6 +91,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; } } @@ -106,6 +111,7 @@ public function stop() { $this->query_offset = null; $this->cache_hit_offset = null; $this->cache_miss_offset = null; + $this->query_indices = array(); $key = array_search( $this, self::$active_loggers, true ); if ( false !== $key ) { diff --git a/src/QueryLogger.php b/src/QueryLogger.php new file mode 100644 index 00000000..50ff6b9e --- /dev/null +++ b/src/QueryLogger.php @@ -0,0 +1,32 @@ +query = $query; + $this->time = $time; + $this->caller = $caller; + $this->hook = $hook; + $this->callback = $callback; + } +}