Skip to content
146 changes: 143 additions & 3 deletions features/profile-eval.feature
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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:
"""
<?php
function wp_cache_init() {
global $wp_object_cache;
$wp_object_cache = new WP_Object_Cache_With_Cache_Calls();
}
function wp_cache_add( $key, $data, $group = '', $expire = 0 ) {
global $wp_object_cache;
return $wp_object_cache->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 |
4 changes: 4 additions & 0 deletions src/Command.php
Original file line number Diff line number Diff line change
Expand Up @@ -164,6 +164,7 @@ public function stage( $args, $assoc_args ) {
'cache_ratio',
'cache_hits',
'cache_misses',
'cache_calls',
'request_time',
'request_count',
);
Expand All @@ -178,6 +179,7 @@ public function stage( $args, $assoc_args ) {
'cache_ratio',
'cache_hits',
'cache_misses',
'cache_calls',
'hook_time',
'hook_count',
'request_time',
Expand Down Expand Up @@ -300,6 +302,7 @@ public function hook( $args, $assoc_args ) {
'cache_ratio',
'cache_hits',
'cache_misses',
'cache_calls',
'request_time',
'request_count',
);
Expand Down Expand Up @@ -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',
)
Expand Down
56 changes: 51 additions & 5 deletions src/Logger.php
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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 */
Expand Down Expand Up @@ -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;
}
}

/**
Expand Down Expand Up @@ -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 = max( 0, $total - $this->cache_calls_offset );
}
Comment thread
swissspidy marked this conversation as resolved.
}

$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 ] );
Expand Down Expand Up @@ -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;
}
}
25 changes: 19 additions & 6 deletions src/Profiler.php
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -403,6 +405,7 @@ public function handle_function_tick() {
'cache_hits' => 0,
'cache_misses' => 0,
'cache_ratio' => null,
'cache_calls' => 0,
);
}

Expand Down Expand Up @@ -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 = max( 0, $total - $this->tick_cache_calls_offset );
$logger_data['cache_calls'] = max( 0, $delta + (int) $current_cache_calls );
}
Comment thread
swissspidy marked this conversation as resolved.
}
}
$this->loggers[ $callback_hash ] = $logger_data;
}
Expand Down Expand Up @@ -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 );
}

/**
Expand Down
Loading