Performance Lab: `PHP Warning: "Undefined array key 1"`

[emrikol]

Bug Description

Loading up my home page of my site, I get two PHP warnings from performance-lab:

Warning: Undefined array key 1 in plugins/performance-lab/includes/server-timing/defaults.php on line 57 [{closure:{closure:{closure:perflab_register_default_server_timing_before_template_metrics():28}:47}:56}(), plugins/performance-lab/includes/server-timing/defaults.php:54 array_reduce(), plugins/performance-lab/includes/server-timing/class-perflab-server-timing.php:121 {closure:{closure:perflab_register_default_server_timing_before_template_metrics():28}:47}(), plugins/performance-lab/includes/server-timing/load.php:87 Perflab_Server_Timing->register_metric(), plugins/performance-lab/includes/server-timing/defaults.php:44 perflab_server_timing_register_metric(), plugins/performance-lab/includes/server-timing/defaults.php:77 {closure:perflab_register_default_server_timing_before_template_metrics():28}(), wp-includes/class-wp-hook.php:324 {closure:perflab_register_default_server_timing_before_template_metrics():75}(), wp-includes/plugin.php:205 WP_Hook->apply_filters(), wp-includes/template-loader.php:104 apply_filters('template_include'), wp-blog-header.php:19 require_once('wp-includes/template-loader.php'), index.php:17 require('wp-blog-header.php')]
Warning: Undefined array key 1 in plugins/performance-lab/includes/server-timing/defaults.php on line 170 [{closure:{closure:{closure:perflab_register_default_server_timing_template_metrics():151}:156}:169}(), plugins/performance-lab/includes/server-timing/defaults.php:167 array_reduce(), plugins/performance-lab/includes/server-timing/class-perflab-server-timing.php:121 {closure:{closure:perflab_register_default_server_timing_template_metrics():151}:156}(), plugins/performance-lab/includes/server-timing/load.php:87 Perflab_Server_Timing->register_metric(), plugins/performance-lab/includes/server-timing/defaults.php:153 perflab_server_timing_register_metric(), wp-includes/class-wp-hook.php:324 {closure:perflab_register_default_server_timing_template_metrics():151}(), wp-includes/class-wp-hook.php:348 WP_Hook->apply_filters(), wp-includes/plugin.php:517 WP_Hook->do_action(), plugins/performance-lab/includes/server-timing/class-perflab-server-timing.php:160 do_action('perflab_server_timing_send_header'), plugins/performance-lab/includes/server-timing/class-perflab-server-timing.php:274 Perflab_Server_Timing->send_header(), Perflab_Server_Timing->{closure:Perflab_Server_Timing::start_output_buffer():271}(), wp-includes/functions.php:5472 ob_end_flush(), wp-includes/class-wp-hook.php:324 wp_ob_end_flush_all(), wp-includes/class-wp-hook.php:348 WP_Hook->apply_filters(), wp-includes/plugin.php:517 WP_Hook->do_action(), wp-includes/load.php:1307 do_action('shutdown'), shutdown_action_hook()]

Steps to reproduce

I'm not sure how to reproduce if you're not already experiencing this issue. I think it might be related to using HyperDB?

Dumping $query from Line 57 gives me:

array (
  'elapsed' => 0.00029397010803222656,
  'host' => '[REMOVED]',
  'microtime' => '0.27954500 1757014437',
  'debug' => 'require, require_once, require_once, require_once, do_action, WP_Hook->do_action, WP_Hook->apply_filters, wpcom_vip_qm_require, apply_filters, WP_Hook->apply_filters, wpcom_vip_qm_enable, current_user_can, wp_get_current_user, _wp_get_current_user, wp_set_current_user, do_action, WP_Hook->do_action, WP_Hook->apply_filters, {closure:/var/www/wp-content/mu-plugins/000-vip-init.php:161}, get_user_by, WP_User->get_data_by, wpdb->get_row, hyperdb->query',
  'query' => 'SELECT * FROM wp_users WHERE user_login = \'[REMOVED]\' LIMIT 1',
  'dbhname' => 'global__r',
  'dataset' => 'global',
  'callback_result' => NULL,
  'connection' =>
  array (
    'dbhname' => 'global__r',
    'host' => '[REMOVED]',
    'port' => '[REMOVED]',
    'user' => '[REMOVED]',
    'name' => '[REMOVED]',
    'server_state' => 'up',
    'elapsed' => 0.0012891292572021484,
    'success' => true,
    'queries' => 1,
    'lag' => 0,
  ),
)

Additional Context

• PHP Version: 8.4.12
• WordPress Version: 6.9-alpha-60637
• OS: MacOS?
• Browser: Latest Chrome and Firefox?
• Plugin Version: 4.0.0
• Device: MacBook Pro?

I threw this in for a quick fix, if I'm understanding correctly what the code is doing:

diff --git a/plugins/performance-lab/includes/server-timing/defaults.php b/plugins/performance-lab/includes/server-timing/defaults.php
index db92f30..5ac1001 100644
--- a/plugins/performance-lab/includes/server-timing/defaults.php
+++ b/plugins/performance-lab/includes/server-timing/defaults.php
@@ -54,7 +54,13 @@ function perflab_register_default_server_timing_before_template_metrics(): void
                                                $GLOBALS['perflab_query_time_before_template'] = array_reduce(
                                                        $GLOBALS['wpdb']->queries,
                                                        static function ( $acc, $query ) {
-                                                               return $acc + $query[1];
+                                                               $query_time = 0.0;
+                                                               if ( isset( $query[1] ) && is_float( $query[1] ) ) {
+                                                                       $query_time = $query[1];
+                                                               } elseif ( isset( $query['elapsed'] ) && is_float( $query['elapsed'] ) ) {
+                                                                       $query_time = $query['elapsed'];
+                                                               }
+                                                               return $acc + $query_time;
                                                        },
                                                        0.0
                                                );
@@ -167,7 +173,13 @@ function perflab_register_default_server_timing_template_metrics(): void {
                                                        $total_query_time = array_reduce(
                                                                $GLOBALS['wpdb']->queries,
                                                                static function ( $acc, $query ) {
-                                                                       return $acc + $query[1];
+                                                                       $query_time = 0.0;
+                                                                       if ( isset( $query[1] ) && is_float( $query[1] ) ) {
+                                                                               $query_time = $query[1];
+                                                                       } elseif ( isset( $query['elapsed'] ) && is_float( $query['elapsed'] ) ) {
+                                                                               $query_time = $query['elapsed'];
+                                                                       }
+                                                                       return $acc + $query_time;
                                                                },
                                                                0.0
                                                        );

[westonruter]

@emrikol Thanks for reporting this.

Here's how $wpdb->queries is populated in core:

$this->queries[] = array(
	$query,
	$query_time,
	$query_callstack,
	$query_start,
	$query_data,
);

So the second array arg is supposed to be the "Total time spent on the query, in seconds."

But the dumped query info from HyperDB shows that the array format is very different. Instead of being an indexed array, it is an associative array. Here's how it is populated:

if ( is_callable( $this->save_query_callback ) ) {
	// phpcs:ignore WordPress.PHP.DevelopmentFunctions.error_log_debug_backtrace
	$saved_query = call_user_func_array( $this->save_query_callback, array( $query_for_log, $elapsed, $this->save_backtrace ? debug_backtrace( DEBUG_BACKTRACE_IGNORE_ARGS ) : null, $this ) );
	if ( null !== $saved_query ) {
		$this->queries[] = $saved_query;
	}
} else {
	$this->queries[] = array( $query_for_log, $elapsed, $this->get_caller() );
}

It seems that if $this->save_query_callback is not defined, that the $elapsed data at least corresponds to the $query_time being used in core, although HyperDB is missing the $query_start and $query_data items. It should be an array with the following items:

Param	Description
$query	The query's SQL.
$query_time	Total time spent on the query, in seconds.
$query_callstack	Comma-separated list of the calling functions.
$query_start	Unix timestamp of the time at the start of the query.
$query_data	Custom query data.

The $save_query_callback is documented to be a "Custom callback to save debug info in $this->queries". Is this being defined in your environment? If so, I think it should follow the same format as used in core as an indexed array, by using the 5th $query_data param. In fact, core even has a filter for this, which HyperDB doesn't seem to implement. But if it did, it would make the $save_query_callback unnecessary.

I don't think Performance Lab can reliably use the non-standard format, so probably what it would have to do is check to see if all arrays contained in $GLOBALS['wpdb']->queries contain the expected $query_time item as the second value in the array, and if not, to abort with a notice.

[westonruter]

@emrikol I have a fix prepared in #2159, with a build for testing: #2159 (comment) #2159 (comment).

[emrikol]

@emrikol I have a fix prepared in #2159, with a build for testing: #2159 (comment) #2159 (comment).

Sorry for the delay! I just installed this and a quick stroll around with Query Monitor is no longer showing the PHP warnings that I had been seeing. Thank you so much for the support!