Fix Server-Timing compatibility with other plugins that do output buffering

[westonruter]

Summary

When testing with WordPress core trunk (6.6-alpha), I noticed a _doing_it_wrong() notice:

PHP Notice: Function Perflab_Server_Timing::register_metric was called incorrectly. The method must be called before or during the perflab_server_timing_send_header action. Please see Debugging in WordPress for more information. in /var/www/html/wp-includes/functions.php on line 6078

In looking at Query Monitor, it identifies Optimization Detective in the stack trace:

With git bisect I discovered the issue started with r57920 for Core-42441. Nevertheless, in looking at that commit I see nothing which would seem to be related to this. There seems to be some race condition happening due to the fact that the Server-Timing component is starting output buffering at PHP_INT_MAX while Optimization Detective is doing the same. In order for Optimization Detective to register its Server-Timing metric and for Server-Timing to be able to send the header successfully, the Server-Timing component (counter intuitively) needs to start its output buffer first so that it wraps the output buffer of Optimization Detective and and other plugins which may be starting the output buffer at PHP_INT_MAX. The callback for the first output buffer is executed last.

So this PR changes the priority for the Server-Timing output buffer to start now at the minimum template_redirect action priority so that its output buffer callback is invoked last, allowing any other plugins that do output buffering and add server-timing metrics (e.g. Optimization Detective) to be able to do so in their own output buffer callbacks which run before the the Server-Timing callback is invoked.

Note: To test this you need to (1) enable output buffering in the Server-Timing screen, and (2) access the site while logged-out of the admin or add a add_filter( 'od_can_optimize_response', '__return_true' ) filter since by default Optimization Detective does not run for admins.

[github-actions]

The following accounts have interacted with this PR and/or linked issues. I will continue to update these lists as activity occurs. You can also manually ask me to refresh this list by adding the props-bot label.

If you're merging code through a pull request on GitHub, copy and paste the following into the bottom of the merge commit message.

Co-authored-by: westonruter <westonruter@git.wordpress.org>
Co-authored-by: joemcgill <joemcgill@git.wordpress.org>

To understand the WordPress project's expectations around crediting contributors, please review the Contributor Attribution page in the Core Handbook.

[joemcgill]

I'm curious why we need to change the hook that this is attached to depending on if OB is being used? I also wonder why we just don't move the hook regardless of the OB status if there is a benefit, so that the timing will be consistent.

The other consideration here is that the wp-before-template metrics are calculated from the tempate_include hook as well (reference) and I think we want these to happen on the same hook in order to accurately report the wp-total value.

[westonruter]

I'm curious why we need to change the hook that this is attached to depending on if OB is being used? I also wonder why we just don't move the hook regardless of the OB status if there is a benefit, so that the timing will be consistent.

When output buffering is not enabled, the Server-Timing header should be sent as late as possible to give a chance for plugins to register their metrics. In this case, template_include filter with max priority is appropriate.

On the other hand, when output buffer is enabled then we still need to send the Server-Timing header at the very end, but the way we do so is different: we do so by starting the output buffer earlier so that it wraps the entire page resulting in its callback running at the very end.

If we always sent the Server-Timing header at template_redirect (even when not doing output buffering) then this would potentially exclude plugins from being able to register their metrics since they may occur between template_redirect and template_include.

The other consideration here is that the wp-before-template metrics are calculated from the tempate_include hook as well (reference) and I think we want these to happen on the same hook in order to accurately report the wp-total value.

I'm not sure the change impacts this wp-before-template metrics calculation since the change here is only changing when output buffering starts, not when calculation happens.

[joemcgill]

Ah, right, the metric still gets recorded at the same time, it's just when we start the buffer that changes. Makes sense.

The interesting side effect here is that this allows us to add Server Timing headers to things like robots.txt, feeds, etc. which weren't previously possible.

[joemcgill]

Ah, right, the metric still gets recorded at the same time, it's just when we start the buffer that changes. Makes sense.

The interesting side effect here is that this allows us to add Server Timing headers to things like robots.txt, feeds, etc. which weren't previously possible.