search

bobbingwide / oik-bwtrace

debug trace for WordPress
https://www.oik-plugins.com/oik-plugins/oik-bwtrace-debug-trace-for-wordpress/
GNU General Public License v2.0
6 stars 1 forks source link

Improve startup performance of _oik-bwtrace-mu.php #109

Closed bobbingwide closed 11 months ago

bobbingwide commented 2 years ago

In the performance reports I produced for cwiccer.com the Plugin load times post indicates that _oik-bwtrace-mu.php takes 0.04 of a second to get started.

This is significantly greater than other plugins: plugin Load time (secs )
_oik-bwtrace-mu.php 0.039529
oik-fields.php 0.000737
oik-unloader-mu.php 0.000547
oik-unloader.php 0.000153
gbcptedit.php 0.000073

Requirement

Reduce the overhead of tracing when it's being used to analyse server performance

Proposed solution

Investigate solutions to reduce the load time when tracing is being invoked for performance reasons.

bobbingwide commented 2 years ago

Figures for plugin load times on blocks.wp-a2z.org show _oik-bwtrace-mu.php taking 0.05 seconds.

Plugin load times Plugin,Load time (secs),Accum
REQUEST_TIME_FLOAT,0.000000,0.000000
WP_START_TIMESTAMP,0.001752,0.001752
wp-content/mu-plugins/_oik-bwtrace-mu.php,0.050222,0.051974
wp-content/mu-plugins/oik-loader-mu.php,0.006684,0.058658
wp-content/mu-plugins/oik-unloader-mu.php,0.000208,0.058866
wp-content/plugins/allow-reinstalls/allow-reinstalls.php,0.000702,0.059568
wp-content/plugins/diy-oik/diy-oik.php,0.000109,0.059677
wp-content/plugins/oik-a2z/oik-a2z.php,0.000123,0.059800
wp-content/plugins/oik-ajax/oik-ajax.php,0.000135,0.059935
wp-content/plugins/oik-batch/oik-wp.php,0.000502,0.060437
wp-content/plugins/oik-blocks/oik-blocks.php,0.000152,0.060589
wp-content/plugins/oik-bob-bing-wide/oik-bob-bing-wide.php,0.000173,0.060762
wp-content/plugins/oik-bwtrace/oik-bwtrace.php,0.000024,0.060786
wp-content/plugins/oik-css/oik-css.php,0.000126,0.060912
wp-content/plugins/oik-fields/oik-fields.php,0.000151,0.061063
wp-content/plugins/oik-lib/oik-lib.php,0.000584,0.061647
wp-content/plugins/oik-libs/oik-libs.php,0.000082,0.061729
wp-content/plugins/oik-ms/oik-ms.php,0.000067,0.061796
wp-content/plugins/oik-plugins/oik-plugins.php,0.000267,0.062063
wp-content/plugins/oik-rwd/oik-rwd.php,0.000093,0.062156
wp-content/plugins/oik-sc-help/oik-sc-help.php,0.000097,0.062253
wp-content/plugins/oik-shortcodes-a2z/oik-shortcodes-a2z.php,0.000100,0.062353
wp-content/plugins/oik-shortcodes/oik-shortcodes.php,0.000429,0.062782
wp-content/plugins/oik-themes/oik-themes.php,0.000193,0.062975
wp-content/plugins/oik-types/oik-types.php,0.000167,0.063142
wp-content/plugins/oik/oik.php,0.002996,0.066138
wp-content/plugins/sb-toolicons-block/sb-toolicons-block.php,0.000084,0.066222
wp-content/plugins/woo-gutenberg-products-block/woocommerce-gutenberg-products-block.php,0.002532,0.068754
muplugins_loaded,0.000009,0.068763
wp-content/plugins/foster-child/foster-child.php,0.007691,0.076454
wp-content/plugins/gutenberg/gutenberg.php,0.005789,0.082243
wp-content/plugins/oik-block/oik-block.php,0.000105,0.082348
wp-content/plugins/oik-clone/oik-clone.php,0.000200,0.082548
wp-content/plugins/oik-loader/oik-loader.php,0.000058,0.082606
wp-content/plugins/oik-patterns/oik-patterns.php,0.000054,0.082660
wp-content/plugins/oik-plugin-fields/oik-plugin-fields.php,0.000080,0.082740
wp-content/plugins/oik-unloader/oik-unloader.php,0.000079,0.082819
wp-content/plugins/sb-breadcrumbs-block/sb-breadcrumbs-block.php,0.000074,0.082893
wp-content/plugins/sb-chart-block/sb-chart-block.php,0.000082,0.082975
wp-content/plugins/sb-children-block/sb-children-block.php,0.000063,0.083038
wp-content/plugins/sb-post-edit-block/sb-post-edit-block.php,0.000078,0.083116
wp-content/plugins/slog/slog.php,0.000092,0.083208
wp-content/plugins/wordpress-seo/wp-seo.php,0.005458,0.088666
plugins_loaded,0.000665,0.089331
bobbingwide commented 2 years ago

Synchronise .json file updates with updates on the settings pages

oik-bwtrace settings are updated by wp-admin/options.php There is already code that's run to sanitize the different options sets. The callbacks are registered by the calls to register_setting().

Settings Hook Sanitize routine
bw_trace_files_options sanitize_option_bw_trace_files_options bw_trace_files_options_validate
bw_trace_options sanitize_option_bw_trace_options bw_trace_options_validate
bw_action_options sanitize_option_bw_action_options bw_action_options_validate
bw_summary_options sanitize_option_bw_summary_options bw_summary_options_validate

So we could add code into these sanitization routines. But it would be better to add new code to respond to the action hook that's run once the options have been updated. eg update_option_bw_trace_files_options. This hook gets passed 3 parameters: $old_value, $new_value, $option

The hook name includes the option name, which means we can hook into each of the settings individually.

This is preferable to hooking into the update_option action that precedes this, and the updated_option action that follows it. The same callback function can be used for each of the options.

bobbingwide commented 2 years ago

The same callback function can be used for each of the options.

The callback function bw_trace_update_option_sync() will access the instance of class trace_json_options in the global $bw_trace object. This class will deal with the exporting to and loading of the trace options settings from JSON files stored in the mu-plugins folder.

The performance logic will be enabled when the Trace file > Enable performance trace checkbox is set.

So long as other tests pass:

  1. mu-plugins folder exists and is accessible.
  2. tracing is enabled
  3. etc

The value of the bw_trace_files_options.performance _trace setting will control the trace start up processing

Initialisation

Processing when set Processing when not set
Tracing for performance Tracing for debugging
Load settings from JSON files Load settings from wp_options
Trace into memory Trace to the relevant trace file
Don't trace non-scalar data Trace all types of data

Processing until shutdown

Processing when set Processing when not set
Trace into memory Trace to the relevant trace file
Don't trace non-scalar data Trace all types of data

Processing on 'shutdown'

Processing when set Processing when not set
Trace to the relevant file already done
Trace all types of data already being done
bobbingwide commented 2 years ago

It appears that the figures I reported earlier were wrong..

for cwiccer.com ... _oik-bwtrace-mu.php takes 0.04 of a second to get started. Figures for plugin load times on blocks.wp-a2z.org show _oik-bwtrace-mu.php taking 0.05 seconds.

The elapsed time between WP_START_TIMESTAMP and wp-content/mu-plugins/_oik-bwtrace-mu.php covers all the work that WordPress has to do between setting WP_START_TIMESTAMP in wp_initial_constants() and the mu_plugin_loaded action after _oik-bwtrace-mu.php has been loaded.

WordPress does quite a lot of loading between these two points. Approximately 180 WordPress include files are loaded. See the code in wp-settings.php from line 61 to line 358.

To get a better understanding of the time taken to initialise tracing I added another timing point run at the start of _oik-bwtrace-mu.

if ( ! defined( 'BW_TRACE_START_TIMESTAMP' ) ) {
    define( 'BW_TRACE_START_TIMESTAMP', microtime( true ) );
}

and for the case where _oik-bwtrace-mu isn't being loaded at the start of oik-bwtrace the same code appears at the start of oik-bwtrace/oik-bwtrace.php

This new timing point gives a better indication of the time spent initialising tracing. The figures aren't as bad as I first thought. When combined with the first attempt at supporting performance trace it's more promising. I've only got local figures at present.

bobbingwide commented 2 years ago

Don't trace complex objects when tracing for performance - except when the data's actually needed

I tried this in BW_trace_record::flf(). It made a slight improvement to the total execution time when the object was a reasonable size, such as $_SERVER, but hardly any difference when the array was small or empty.

Tracing Normal Performance
_SERVER array .000039 .000015
_REQUEST array .000014 .000013

I didn't implement any logic dealing with backtrace.

bobbingwide commented 2 years ago

Load the trace and action settings from .json files - supporting WPMS

The current logic loads the options using WordPress's get_option() function. We could either intercept the filters that are invoked by this function or wrap the get_option() call with our own method. If we implement the intercept logic then we may find we don't load the options from the database when they're requested by in the admin pages.

bobbingwide commented 2 years ago

Note: PHPUnit tests need updating for different values of the Enable performance trace checkbox. They currently assume that it's not checked and fail when it is.

bobbingwide commented 2 years ago

In s.b/cwiccer I'm getting the following Fatal when using the block editor.

[04-Apr-2022 12:26:04 UTC] PHP Fatal error:  Uncaught Error: Call to a member function set_trace_files_directory() on null in C:\apache\htdocs\wordpress\wp-content\plugins\oik-bwtrace\includes\class-BW-trace-controller.php:590
Stack trace:
#0 C:\apache\htdocs\cwiccer\wp-includes\class-wp-hook.php(307): BW_trace_controller->shutdown_performance_trace('')
#1 C:\apache\htdocs\cwiccer\wp-includes\class-wp-hook.php(331): WP_Hook->apply_filters(NULL, Array)
#2 C:\apache\htdocs\cwiccer\wp-includes\plugin.php(474): WP_Hook->do_action(Array)
#3 C:\apache\htdocs\cwiccer\wp-includes\load.php(1100): do_action('shutdown')
#4 [internal function]: shutdown_action_hook()
#5 {main}
  thrown in C:\apache\htdocs\wordpress\wp-content\plugins\oik-bwtrace\includes\class-BW-trace-controller.php on line 590
bobbingwide commented 2 years ago

The PHPUnit tests need to be updated for the changes in 95f024d - Load options from JSON files if available. Depending on the current value of trace_cli they either fail in:

Tests_oik_bwtrace::test_bw_trace_plugin_startup_tracing_off Failed asserting that true is false.

C:\apache\htdocs\wordpress\wp-content\plugins\oik-bwtrace\tests\test--oik-bwtrace.php:324

or

1) Tests_oik_bwtrace::test_bw_trace_plugin_startup_tracing_on Failed asserting that false is true.

C:\apache\htdocs\wordpress\wp-content\plugins\oik-bwtrace\tests\test--oik-bwtrace.php:271

bobbingwide commented 1 year ago

Currently, after running PHPUnit tests for oik-bwtrace, things get a bit out of sync in the .json files. This is a side effect of running the PHPUnit tests when performance tracing is enabled. The .json files are overwritten by tests in Tests_oik_bwtrace and Tests_includes_class_BW_trace_controller::test_reset_status()

When using s.b/wordpress after running the PHPUnit tests we see that tracing does not appear to be enabled. The evidence is that the trace file link is not displaying and the trace summary link leads to a daily trace summary report where there's no trace file names.

To re-enable tracing the .json files need to be deleted and recreated.

The logic that synchronises one .json file when an option set is updated ( see
https://github.com/bobbingwide/oik-bwtrace/issues/109#issuecomment-1084922246 ) needs to be extended to update the other .json files for the other options.

bobbingwide commented 1 year ago

With bwtrace v3.4.2 on wp-pompey.org.uk there were several messages due to the mu-plugins folder not being present

[14-Oct-2023 09:37:57 UTC] PHP Warning:  file_put_contents(/home/customer/www/wp-pompey.org.uk/public_html/wp-content/mu-plugins/bw_trace_files_options.1.json): Failed to open stream: No such file or directory in /home/customer/www/wp-pompey.org.uk/public_html/wp-content/plugins/oik-bwtrace/includes/class-trace-json-options.php on line 64
[14-Oct-2023 09:37:57 UTC] PHP Warning:  file_put_contents(/home/customer/www/wp-pompey.org.uk/public_html/wp-content/mu-plugins/bw_trace_options.1.json): Failed to open stream: No such file or directory in /home/customer/www/wp-pompey.org.uk/public_html/wp-content/plugins/oik-bwtrace/includes/class-trace-json-options.php on line 64
[14-Oct-2023 09:37:57 UTC] PHP Warning:  file_put_contents(/home/customer/www/wp-pompey.org.uk/public_html/wp-content/mu-plugins/bw_action_options.1.json): Failed to open stream: No such file or directory in /home/customer/www/wp-pompey.org.uk/public_html/wp-content/plugins/oik-bwtrace/includes/class-trace-json-options.php on line 64

This problem was due to the new code in the BW_trace_controller class calling sync_to_json() directly. It should call maybe_trace_sync_to_json() which checks for the existence of the mu-plugins folder.

bobbingwide commented 11 months ago

Delivered in v3.4.3