Implement logic to measure specific hook execution time with Server-Timing controlled by a WP Admin screen #784

felixarntz · 2023-07-18T00:22:29Z

Summary

This PR implements a WP Admin screen Tools > Server-Timing which allows providing action and filter names. Any hook names provided will be measured and exposed in the Server-Timing header in the frontend.

While the Server-Timing API from #553 has been a powerful foundation, it can sometimes be cumbersome to measure specific hooks performance, since it always requires writing custom code. Gists like this one can be used for that, but even with such thing it may be easier to just add the action or filter to a UI instead of having to modify a plugin's code. This PR makes it really easy and gives site owners control about specific hooks to measure.

Admin screen to manage hooks to measure with Server-Timing

The new admin screen with example input

Relevant technical choices

Adds a new WordPress option/setting to store Server-Timing configuration.
Adds a new WP Admin screen with textareas to provide action and filter names.
Uses the data from the new option/setting to measure the duration of those hooks, using similar logic as previously implemented in the aforementioned Gist.

Testing

Go to Tools > Server-Timing.
Add some hook names (actions and/or filters), one per line. For example those from the screenshot above.
Save and verify the hook names are still shown in the textareas, in a sanitized way.
- For example, try to add spaces or (other) invalid characters and check that they're stripped after submitting.
Load the frontend.
Type console.table( performance.getEntries()[0].serverTiming ) in the browser's dev tools console.
Verify that you see measurements for the actions/filters you provided, via wp-action-{$action} / wp-filter-{$filter} metrics.
- Note that metrics will only show up if the respective action/filter was actually run during the request.
- If you provide hook names that are only run after the template is being parsed (e.g. wp_enqueue_scripts action), they won't show up by default. You'll need to activate output buffering (e.g. via this Gist plugin) so that those can be exposed as well.

Checklist

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

…iming controlled by a WP Admin screen.

spacedmonkey · 2023-07-19T09:51:22Z

admin/server-timing.php

+		add_action( "load-{$hook_suffix}", 'perflab_load_server_timing_page' );
+	}
+
+	return $hook_suffix;


What are you returning this for? This is hooked into an action right?

Right, this would only be useful for test coverage, which I'm planning to add.

spacedmonkey · 2023-07-19T11:35:10Z

server-timing/load.php

+function perflab_sanitize_server_timing_setting( $value ) {
+	if ( ! is_array( $value ) ) {
+		return array();
+	}
+
+	// Ensure that every element is an indexed array of hook names.
+	return array_filter(
+		array_map(
+			static function( $hooks ) {
+				if ( ! is_array( $hooks ) ) {
+					$hooks = explode( "\n", $hooks );
+				}
+				return array_filter( array_map( 'sanitize_key', $hooks ) );
+			},
+			$value
+		)
+	);
+}


This could do with a unit test IMO.

Yeah, I haven't added unit tests yet, but definitely planning to do so.

server-timing/load.php

server-timing/defaults.php

swissspidy · 2023-07-24T16:06:23Z

Just from looking at the screenshot alone it is not clear what exactly would be measured. Is it the time since the last hook (i.e. do_action(wp_loaded) *start* ... *stop* do_action(init), or the duration of all the functions hooked into it (i.e. *start* ... do_action( xyz ); *stop*). Looking at https://gist.github.com/felixarntz/63c05392dbf7d51cc7f8f4a424b1ff39, it seems to be the latter, but would be nice to clarify that in the UI with a clearer description.

mukeshpanchal27

Thanks @felixarntz for the PR, If anyone add duplicate value in Actions or Filters then it shows error.

For ex.

init
wp_loaded
init

…ntation for better understanding.

felixarntz · 2023-08-03T17:19:36Z

Thanks @swissspidy @mukeshpanchal27 for the feedback.

In 6b5d12a, I've pushed a clarification for how the hooks are measured.
In 61f5ccc, I've pushed a fix to ensure no duplicate hooks can be provided.

I'll work on some test coverage now, mostly relevant for the WP Admin UI.

felixarntz · 2023-08-03T18:16:53Z

In 585911d and 6db1e85 I've added test coverage, so this PR is now ready for a full review.

… stripping whitespace.

westonruter · 2023-08-07T19:44:11Z

server-timing/load.php

+	 * Any duplicates across a group of hooks are removed.
+	 */
+	return array_filter(
+		array_map(


Should this be checking whether the keys are those which are allowed, i.e. benchmarking_actions and benchmarking_filters?

Good idea, updated in 7f99021

westonruter · 2023-08-07T19:48:04Z

server-timing/load.php

+								},
+								$hooks
+							)
+						)
+					)
+				);
+			},
+			$value
+		)


There is a lot of nesting happening here. Not a problem, but just makes it a bit hard on the eyes. Not a blocker.

Reduced the nesting a bit in 7f99021

westonruter · 2023-08-07T20:38:48Z

For some reason when I add a filter to get Server-Timing for, e.g. the_content, I'm getting a PHP notice:

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 5865

I don't get it for when I add actions, however. 😕

felixarntz · 2023-08-07T22:04:27Z

@westonruter That's because the the_content hook runs after the header is output. So hooks like that can only be used if output buffering is enabled. Maybe we open a separate PR to add a checkbox to allow controlling that as well? That would make that bit easier as well, without the need for another one-liner plugin.

westonruter · 2023-08-07T22:07:51Z

@westonruter That's because the the_content hook runs after the header is output. So hooks like that can only be used if output buffering is enabled. Maybe we open a separate PR to add a checkbox to allow controlling that as well? That would make that bit easier as well, without the need for another one-liner plugin.

Oh, of course. Same as mentioned in #784 (comment).

What do you think about the presence of any Server-Timing hooks to automatically cause output buffering to be enabled automatically? That would prevent others from getting tripped up the same way I did.

felixarntz · 2023-08-07T22:49:34Z

@westonruter I think it would be better to have an explicit setting for it. To clarify the limitation when output buffering is not enabled, I have added a message for it in fd41db1 (see also the updated screenshot in the PR description).

Once we add a setting control for it, we can consider toggling that with JS based on the checkbox.

swissspidy · 2023-08-08T08:50:15Z

admin/server-timing.php

+		static function() {
+			?>
+			<p>
+				<?php esc_html_e( 'In this section, you can provide hook names to include measurements for them in the Server-Timing header.', 'performance-lab' ); ?>


Since the Server-Timing header is not something that should be translated, I'd recommend using sprintf with a placeholder here (+ a translator comment of course).

swissspidy · 2023-08-08T08:50:39Z

admin/server-timing.php

+					<br>
+					<?php
+					echo wp_kses(
+						__( 'Since the Server-Timing header is sent before the template is loaded, only hooks before the <code>template_include</code> filter can be measured.', 'performance-lab' ),


I'd use sprintf with a placeholder for template_include so that it does not get translated

swissspidy

LGTM, just two i18n notes

mukeshpanchal27

Thanks @felixarntz for the updates.

I still reproduce #784 (review) error. Could you please take a look. Thanks.

felixarntz · 2023-08-08T17:53:27Z

@mukeshpanchal27

I still reproduce #784 (review) error. Could you please take a look. Thanks.

Maybe it was because you had those settings saved from before? The actual behavior from having duplicate hooks was not changed, but I added sanitization to strip duplicate values. So can you please try to go to the Tools screen again and re-save? It should result in the duplicates being stripped.

westonruter · 2023-08-08T18:12:21Z

Once we add a setting control for it, we can consider toggling that with JS based on the checkbox.

I'd like to propose Output Buffering as a new module. This module would be to explore implementation of Core-43258/Core-58285 while also providing an easy way to implement the toggle. It will give us an area to explore use of output buffering to make Performance enhancements as well, such as applying LCP enhancements to arbitrary elements not rendered using the normal WordPress mechanisms (e.g. hard-coded images and page builders). cc @joemcgill @kt-12

mukeshpanchal27

Thanks @felixarntz, I test in fresh installation and it working for me.

westonruter · 2023-08-10T15:54:42Z

Maybe we open a separate PR to add a checkbox to allow controlling that as well? That would make that bit easier as well, without the need for another one-liner plugin.

I'll work on this.

westonruter · 2023-08-12T01:34:38Z

Maybe we open a separate PR to add a checkbox to allow controlling that as well? That would make that bit easier as well, without the need for another one-liner plugin.

I'll work on this.

See #801

Implement logic to measure specific hook execution time with Server-T…

a1fd89c

…iming controlled by a WP Admin screen.

felixarntz added [Type] Feature A new feature within an existing module Infrastructure Issues for the overall performance plugin infrastructure no milestone PRs that do not have a defined milestone for release labels Jul 18, 2023