#57916 closed task (blessed) (fixed)
Explore and assess 6.2 server-side performance regressions
Reported by: | flixos90 | Owned by: | flixos90 |
---|---|---|---|
Milestone: | 6.2 | Priority: | normal |
Severity: | normal | Version: | 6.2 |
Component: | General | Keywords: | has-patch |
Focuses: | performance | Cc: |
Description
Over the past few weeks, I have been monitoring server-side performance of WordPress 6.2 Beta releases in this spreadsheet. While there has been one known regression in #57648 that is acceptable temporarily (due to the nature of the change, and the root problem should be addressed in the near future), there are a few other regressions in server-side performance, specifically in the init
action, that deserve some attention.
Today I conducted another benchmark for 6.2 RC1 (see this sheet and unfortunately got worse results overall. Performance measurements fluctuate sometimes, so at first I thought this was random, but I got similar results, no matter how often I ran it. I used the same site and configuration for testing as I did before, but the numbers were different - even when I re-ran 6.2 Beta 3 benchmarks. While it is unclear to me still why the results now are so different from the previous analyses, one thing that is clear and now further emphasized by the new benchmark is that there are some regressions in init
: 3.47ms for a block theme and 3.41ms for a classic theme
Those regressions were not as clearly visible in the previous benchmarks. While we don't know at this point exactly which of the two numbers we should trust, it is worth noting that these regressions also impact overall load time:
- TT1 (classic theme) loads 4.29ms slower in 6.2-RC1 than in 6.1.1.
- TT3 (block theme) still loads ~25ms faster in 6.2-RC1 than in 6.1.1 (which is a great win), yet the previous benchmarks had indicated a far better ~34ms difference.
In order to get more insights on the init
performance regression, I ran another benchmark with a more detailed breakdown that includes metrics for every single callback that is hooked into the init
action, which can be explored in this spreadsheet.
The primary areas causing the slowdown in init
performance are:
- The
wp_widgets_init()
function (mostly thewidgets_init
action): 0.92ms slower for classic theme, 2.05ms for block theme - The
WP_Block_Supports::init()
method: 0.71ms for classic theme, 0.87ms slower for block theme - The
register_core_block_types_from_metadata()
function: 0.21ms slower for classic theme, 0.86ms for block theme - The
register_core_block_patterns_and_categories()
function: 0.2ms slower for classic theme, 0.25ms for block theme
Given that there are 2 new block types being registered with server-side logic in this release (core/heading
and core/post-author-name
) and given the general addition of a few block types, there is a good chance that especially the last two points above are affected by those, which is probably acceptable. After all, features come at a cost, and that is certainly justifiable. However, some of those regressions seem unnecessarily large. We should explore particularly why wp_widgets_init()
and WP_Block_Supports::init()
are that much slower than they were in 6.1.
For block themes only, it is also worth noting that a few block registration functions see a notable regression (which do not see this regression for classic themes):
register_block_core_heading()
: 0.34ms slowerregister_block_core_post_navigation_link()
: 0.21ms slowerregister_block_core_site_title()
: 0.21ms slower
It's probably a good idea to check why these block registration functions are that slow as well.
I have added this task to the 6.2 milestone, since this task is about determining where these problems come from and whether we can do something about them. I understand we may not fix any of these regressions for the 6.2 release, but I think we should assess them prior to the release so that we can fix some of them for 6.2.1, which should be done in separate tickets. This ticket's purpose is to provide an overview and facilitate general discussion about the problems, not to actually fix them.
Attachments (3)
Change History (19)
This ticket was mentioned in Slack in #core by mukeshpanchal27. View the logs.
21 months ago
This ticket was mentioned in Slack in #core by costdev. View the logs.
21 months ago
#4
@
21 months ago
As a second data point here, I quickly ran some tests locally using wp-env to spin up a site with the following config:
{ "config": { "WP_DEBUG": false, "WP_DEBUG_LOG": false, "WP_DEBUG_DISPLAY": false, "SCRIPT_DEBUG": false } }
I set loaded the Twenty Twenty-One theme and ran tests of 20 requests using the Apache Bench tool (i.e., ab
) for WP 6.1.1, 6.2-beta1, and 6.2-RC1, respectively, using WP CLI to update the site so the zip packages would be applied. Here are the results that I got from these tests:
## 6.1.1 Document Path: / Document Length: 62259 bytes Concurrency Level: 1 Time taken for tests: 1.627 seconds Complete requests: 20 Failed requests: 0 Total transferred: 1250420 bytes HTML transferred: 1245180 bytes Requests per second: 12.29 [#/sec] (mean) Time per request: 81.367 [ms] (mean) Time per request: 81.367 [ms] (mean, across all concurrent requests) Transfer rate: 750.38 [Kbytes/sec] received Connection Times (ms) min mean[+/-sd] median max Connect: 0 0 0.0 0 0 Processing: 52 81 89.5 56 458 Waiting: 30 56 84.6 34 415 Total: 52 81 89.5 57 459 Percentage of the requests served within a certain time (ms) 50% 57 66% 70 75% 70 80% 71 90% 98 95% 459 98% 459 99% 459 100% 459 (longest request) ## 6.2-beta1 Document Path: / Document Length: 62433 bytes Concurrency Level: 1 Time taken for tests: 1.448 seconds Complete requests: 20 Failed requests: 0 Total transferred: 1253900 bytes HTML transferred: 1248660 bytes Requests per second: 13.81 [#/sec] (mean) Time per request: 72.390 [ms] (mean) Time per request: 72.390 [ms] (mean, across all concurrent requests) Transfer rate: 845.77 [Kbytes/sec] received Connection Times (ms) min mean[+/-sd] median max Connect: 0 0 0.0 0 0 Processing: 44 72 101.5 47 503 Waiting: 26 53 98.5 29 471 Total: 44 72 101.6 47 503 Percentage of the requests served within a certain time (ms) 50% 47 66% 51 75% 54 80% 56 90% 70 95% 503 98% 503 99% 503 100% 503 (longest request) ## 6.2-RC1 Document Path: / Document Length: 62613 bytes Concurrency Level: 1 Time taken for tests: 1.289 seconds Complete requests: 20 Failed requests: 0 Total transferred: 1257500 bytes HTML transferred: 1252260 bytes Requests per second: 15.51 [#/sec] (mean) Time per request: 64.475 [ms] (mean) Time per request: 64.475 [ms] (mean, across all concurrent requests) Transfer rate: 952.33 [Kbytes/sec] received Connection Times (ms) min mean[+/-sd] median max Connect: 0 0 0.0 0 0 Processing: 43 64 69.6 49 360 Waiting: 26 45 67.0 29 329 Total: 43 64 69.6 49 360 Percentage of the requests served within a certain time (ms) 50% 49 66% 51 75% 52 80% 54 90% 56 95% 360 98% 360 99% 360 100% 360 (longest request)
I'd like to retry this process using the same server timing method that @flixos90 has reported, but from this initial simple set of checks, it would seem to confirm what our automated performance workflows have been saying, which is that Twenty Twenty One is loading faster on WP 6.2 than on WP 6.1 in a default configuration.
@flixos90 could you add more detail about the method you're using to get the results you're seeing so that I and others can try to reproduce?
#5
@
21 months ago
I ran the tests I've been doing for the whole 6.2 cycle, to have another datapoint. It measures total time (TTFB) for a homepage request of a clean install for the last four default themes: TwentyTwenty, TwentyTwentyOne, TwentyTwentyTwo, TwentyTwentyThree.
According to those numbers, 6.2 RC2 is still an improvement over 6.1.1 for all the themes.
Link to the post with the details and to the full dataset.
(I'm unable to upload images to trac and, apparently, providing a link to the image doesn't work either. Sorry about that.)
This ticket was mentioned in Slack in #core by francina. View the logs.
21 months ago
This ticket was mentioned in PR #4243 on WordPress/wordpress-develop by @spacedmonkey.
21 months ago
#7
- Keywords has-patch added
Trac ticket: https://core.trac.wordpress.org/ticket/57916
#8
follow-up:
↓ 10
@
21 months ago
After spending a lot of time profiling, I discovery a performance difference between beta4 and rc2. This function is called register_block_style_handle
. This function seems to have changed how it working somehow. The biggest things slowing this function down is the realpath check. In the 184 times it was called in my local env, it was doing a realpath a file that does not exist.
In #4243, I do a simple check for if the file exists.
Here is the profiling data.
WP 6.2 - RC2
Response Time (median),185.64
wp-before-template (median),110.79
wp-before-template-db-queries (median),0
wp-template (median),66.44
wp-template-db-queries (median),0
WP 6.2 - RC2 + PR #4243
Response Time (median),169.25
wp-before-template (median),100.97
wp-before-template-db-queries (median),0
wp-template (median),60.95
wp-template-db-queries (median),0
As this is a simple fix, it could go into 6.2RC3 or 6.2.1.
I would like to understand the root cause of this problem, but couldn't find it in my profiles.
#9
@
21 months ago
@spacedmonkey Can you clarify how you tested this, in which environment etc.? It looks like you tested with a block theme for example.
I just manually added the code from your PR directly into the regular ZIP production build code for WP 6.2-RC2 and tested like that, also doing a fresh comparison with 6.1.1. I used a LocalWP site, where I "hacked" the wp-includes/blocks.php
file with the code change from https://github.com/WordPress/wordpress-develop/pull/4243.
Here are my numbers for TT1 theme:
WP 6.1.1:
wp-before-template
: 37.89mswp-init
(part of the above): 18.66ms
wp-template
: 25.89mswp-total
: 63.88ms
WP 6.2-RC2:
wp-before-template
: 37.99mswp-init
(part of the above): 19.46ms
wp-template
: 23.3mswp-total
: 61.39ms
WP 6.2-RC2 with code from the PR:
wp-before-template
: 38.11mswp-init
(part of the above): 19.55ms
wp-template
: 23.38mswp-total
: 61.62ms
Two main observations:
- For some reason, now my numbers again show that 6.2 is faster than 6.1.1, which is great and covers with the numbers I had before. Still not sure what went wrong earlier this week, again I haven't even touched my setup. Very confusing.
- The PR does not seem to have a notable effect on performance when using TT1, so based on my data I wouldn't think it's what is causing the
init
regression (which, again, is still there regardless of which data we trust, whether WP 6.2 overall is faster or not). I see the major improvement on your tests though, but again I wonder if this is just a separate performance enhancement worth making rather than being the cause for the regression.
#10
in reply to:
↑ 8
@
21 months ago
Replying to spacedmonkey:
After spending a lot of time profiling, I discovery a performance difference between beta4 and rc2. This function is called
register_block_style_handle
. This function seems to have changed how it working somehow. The biggest things slowing this function down is the realpath check. In the 184 times it was called in my local env, it was doing a realpath a file that does not exist.
As this is a simple fix, it could go into 6.2RC3 or 6.2.1.
I would like to understand the root cause of this problem, but couldn't find it in my profiles.
For it to go into 6.2 RC3:
- Need to confirm that this is a performance regression introduced in 6.2.
- Need to identify and "understand the root cause of this problem" to ensure the fix resolves it without causing unexpected issue(s).
- Need to assess its severity / impact on the release.
Else, I'd suggest considering it for 6.2.1 when ready.
#11
@
21 months ago
Something to note
register_block_core_post_navigation_link - Does a database query to next and back links.
wp_widgets_init - Does a database query see attached screenshot.
I haven't look at the others, but may also be the case, that are the either doing database looksup or a file system look up. Which might result in different results between test runs.
#12
@
21 months ago
I spent a bit more time researching this and got to one interesting and very positive finding:
Since the widgets_init
action was one of the primary offenders for the init
regression, I first used this Gist plugin with a manually added call to include Server-Timings for every callback hooked to the widgets_init
action. This sheet shows the results from 100 runs. As you can see, the primary offender there is the ...-register-widgets
call, which refers to the WP_Widget_Factory::_register_widgets()
function.
Looking at the history, none of the widget foundation has been touched in the WP 6.2 cycle in any way that could even affect performance (see https://github.com/WordPress/wordpress-develop/commits/trunk/src/wp-includes/class-wp-widget-factory.php, https://github.com/WordPress/wordpress-develop/commits/trunk/src/wp-includes/class-wp-widget.php, https://github.com/WordPress/wordpress-develop/commits/trunk/src/wp-includes/widgets.php), so I was thinking that maybe it is something that a specific widget does when it is registered.
So I hacked my WordPress installs to include Server-Timing metrics for every individual widget registration (couldn't do that from a plugin). I then did another Server-Timing benchmark doing 100 runs. I noticed that the WP_Widget_Text
widget was generally way slower than the other widgets to register, and that had seemingly gotten worse in WP 6.2. I knew that @spacedmonkey had recently touched that widget in [55553] for performance reasons (only in trunk
, so will only be included in WP 6.3), so I gave it a try to apply that change to my WordPress 6.2 installation. Then I ran the Server-Timing benchmark with 100 runs again.
Turns out that fix brings a notable performance improvement that enhances the widgets_init
performance so that the "regression" is gone. This sheet shows it in detail: Compare column F with column D, particularly for rows 62-66. The faster performance in the registration of that widget is what brings down overall processing time for widgets_init
by ~3ms, which happens because we avoid JSON-encoding some data there unnecessarily. Note that if you only fix this for the WP_Widget_Text
class, the problem will instead surface in the WP_Widget_Custom_HTML
class. It seems that for whatever reason, the JSON-encode call is expensive only the first time that it happens.
Accordingly, the performance improvement for overall init
is not as high, but it's still 0.4ms - potentially because now some other code has the first JSON-encode call. But it's definitely a nice performance enhancement overall.
I am still unsure how all that relates to why init
performance of WP 6.2 seems worse than in WP 6.1, since all that code had not been touched. It seems that indeed someone else affects it.
Given that [55553] is simply a new performance enhancement and doesn't technically fix anything that was introduced in the 6.2 cycle, it doesn't justify being backported and can be included in 6.3. That said, I think it's a neat enhancement and technically improves the metrics we're seeing here.
We may want to do some more research on why widgets_init
is actually slower in 6.2 than 6.1, but at this point I'm unsure that will be fruitful. And at least we now have a good path forward to enhance this.
I would still suggest to keep this ticket open to explore the other notable reason for the init
regression, the WP_Block_Supports::init()
function (see here.
This ticket was mentioned in Slack in #core by shuvoaftab. View the logs.
21 months ago
#14
@
21 months ago
I believe I have tracked down the issue with WP_Block_Supports::init
. Init calls register_attributes
. In WordPress 6.2, wp_register_position_support
was added and is not called as part of register_attributes
. So this regression is from adding new functionality.
See screenshots.
This ticket was mentioned in Slack in #core by hellofromtonya. View the logs.
21 months ago
#16
@
21 months ago
- Resolution set to fixed
- Status changed from assigned to closed
Thanks @spacedmonkey, that makes sense.
I just gave it another look and did some quick benchmarks, looks like the new logic for the position
support isn't in any way slower than that of other block supports features, so there's probably nothing we would need to do specific to the new feature.
That said, I noticed some potential areas of improvement in the WP_Block_Supports
class logic in general, for example the register_attributes()
method calls every block supports feature's registration function for every block that exists, which means a potentially small change there could make a meaningful difference due to the many calls. One thing that looks unnecessarily complex and potentially slow to me is that that method already has access to the $block_type->supports
property where it could just check if the specific feature is supported by the block type before (unconditionally) calling the registration function. The individual registration functions then all use block_has_support()
with _wp_array_get()
, which seems a bit backwards since it's always just one element: For example, checking isset( $block_type->supports['position'] )
is lighter than _wp_array_get( $block_type->supports, array( 'position' ) )
. Not sure if this will make a difference in performance, but due to the common usage may be worth exploring.
Any follow-up investigation for related performance enhancements would be decoupled from potential 6.2 regressions, so I think it's fair to say we have figured out what's going on here and no further action is required. Thanks everyone for helping out here!
I wonder if #57864 it related to the issue with widget_init?