Explore and assess 6.2 server-side performance regressions

[flixos90]

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 the widgets_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 slower
• register_block_core_post_navigation_link(): 0.21ms slower
• register_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.

[spacedmonkey]

I wonder if #57864 it related to the issue with widget_init?

[joemcgill]

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?

[oandregal]

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 ​for the 6.2 cycle and ​comparing major versions.

(I'm unable to upload images to trac and, apparently, providing a link to the image doesn't work either, so I removed it. Sorry about that.)

Trac ticket: https://core.trac.wordpress.org/ticket/57916

[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.

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.

[flixos90]

@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.89ms
  • wp-init (part of the above): 18.66ms
• wp-template: 25.89ms
• wp-total: 63.88ms

WP 6.2-RC2:

• wp-before-template: 37.99ms
  • wp-init (part of the above): 19.46ms
• wp-template: 23.3ms
• wp-total: 61.39ms

WP 6.2-RC2 with code from the PR:

• wp-before-template: 38.11ms
  • wp-init (part of the above): 19.55ms
• wp-template: 23.38ms
• wp-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.

[hellofromTonya]

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.

[spacedmonkey]

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.

[flixos90]

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.

[spacedmonkey]

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.

[spacedmonkey]

Child functions in 6.1

[spacedmonkey]

Child functions in 6.2

[flixos90]

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!