Implement Server-Timing API foundation as well as basic load time metrics

[felixarntz]

Summary

Fixes #551

Relevant technical choices

• Add Perflab_Server_Timing class to control the Server-Timing header.
• Add Perflab_Server_Timing_Metric class to represent a single metric, so that measuring callbacks can set a value on it without having access to the full API.
• Add perflab_server_timing_register_metric() function which can be used to register a Server-Timing metric. This function can be called at any point as long as it is before or during the perflab_server_timing_send_header action.
• Add perflab_server_timing_use_output_buffer() function and filter of the same name. By default output buffering is disabled, but it can be enabled to record additional measurements that occur while rendering the template.
• Add perflab_server_timing() function which provides access to the API instance, e.g. to use it for lower-level functions, which are typically not necessary due to the wrapper functions mentioned above.
• Add two functions to register default metrics. These are:
  • wp-before-template measures how long WordPress execution time takes prior to serving the HTML template
  • wp-before-template-db-queries measures total execution of database queries prior to serving the HTML template (only if SAVEQUERIES constant is enabled)
  • wp-template measures the overall HTML template execution (only if using an output buffer)
  • wp-template-db-queries measures total execution of database queries during HTML template execution (only if using an output buffer and if SAVEQUERIES constant is enabled)
  • wp-load-alloptions-query measures execution of the alloptions database query (only if the Performance Lab object-cache.php drop in is placed, see below)
• Implement perflab_wrap_server_timing() utility function which can be used to measure execution of any callback (e.g. for an action or filter).
• Include an object-cache.php drop-in, which is used to initialize the Server-Timing API early, in order to measure events that would not be possible from within a plugin.
  • This file is placed automatically if possible, in a way that's entirely non-disruptive.
  • If there is already a (real) object-cache.php file, it will be renamed to object-cache-plst-orig.php and then required from the new object-cache.php file, so nothing will change in the behavior of any persistent object cache present.
  • Placing the file will only be attempted in WP Admin.
  • If placing the file fails for any reason, it will only be attempted once per hour maximum (and only if logged into WP Admin, see above).
  • If a site still does not want to use the drop-in, it can set a constant: define( 'PERFLAB_DISABLE_OBJECT_CACHE_DROPIN', true );
  • The PR includes one more specific metric which is facilitated by having this drop-in, which is to measure the autoloaded options query. This query is added in support of Module Proposal: Optimized Autoloaded Options #526 (also since it would not be possible to add this query from within a plugin).

Testing

Server-Timing header information can be inspected in JS via:

performance.getEntries()[0].serverTiming

Use the following code snippet to test with output buffering enabled:

add_filter( 'perflab_server_timing_use_output_buffer', '__return_true' );

You can test the perflab_wrap_server_timing() function e.g. by adding a code snippet like the following:

add_action(
	'init',
	perflab_wrap_server_timing(
		function() {
			// Wait for 1 second.
			usleep( 1000000 );
		},
		'init-test-callback',
		'exist'
	)
);

Some other example use cases to test with can be found in this Gist: https://gist.github.com/felixarntz/43fb19e6491a1bc65a7e930dace17c47

Checklist

• PR has either [Focus] or Infrastructure label.
• PR has a [Type] label.
• PR has a milestone or the no milestone label.

[felixarntz]

In 51c4222, I have revamped the API to simplify its usage quite a bit. I've updated the PR description accordingly and created a new Gist with updated examples (https://gist.github.com/felixarntz/43fb19e6491a1bc65a7e930dace17c47).

For reference, I've kept the original example Gist (https://gist.github.com/felixarntz/c343a33242b6527ad3f446c8f7f4fec2). By comparing the two, you will see that the new API usage is much simplified. Most importantly the new approach has the following benefits:

• You aren't forced to hook into a specific action to register a Server-Timing metric.
• This encourages registration of metrics as close as possible to when the relevant logic runs rather than registering all metrics early on - essentially lazy initialization, to avoid registering metrics which may not be used during a page load.
• Through that it also allows the core infrastructure to not run a measuring callback if the current user lacks the necessary capability, saving resources (even though these aren't expensive to run, it's a nice-to-have).
• There is now an action right before the Server-Timing header is sent, so that you can rely on it or check for it to ensure you register metrics in time for that.
• The new measure_before() and measure_after() methods simplify measurement as you no longer need to manually store the reference value and calculate the diff.

[felixarntz]

@johnbillion @tillkruss @jjgrainger I'd like to get your feedback on this. I'm still keeping it as a draft PR until I have added test coverage, but at this point I think the implementation would be suitable for the Performance Lab plugin.

Some high-level considerations:

• Currently, using an output buffer is off by default. Could we consider enabling it by default (since we're in plugin territory, and therefore it's certainly feasible here)?
• Some metrics that would be valuable to measure cannot be captured from within a plugin because they are running too early (e.g. the alloptions query). I wonder if we can find ways to address that. Given this is a beta testing plugin, could we potentially place a drop-in file to register some early metrics?

For the latter, it would be a hack, but I'm thinking potentially we could place e.g. object-cache.php (without that being actually an object cache implementation). If the site is not using an object cache, that'll still work as before, and if it does, we could easily detect that it has object-cache.php already and in that case rename that file, then require_once it within our own object-cache.php file. Too crazy, or potentially okay? :)

[tillkruss]

The advanced-cache.php might be more suited for that, since it loads a lot earlier than the object-cache.php.

[tillkruss]

Can you give me a gist how an Object Cache implementation would supply the Server Timing API with let's say a single metric "total time waited for Datastore", similar to "total time waited for SQL"?

[felixarntz]

@tillkruss For the actual measurement, you would probably need to add support for that in the object-cache.php implementation itself, e.g. use microtime( true ) or something like that around every single cache lookup, then store that somewhere. Maybe you could rely on a constant similar to SAVEQUERIES to enable that?

You could then register the data like this:

add_action(
	'perflab_server_timing_send_header',
	function() {
		perflab_server_timing_register_metric(
			'object-cache-lookups',
			array(
				'measure_callback' => function( $metric ) {
					// The function here should return the time in milliseconds.
					$total_cache_time = demo_function_that_returns_total_cache_time();
					$metric->set_value( $total_cache_time );
				},
				'access_cap'       => 'exist',
			)
		);
	}
);

The hook is called as late as possible (either before serving the HTML template or on shutdown, depending on whether the feature is configured with an output buffer or not for the site), so all lookups should be calculated by then at least if an output buffer is used. For sites without an output buffer (see perflab_server_timing_use_output_buffer()), if there is still value in including this, you could call it something like before-template-object-cache-lookups, kind of similar how it is in this PR for the DB queries (since without an output buffer you can only account for the lookups that happen prior to serving the template).

[tillkruss]

@felixarntz: This is great 👍

[felixarntz]

@tillkruss @johnbillion In 096bb87, I've added logic to place an object-cache.php drop-in to initialize the Server-Timing API early, as mentioned in #553 (comment). While this is a bit of a hack, I think it is totally reasonable. Unless I'm missing something, the implementation should not be disruptive in any way. Please take a look. Also review the PR description, which I keep updating based on the latest implementation.

I will work on tests within the next 2 weeks and get this ready for a full code review.

[felixarntz]

@adamsilverstein @eugene-manuilov Addressed all your feedback either with new commits or comment replies.

[adamsilverstein]

Looks good to me!

[mukeshpanchal27]

Thanks, @felixarntz for all your answers. looks good to me.

[eugene-manuilov]

LGTM. Great work, @felixarntz!

[westonruter]

I'm curious why this method doesn't rather return the $this->registered_metrics[ $metric_slug ] value here? Why is measure_callback needed?

Then instead of:

performance/server-timing/load.php

Lines 105 to 115 in 0e10d5a

	if ( ! perflab_server_timing()->has_registered_metric( $metric_slug ) ) {
	perflab_server_timing_register_metric(
	$metric_slug,
	array(
	'measure_callback' => static function ( $metric ) use ( &$server_timing_metric ) {
	$server_timing_metric = $metric;
	},
	'access_cap' => $access_cap,
	)
	);
	}

It could be simplified to:

		if ( ! perflab_server_timing()->has_registered_metric( $metric_slug ) ) {
			$server_timing_metric = perflab_server_timing_register_metric(
				$metric_slug,
				array(
					'access_cap' => $access_cap,
				)
			);
		}

[felixarntz]

@westonruter I think that scenario is an edge-case, which is only needed because of the way this function is a wrapper to an action callback.

Overall, I consider that a discouraged pattern. Passing a measurement callback allows for that callback to only be called on other conditions (e.g. depending on the "access cap"). If the metric was returned, it would encourage implementing the measurement logic there, which then would be decoupled from those conditions for whether the metric should be measured in the first place. Alternatively, we could return the metric only if the conditions are satisfied, but that would be a strange pattern IMO, as not returning it wouldn't mean that the metric wasn't registered correctly - whereas the return value of a "register" function would be expected to only return null or false if the registration itself failed.