Closed bobbingwide closed 1 month ago
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.
eg
mu_plugins_loaded
plugins_loaded
init
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.
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.
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.
Support ad hoc specification of hooks to time
There are two options for this.
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
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.
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.
In Rarst's Laps plugin there's a list of core hooks that Laps is interested in:
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!
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
mu_plugin_loaded
action that was timed occurred after oik_lib_loaded
.muplugins_loaded
is run after network activated plugins have been loaded.muplugins_loaded
( allow_reinstalls to slog )plugin_loaded
and the timing of plugins_loaded
plugins_loaded
before any other plugin's hook. 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
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. https://github.com/Automattic/jetpack/pull/14720 Read that issue for the follow up from WPML.
- 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.F=265
in the previous output. 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 |
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
This is now delivered in oik-bwtrace v3.3.1. It will be closed when released to wordpress.org.
oik-bwtrace v3.3.1 was delivered to wordpress.org on 22nd March 2022. The commits in April 2022 were delivered in v3.4.0 in August 2022
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.