Add ad hoc calculation of elapsed time for selected hooks

[bobbingwide]

When attempting to analyse performance issues we don’t want to produce lots of trace records since this slows the system down. It would be nice to know, for selected hooks the total number of invocations and the total time spent in the hook.
This would help us to identify whether or not a hook which is invoked often takes up a large percentage of the total execution.
Note: There are some hooks, such as init, which can take ages because every man and his dog seems to want to make sure their routines are ready and poised for anything that could possibly be done.
There are other hook functions which innocently do lots of things thinking they’ll only be called once.

[bobbingwide]

Having recently developed a plugin that's all about performance improvement I'm now more interested in developing a solution that will enable easy reporting of elapsed time between hooks or for time spent while processing a a particular function.

oik-bwtrace already supports logging of the total elapsed time and time since the last trace record but it doesn't
provide easy to see figures showing how long it takes to respond to a particular action or elapsed time between one hook and the next.

Proposal

• Add new trace call to start a timer
• And another call to stop the timer
• Or another call to count iterations
• At shutdown produce a summary of elapsed time between hooks
• Support ad hoc specification of hooks to time
• Support specification of start and end hooks

eg

mu_plugins_loaded
plugins_loaded
init

[bobbingwide]

I've started adding a very basic implementation that records the start time of each hook if not already set
In shutdown processing this is reported in a new positional parameter output for the [hook] shortcode.
Early days yet.

[bobbingwide]

Changing the [hook] shortcode output didn't work well.
I changed the code to produce a separate report.
Here's a subset of the output

hook,total,elapsed
mu_plugin_loaded,0.005980,0.005980
muplugins_loaded,0.007149,0.001169
registered_taxonomy,0.008325,0.001176
registered_post_type,0.009342,0.001017
plugin_loaded,0.033495,0.024153
plugins_loaded,0.041493,0.007998
sanitize_comment_cookies,0.048730,0.007237
wp_roles_init,0.048878,0.000148
setup_theme,0.048880,0.000002

There's both too much information and not enough to make good use of it.
hooks such as mu_plugin_loaded, registered taxonomy and registered_post_type get called multiple times

[hook mu_plugin_loaded action 1 2 0]
[hook muplugins_loaded action 0 1 1]
[hook registered_taxonomy action 3 14 0]
[hook registered_post_type action 2 26 0]

But if no logic acts on an action hook then it's probably not important to know that the hook was invoked.
Perhaps the action hook list can be reduced by ignoring the hooks for which there are no implementing functions.

[bobbingwide]

Perhaps the action hook list can be reduced by ignoring the hooks for which there are no implementing functions.

This helped. Now, if there was a particular action hook of interest, but which doesn't have any attached functions this can easily be alleviated by using oik action options. Just add the required hooks into the Other hooks to trace field. The action will be traced, with any parameters passed and the start time will be recorded.

[bobbingwide]

Support ad hoc specification of hooks to time

There are two options for this.

1. Simple hook - timing points

For a simple timeline of actions we can use the "Action timings" report.

For any action which doesn't already have an implementation we can

• either force an implementation by adding a special hook that simply traces the fact that the function's been invoked for the hook.
• or just check if the hook's a timing point; it may not even be necessary to trace the fact that the hooks been called.

There would be an oik-actions checkbox for this type of hook
As with other fields it should support priorities.
The Action timings report will show the first invocation of the hook.

2. Timer hook

To find out the elapsed time for a particular hook, and the average time for each invocation,
we can add a hook that's run before any other hook and another hook that runs at the end.

• The start hook will record the current time
• The end hook will calculate the elapsed time
• The logic should support multiple invocations of the hook.
• It could potentially be extended to support a start hook and an end hook.
• There'll be a separate report produced at shutdown.

[bobbingwide]

In Rarst's Laps plugin there's a list of core hooks that Laps is interested in:

• plugins_loaded
• setup_theme
• init
• wp_loaded
• template_redirect
• admin_init
• _admin_menu
• admin_enqueue_scripts
• wp-head
• loop_start
• dynamic_sidebar_before and dynamic_sidebar_after
• admin_bar_menu
• wp_footer

These events could be the default events for timing points.

See src/Events/Core_Events.php

It also supports: Beaver Builder, Genesis, Hybrid Core, Theme Hook Alliance, WooCommerce and Yoast

Laps shows the elapsed time for each plugin to load. It hooks into plugin_loaded.
We could do the same!

[bobbingwide]

Having added the Plugin load times report I then attempted to reconcile the output with the trace records and the Action timings.

Here's an edited version of the plugin load times report.

C:\apache\htdocs\wordpress\wp-content\plugins\oik-bwtrace\includes\oik-actions.php(390:0) bw_trace_plugin_loaded_report(1) 94 18 2021-12-31T09:19:56+00:00 2.377035 0.256599 cf=shutdown 29187 90 0 6291456/6291456 256M F=1083 Plugin load times Plugin,Load time (msecs),0
REQUEST_TIME_FLOAT,0.000000,0.000000
WP_START_TIMESTAMP,0.020588,0.020588
wp-content/mu-plugins/_oik-bwtrace-mu.php,0.433750,0.454338
wp-content/mu-plugins/oik-unloader-mu.php,0.001455,0.455793
wp-content/plugins/allow-reinstalls/allow-reinstalls.php,0.004667,0.460460
...
wp-content/plugins/slog/slog.php,0.000883,0.479586
muplugins_loaded,0.000016,0.479602
wp-content/plugins/query-monitor/query-monitor.php,0.045588,0.525190
wp-content/plugins/wordpress-seo/wp-seo.php,0.220943,0.902138
...
wp-content/plugins/wp-top12/wp-top12.php,0.000620,0.902758
plugins_loaded,0.015970,0.918728

Here's the first part of Action timings

C:\apache\htdocs\wordpress\wp-content\plugins\oik-bwtrace\includes\oik-action-counts.php(312:0) bw_trace_action_timings(1) 105 18 2021-12-31T09:19:56+00:00 2.412086 0.000947 cf=shutdown 29215 93 0 6291456/6291456 256M F=1083 action timings <h3>Action timings</h3>
hook,total,elapsed,time
mu_plugin_loaded,0.454329,0.454329
oik_lib_loaded,-0.002092,0.452237
network_plugin_loaded,0.008214,0.460451
muplugins_loaded,0.019145,0.479596
registered_taxonomy,0.002472,0.482068
registered_post_type,0.002461,0.484529
plugin_loaded,0.040647,0.525176
plugins_loaded,0.383297,0.908473

Observations

1. The first mu_plugin_loaded action that was timed occurred after oik_lib_loaded.
2. This needs to be catered for.
3. muplugins_loaded is run after network activated plugins have been loaded.
4. In a Multi site install the network activated plugins will appear before the muplugins_loaded ( allow_reinstalls to slog )
5. Some things can happen between the last plugin_loaded and the timing of plugins_loaded
6. When Jetpack is activated it hooks into plugins_loaded before any other plugin's hook.
7. The timing for trace records and the action timing report didn't match.

6. Jetpack hook into plugins_loaded

When Jetpack is activated it hooks into plugins_loaded before any other plugin's hook.

See Jetpack::add_configure_hook() which is hooked into each of plugin_loaded, network_plugin_loaded and mu_plugin_loaded with priority 90. It does this pissing about for every plugin that's been loaded.
Why it doesn't just set its priority to -PHP_INT_MAX I don't know!
It's a complete waste of time.

C:\apache\htdocs\wordpress\wp-content\plugins\oik-bwtrace\includes\bwtrace-actions.php(569:0) bw_trace_attached_hooks(2) 11 0 2021-12-31T09:42:24+00:00 0.960581 0.000603 cf=plugins_loaded 2487 9 0 6291456/6291456 256M F=529 plugins_loaded 
: -10000   Jetpack::configure;1
: -9999   bw_trace_time_plugin_loaded;1
: 0   wp_maybe_load_widgets;1 wp_maybe_load_embeds;1 _wp_add_additional_image_sizes;1 bw_trace_parms;9 bw_trace_attached_hooks;9

[bobbingwide]

Why it doesn't just set its priority to -PHP_INT_MAX I don't know! It's a complete waste of time.

I found some issues in the Jetpack repo where they had problems with other plugins using - PHP_INT_MAX, eg WPML.
So why can't Jetpack use -1000 or some other arbitrary figure. What's it doing in configure() that's so important!

Here's the original issue. Automattic/jetpack#14720
Read that issue for the follow up from WPML.

[bobbingwide]

7. The timing for trace records and the action timing report didn't match.

In the trace output, when Include timestamp is selected, each trace record contains fields showing the elapsed time and the interval between the previous trace record and the next.

C:\apache\htdocs\wordpress\wp-content\plugins\oik-bwtrace\includes\oik-action-counts.php(22:32)
 bw_trace_activate_mu(1) 1 0 2021-12-29T17:08:32+00:00 0.000000 0.000000 cf! 3 1 0 2097152/2097152 512M F=265 1 on
C:\apache\htdocs\wordpress\wp-content\plugins\oik-bwtrace\includes\oik-action-counts.php(22:32)
 bw_trace_activate_mu(2) 2 0 2021-12-29T17:08:32+00:00 0.015047 0.015047 cf! 3 1 0 2097152/2097152 512M F=265 target dir C:\apache\htdocs\ebps/wp-content/mu-plugins

The first elapsed time of zero didn't take into account the fact that a lot of WordPress core had already been loaded.
$timer_start was being set to the current time, using microtime( true ) .
It would be more accurate if set to $_SERVER['REQUEST_TIME_FLOAT'].

In the example below the code's been changed.
We can see that 0.178 seconds have elapsed since the transaction first started.
This time was spent loading and processing a lot of WordPress core.

C:\apache\htdocs\wordpress\wp-content\plugins\oik-bwtrace\includes\oik-action-counts.php(22:32) 
bw_trace_activate_mu(1) 1 0 2021-12-31T12:17:05+00:00 0.178450 0.178450 cf! 3 5 0 2097152/2097152 256M F=287 1 on
C:\apache\htdocs\wordpress\wp-content\plugins\oik-bwtrace\includes\oik-action-counts.php(22:32) 
bw_trace_activate_mu(2) 2 0 2021-12-31T12:17:05+00:00 0.183617 0.005167 cf! 3 5 0 2097152/2097152 256M F=287 target dir C:\apache\htdocs\bwcom/wp-content/mu-plugins

• F=287 indicates the number of PHP files that have been included at this point.
• This is different from the F=265 in the previous output.
• Explanations of the 22 extra files below

Difference	Accounts for
The request being traced was different. wp-admin/upload.php vs wp-admin/options-general.php	0
Query monitor's custom db.php drop-in	3
Files for WordPress Multi Site	10
sunrise.php drop-in	1
More Multi Site files	3
An additonal Must Use plugin __oik-lib-mu.php	5
libs\oik-boot.php loaded later when oik-lib not loaded	0
total	22

[bobbingwide]

The first elapsed time of zero didn't take into account the fact that a lot of WordPress core had already been loaded.

I need to check if the trace shutdown report and the daily trace summary figures were already correct
or will now be higher than before, due to the WordPress load not having been taken into account.
The figures in bold may now be higher.

wordpress/,,1.497586,8.0.2,1278,3843,358,1,584,31,14,7,43,0.06969141960144,
C:/apache/htdocs/wordpress/bwtrace3/bwtraces.loh.3,39,0,17425,127.0.0.1,1.497317,
2021-12-31T16:15:05+00:00,Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML; like Gecko) Chrome/96.0.4664.110 Safari/537.36,GET,200

[bobbingwide]

This is now delivered in oik-bwtrace v3.3.1. It will be closed when released to wordpress.org.