diff --git a/features/profile-eval.feature b/features/profile-eval.feature index 6a0a694a..3e3e8e34 100644 --- a/features/profile-eval.feature +++ b/features/profile-eval.feature @@ -10,10 +10,10 @@ Feature: Profile arbitary code execution } """ - When I run `wp profile eval 'wp_cli_do_nothing();' --fields=query_time,query_count,cache_ratio,cache_hits,cache_misses,request_time,request_count` + When I run `wp profile eval 'wp_cli_do_nothing();' --fields=query_time,query_count,cache_ratio,cache_hits,cache_misses,cache_calls,request_time,request_count` Then STDOUT should be a table containing rows: - | query_time | query_count | cache_ratio | cache_hits | cache_misses | request_time | request_count | - | 0s | 0 | | 0 | 0 | 0s | 0 | + | query_time | query_count | cache_ratio | cache_hits | cache_misses | cache_calls | request_time | request_count | + | 0s | 0 | | 0 | 0 | 0 | 0s | 0 | Scenario: Profile a function that makes one HTTP request Given a WP install @@ -48,3 +48,143 @@ Feature: Profile arbitary code execution Then STDOUT should be a table containing rows: | callback | cache_hits | cache_misses | | function(){} | 0 | 1 | + + Scenario: cache_calls shows 0 when no persistent object cache is active + Given a WP install + + When I run `wp profile eval 'wp_cache_get( "foo" );' --fields=cache_misses,cache_calls` + Then STDOUT should be a table containing rows: + | cache_misses | cache_calls | + | 1 | 0 | + + Scenario: cache_calls tracks calls to a persistent object cache that exposes cache_calls + Given a WP install + And a wp-content/object-cache.php file: + """ + add( $key, $data, $group, (int) $expire ); + } + function wp_cache_add_global_groups( $groups ) { + global $wp_object_cache; + $wp_object_cache->add_global_groups( $groups ); + } + function wp_cache_add_non_persistent_groups( $groups ) {} + function wp_cache_close() { return true; } + function wp_cache_decr( $key, $offset = 1, $group = '' ) { + global $wp_object_cache; + return $wp_object_cache->decr( $key, $offset, $group ); + } + function wp_cache_delete( $key, $group = '' ) { + global $wp_object_cache; + return $wp_object_cache->delete( $key, $group ); + } + function wp_cache_flush() { + global $wp_object_cache; + return $wp_object_cache->flush(); + } + function wp_cache_get( $key, $group = '', $force = false, &$found = null ) { + global $wp_object_cache; + return $wp_object_cache->get( $key, $group, $force, $found ); + } + function wp_cache_incr( $key, $offset = 1, $group = '' ) { + global $wp_object_cache; + return $wp_object_cache->incr( $key, $offset, $group ); + } + function wp_cache_replace( $key, $data, $group = '', $expire = 0 ) { + global $wp_object_cache; + return $wp_object_cache->replace( $key, $data, $group, (int) $expire ); + } + function wp_cache_set( $key, $data, $group = '', $expire = 0 ) { + global $wp_object_cache; + return $wp_object_cache->set( $key, $data, $group, (int) $expire ); + } + function wp_cache_switch_to_blog( $blog_id ) {} + class WP_Object_Cache_With_Cache_Calls { + public $cache = array(); + public $cache_hits = 0; + public $cache_misses = 0; + public $cache_calls = array(); + private $global_groups = array(); + private function cache_key( $key, $group ) { + return $group . ':' . $key; + } + private function track( $command ) { + $this->cache_calls[ $command ] = isset( $this->cache_calls[ $command ] ) ? $this->cache_calls[ $command ] + 1 : 1; + } + public function add( $key, $data, $group = 'default', $expire = 0 ) { + if ( isset( $this->cache[ $this->cache_key( $key, $group ) ] ) ) { + return false; + } + return $this->set( $key, $data, $group, $expire ); + } + public function set( $key, $data, $group = 'default', $expire = 0 ) { + $this->cache[ $this->cache_key( $key, $group ) ] = $data; + $this->track( 'set' ); + return true; + } + public function get( $key, $group = 'default', $force = false, &$found = null ) { + $this->track( 'get' ); + if ( isset( $this->cache[ $this->cache_key( $key, $group ) ] ) ) { + $found = true; + $this->cache_hits++; + return $this->cache[ $this->cache_key( $key, $group ) ]; + } + $found = false; + $this->cache_misses++; + return false; + } + public function delete( $key, $group = 'default' ) { + $cache_key = $this->cache_key( $key, $group ); + if ( ! isset( $this->cache[ $cache_key ] ) ) { + return false; + } + unset( $this->cache[ $cache_key ] ); + $this->track( 'del' ); + return true; + } + public function flush() { + $this->cache = array(); + return true; + } + public function decr( $key, $offset = 1, $group = 'default' ) { + $cache_key = $this->cache_key( $key, $group ); + if ( ! isset( $this->cache[ $cache_key ] ) ) { + return false; + } + $this->cache[ $cache_key ] = max( 0, (int) $this->cache[ $cache_key ] - $offset ); + $this->track( 'decrby' ); + return $this->cache[ $cache_key ]; + } + public function incr( $key, $offset = 1, $group = 'default' ) { + $cache_key = $this->cache_key( $key, $group ); + if ( ! isset( $this->cache[ $cache_key ] ) ) { + return false; + } + $this->cache[ $cache_key ] = (int) $this->cache[ $cache_key ] + $offset; + $this->track( 'incrby' ); + return $this->cache[ $cache_key ]; + } + public function replace( $key, $data, $group = 'default', $expire = 0 ) { + if ( ! isset( $this->cache[ $this->cache_key( $key, $group ) ] ) ) { + return false; + } + return $this->set( $key, $data, $group, $expire ); + } + public function add_global_groups( $groups ) { + foreach ( (array) $groups as $group ) { + $this->global_groups[ $group ] = true; + } + } + } + """ + + When I run `wp profile eval 'wp_cache_set( "foo", "bar" ); wp_cache_get( "foo" ); wp_cache_get( "foo" );' --fields=cache_hits,cache_misses,cache_calls` + Then STDOUT should be a table containing rows: + | cache_hits | cache_misses | cache_calls | + | 2 | 0 | 3 | diff --git a/src/Command.php b/src/Command.php index 1f7d4463..eb11a18f 100644 --- a/src/Command.php +++ b/src/Command.php @@ -164,6 +164,7 @@ public function stage( $args, $assoc_args ) { 'cache_ratio', 'cache_hits', 'cache_misses', + 'cache_calls', 'request_time', 'request_count', ); @@ -178,6 +179,7 @@ public function stage( $args, $assoc_args ) { 'cache_ratio', 'cache_hits', 'cache_misses', + 'cache_calls', 'hook_time', 'hook_count', 'request_time', @@ -300,6 +302,7 @@ public function hook( $args, $assoc_args ) { 'cache_ratio', 'cache_hits', 'cache_misses', + 'cache_calls', 'request_time', 'request_count', ); @@ -522,6 +525,7 @@ private static function profile_eval_ish( $assoc_args, $profile_callback, $order 'cache_ratio', 'cache_hits', 'cache_misses', + 'cache_calls', 'request_time', 'request_count', ) diff --git a/src/Logger.php b/src/Logger.php index ff2882bb..2c5a4c35 100644 --- a/src/Logger.php +++ b/src/Logger.php @@ -29,6 +29,8 @@ class Logger { /** @var string|null */ public $cache_ratio = null; /** @var int */ + public $cache_calls = 0; + /** @var int */ public $hook_count = 0; /** @var float */ public $hook_time = 0; @@ -44,6 +46,8 @@ class Logger { private $cache_hit_offset = null; /** @var int|null */ private $cache_miss_offset = null; + /** @var int|null */ + private $cache_calls_offset = null; /** @var float|null */ private $hook_start_time = null; /** @var int */ @@ -119,6 +123,10 @@ public function start() { } $this->cache_hit_offset = ! empty( $wp_object_cache->cache_hits ) ? $wp_object_cache->cache_hits : 0; $this->cache_miss_offset = ! empty( $wp_object_cache->cache_misses ) ? $wp_object_cache->cache_misses : 0; + $total = self::get_object_cache_calls( $wp_object_cache ); + if ( ! is_null( $total ) ) { + $this->cache_calls_offset = $total; + } } /** @@ -164,11 +172,19 @@ public function stop() { } } - $this->start_time = null; - $this->query_offset = null; - $this->cache_hit_offset = null; - $this->cache_miss_offset = null; - $key = array_search( $this, self::$active_loggers, true ); + if ( ! is_null( $this->cache_calls_offset ) && isset( $wp_object_cache ) ) { + $total = self::get_object_cache_calls( $wp_object_cache ); + if ( ! is_null( $total ) ) { + $this->cache_calls = $total - $this->cache_calls_offset; + } + } + + $this->start_time = null; + $this->query_offset = null; + $this->cache_hit_offset = null; + $this->cache_miss_offset = null; + $this->cache_calls_offset = null; + $key = array_search( $this, self::$active_loggers, true ); if ( false !== $key ) { unset( self::$active_loggers[ $key ] ); @@ -227,4 +243,34 @@ public function stop_request_timer() { } $this->request_start_time = null; } + + /** + * Get the total number of object cache backend calls from the active cache. + * + * Supports multiple implementations: + * - WP Redis: $wp_object_cache->redis_calls (array of command => count) + * - Redis Object Cache: $wp_object_cache->cache_calls (array of command => count) + * - Object Cache Pro: $wp_object_cache->metrics()->storeReads + storeWrites + * + * @param object|null $wp_object_cache + * @return int|null Total call count, or null if not supported. + */ + public static function get_object_cache_calls( $wp_object_cache ) { + if ( ! is_object( $wp_object_cache ) ) { + return null; + } + if ( isset( $wp_object_cache->redis_calls ) && is_array( $wp_object_cache->redis_calls ) ) { + return (int) array_sum( $wp_object_cache->redis_calls ); + } + if ( isset( $wp_object_cache->cache_calls ) && is_array( $wp_object_cache->cache_calls ) ) { + return (int) array_sum( $wp_object_cache->cache_calls ); + } + if ( method_exists( $wp_object_cache, 'metrics' ) ) { + $metrics = $wp_object_cache->metrics(); + if ( is_object( $metrics ) && isset( $metrics->storeReads ) && isset( $metrics->storeWrites ) ) { // phpcs:ignore WordPress.NamingConventions.ValidVariableName.UsedPropertyNotSnakeCase + return (int) $metrics->storeReads + (int) $metrics->storeWrites; // phpcs:ignore WordPress.NamingConventions.ValidVariableName.UsedPropertyNotSnakeCase + } + } + return null; + } } diff --git a/src/Profiler.php b/src/Profiler.php index 37ae2ef8..0ec74d4f 100644 --- a/src/Profiler.php +++ b/src/Profiler.php @@ -63,6 +63,8 @@ class Profiler { private $tick_cache_hit_offset = null; /** @var int|null */ private $tick_cache_miss_offset = null; + /** @var int|null */ + private $tick_cache_calls_offset = null; /** @var bool */ private $is_admin_request = false; @@ -403,6 +405,7 @@ public function handle_function_tick() { 'cache_hits' => 0, 'cache_misses' => 0, 'cache_ratio' => null, + 'cache_calls' => 0, ); } @@ -439,6 +442,15 @@ public function handle_function_tick() { $ratio = ( $logger_data['cache_hits'] / $total ) * 100; $logger_data['cache_ratio'] = round( $ratio, 2 ) . '%'; } + + if ( ! is_null( $this->tick_cache_calls_offset ) ) { + $total = Logger::get_object_cache_calls( $wp_object_cache ); + if ( ! is_null( $total ) ) { + $current_cache_calls = isset( $logger_data['cache_calls'] ) && is_numeric( $logger_data['cache_calls'] ) ? $logger_data['cache_calls'] : 0; + $delta = $total - $this->tick_cache_calls_offset; + $logger_data['cache_calls'] = $delta + (int) $current_cache_calls; + } + } } $this->loggers[ $callback_hash ] = $logger_data; } @@ -479,12 +491,13 @@ public function handle_function_tick() { } } - $this->tick_callback = $callback; - $this->tick_location = $location; - $this->tick_start_time = microtime( true ); - $this->tick_query_offset = ! empty( $wpdb->queries ) ? count( $wpdb->queries ) : 0; - $this->tick_cache_hit_offset = ! empty( $wp_object_cache->cache_hits ) ? $wp_object_cache->cache_hits : 0; - $this->tick_cache_miss_offset = ! empty( $wp_object_cache->cache_misses ) ? $wp_object_cache->cache_misses : 0; + $this->tick_callback = $callback; + $this->tick_location = $location; + $this->tick_start_time = microtime( true ); + $this->tick_query_offset = ! empty( $wpdb->queries ) ? count( $wpdb->queries ) : 0; + $this->tick_cache_hit_offset = ! empty( $wp_object_cache->cache_hits ) ? $wp_object_cache->cache_hits : 0; + $this->tick_cache_miss_offset = ! empty( $wp_object_cache->cache_misses ) ? $wp_object_cache->cache_misses : 0; + $this->tick_cache_calls_offset = Logger::get_object_cache_calls( $wp_object_cache ); } /**