Improve caching for `theme.json` processing #3418

oandregal · 2022-10-07T19:40:11Z

Gutenberg report Performance regression in WP 6.1 for theme.json processing gutenberg#44772
Trac ticket https://core.trac.wordpress.org/ticket/56467

What

This PR tries to address some performance regressions introduced in WordPress 6.1.

During the beta cycle, we removed some of the existing caching for theme.json processing (see #3408 and #3359). The rationale for this was that this code was now used before all the blocks are registered (aka get template data, etc.) and resulted in stale cache that created issues (see WordPress/gutenberg#44434 and WordPress/gutenberg#44619). We limited it to only reads from the file system. As pointed out in the Gutenberg's issue, this introduced a big impact in performance that this PR is trying to reduce.

Why

It's a very noticeable degradation that stems from changes done in this cycle.

How

Caches the calculated data for core, theme, and user based on the blocks that are registered. If the blocks haven't changed since the last time we calculated the data for each origin, we return the cached data. Otherwise, we recalculate it.

Essentially, this brings back the cache we had, but refreshing it when the blocks have changed.

Performance improvements

The test I'm doing for profiling performance is loading the "Hello World" post as a logged-out user. These are the numbers in the different setups.

Method	WordPress 6.0	WordPress trunk (rev 54449)	This PR
total time	760ms	1336ms	787ms
`wp_get_global_settings`	0.2ms (24 calls)	1.2ms (72 calls)	0.9ms (72 calls)
`wp_get_global_stylesheet`	1ms (1 call)	0.09ms (1 call)	0.03ms (1 call)
`wp_get_global_styles_svg_filters`	0.05ms (1 call)	0.06ms (1 call)	0.04ms (1 call)
`wp_add_global_styles_for_blocks`	-	1.2ms (1 call)	0.09ms (1 call)
`WP_Theme_JSON_Resolver::get_core_data`	0.3ms (27 calls)	53.9ms (76 calls)	2.7ms (76 calls)
`WP_Theme_JSON_Resolver::get_block_data`	-	20ms (76 calls)	1.2ms (76 calls)
`WP_Theme_JSON_Resolver::get_theme_data`	17ms (49 calls)	264ms (98 calls)	74ms (98 calls)
`WP_Theme_JSON_Resolver::get_user_data`	0.08ms (27 calls)	12.8ms (76 calls)	0.9ms (76 calls)
`WP_Theme_JSON_Resolver::get_merged_data`	12ms (27 calls)	121ms (76 calls)	108ms (76 calls)

These numbers can be seen in the cachegrind data that follows:

WordPress 6.0: cachegrind.out.6-0.gz
Trunk at rev 54449: cachegrind.out.6-1-trunk-54449.gz
This PR: cachegrind.out.6-1-pr-3418.gz

You can take this data and open it with any visualizer of your choice (kcachegrind, webgrind, etc.). As with the client performance numbers, the exact ms are not as important as the variance between them. I also share below how to reproduce this for anyone interested.

How to reproduce the performance results

Enable xdebug profiling:

Clone the https://github.com/WordPress/wordpress-develop repo. Apply this patch to the configuration:
Configure the environment so xdebug profiles the application by URL:
- Edit the .env file and set LOCAL_PHP_XDEBUG=true, and LOCAL_PHP_XDEBUG_MODE=develop,debug,profile. For WordPress 6.0, copy XDEBUG_MODE=develop,debug,profile in the docker-compose.yml file instead (see below).
- Edit the docker-compose.yml file and add XDEBUG_CONFIG=profiler_output_name=cachegrind.out.%R.
Open the browser and visit http://localhost:8889/?p=1 (this loads the "Hello World" post).
As a result of this configuration, the docker container should have created a few files named /tmp/cachegrind.out.*. Verify those files exist. You may use this command
```
 docker exec -it `docker ps -f name=wordpress-develop_php -q` ls -l /tmp
```

Read the profiling reports using webgrind:

Download or clone https://github.com/jokkedk/webgrind in wp-content/plugins/webgrind of the wordpress-develop repo.
Start the wordpress-develop environment normally.
Visit http://localhost:8889/wp-content/plugins/webgrind/ and check the results for this branch. You'll have to do the same for checking the results in trunk and in the 6.0 branch.

Alternatively, you can read the profiling reports using kcachegrind (linux, probably qcachegrind can do the same for mac & windows?), which allows for loading the xdebug files directly so you can easily compare branches:

Copy the files generated by xdebug for this branch (/tmp/cachegrind.out.*) somewhere outside the docker container. Do the same for the files generated for trunk and 6.0 (be aware that the files will overwrite each other, so copy before changing branches).
For example, I copy the files by doing:

docker cp `docker ps -f name=wordpress-develop_php -q`:'/tmp/cachegrind.out.__p=1.gz' /tmp/cachegrind.out.<6-0 or trunk or this-branch>.gz

Open the app and check the results.

How to test

Make sure automated test pass.

Manually test that global styles still works as expected by using the TT2 or TT3 themes and updating some block styles via the global styles sidebar.

oandregal · 2022-10-07T22:58:14Z

This is now in a good enough state we could consider merging, though there are some places where we can squeeze some more ms. I still need to fix tests as well.

ockham · 2022-10-09T14:50:30Z

Thank you @oandregal!

Unfortunately, it looks like unit tests are currently failing. A number of quite different methods seem to be affected, so I wasn't able to figure out the root cause at a quick glance...

spacedmonkey · 2022-10-10T10:01:33Z

@oandregal Can you please add some unit tests for this change. 101 lines change to a very important class, should include some unit tests.

src/wp-includes/class-wp-theme-json-resolver.php

spacedmonkey · 2022-10-10T10:05:08Z

src/wp-includes/class-wp-theme-json-resolver.php

@@ -272,7 +321,7 @@ public static function get_theme_data( $deprecated = array(), $options = array()
 	public static function get_block_data() {
 		$registry = WP_Block_Type_Registry::get_instance();
 		$blocks   = $registry->get_all_registered();
-		$config   = array( 'version' => 1 );
+		$config   = array( 'version' => 2 );


Can you explain this change?

This is a bug I found while working in this PR. I can prepare a different PR if that's preferred but thought it was so minor it didn't merit one.

This sets the version of the theme.json schema used by the data stored in the blocks. We introduced version 2 in WordPress 5.9 and blocks only gained this functionality in this release, so we should be using the latest. In practice, because we're using the version 2 to store data in the blocks, probably we won't notice anything. Though this is still a dormant bug waiting to happen, and I rather do the right thing now. See docs.

src/wp-includes/class-wp-theme-json-resolver.php

spacedmonkey · 2022-10-10T10:20:07Z

Still seeing lots of calls to remove keys in from schema.

spacedmonkey · 2022-10-10T10:44:02Z

Love the feedback from @peterwilsoncc and @mukeshpanchal27

oandregal · 2022-10-10T23:14:40Z

@ockham this is now ready. The numbers are back to 6.0 levels. I've updated the issue description with the performance results of calls to the main APIs people use to interact with theme.json data.

There are opportunities to squeeze a bit more ms, specially in translation (I tried, but tests failed for reasons I didn't understand and thought it was too risky for now, can prepare a follow-up PR if I find a way). More opportunities in reducing the number of calls to WP_Theme_JSON_Resolver methods, by inspecting higher-up the call stack (I didn't understand some of these places well enough to try). Speeding up the lower down (WP_Theme_JSON methods) parts seems a bit more complex, though we should try as well.

oandregal · 2022-10-10T23:52:50Z

Still seeing lots of calls to remove keys in from schema.

@spacedmonkey This is the performance results for this function (I shared the xdebug profiles in the issue description for anyone to visualize with their tool of choice):

Method	WordPress 6.0	WordPress trunk (rev 54449)	This PR
`WP_Theme_JSON::remove_keys_not_in_schema`	1 382 100ns / 249 calls = 5550ns per call	180 317 170ns / 33198 calls = 5431ns per call	6 115 350ns / 1361 calls = 4493ns per call

The times it takes the operation in the three setups I've tried does not indicate this is a bottleneck: it takes about the same amount of time per call. Though the number of times it's called does, and it indicates the issue is higher-up.

This is what I saw when zooming out a bit (call hierarchy for one path, via kcachegrind):

WordPress 6.0	WordPress trunk (rev 54449)	This PR

My point is that remove_keys_not_in_schema is a leaf function. We can look at optimizing it, though it is not the culprit here. The nature of the issue was that we had to remove the cache we had, so it's only reasonable that some methods are called more times now. The bigger gains in this case were (still are?) in bringing back that cache we had selectively. For example, digging into why get_the_block_template_html still takes 10x more than it did it 6.0 or looking at get_theme_data and get_merged_data sounds more promising.

oandregal · 2022-10-11T00:40:29Z

I forgot to test the latest changes manually per the issue instructions:

Manually test that global styles still works as expected by using the TT2 or TT3 themes and updating some block styles via the global styles sidebar.

Probably some other random tests related to global styles won't hurt. I'm now far from the computer and can't do it myself, but wanted to leave this note for reviewers.

mukeshpanchal27

Thanks @oandregal Left some review comments.

src/wp-includes/class-wp-theme-json-resolver.php

mukeshpanchal27 · 2022-10-11T05:53:28Z

@oandregal Please check #3418 (review)

oandregal · 2022-10-11T07:11:40Z

I tested this myself manually using TT2 and TT3 themes. I tested empty state for each theme and updating the user values from the global styles' sidebar (selecting a style variation, specific changes to some blocks, etc.). I've also tested a localized WordPress to make sure translations are picked up. It's working as expected.

oandregal · 2022-10-11T07:16:12Z

src/wp-includes/class-wp-theme-json-resolver.php

@@ -189,19 +243,21 @@ public static function get_theme_data( $deprecated = array(), $options = array()

 		$options = wp_parse_args( $options, array( 'with_supports' => true ) );

-		$theme_json_data = static::read_json_file( static::get_file_path_from_theme( 'theme.json' ) );
-		$theme_json_data = static::translate( $theme_json_data, wp_get_theme()->get( 'TextDomain' ) );
+		if ( null === static::$theme || ! static::has_same_registered_blocks( 'theme' ) ) {


The only change here is running this code conditionally. The code within has not changed, it's only tabbed.

src/wp-includes/class-wp-theme-json-resolver.php

oandregal · 2022-10-11T11:24:05Z

To get a change this big merged in at the last minute, then unit tests are must. We do not want a regression at this late stage.

We have dozens of unit tests for this code already that cover the existing behavior (wpThemeJsonResolver.php, wpThemeJson.php, wpThemeJsonSchema.php, wpGetGlobalStylesheet.php). I've been using them to drive changes in this PR as they were failing at the beginning.

Having "more test" sounds good to me. At the same time, I also want to be mindful of the time and resources we all have to move this forward, so in the name of efficiency I'd like to ask: what additional tests do we need that are a blocker for merging?

spacedmonkey · 2022-10-11T11:32:42Z

There are not unit tests for the following methods.

get_core_data
has_same_registered_blocks
get_theme_data
get_user_data

I don't think we have enough coverage to merge this change. Tests to prove that methods above do as expected. Check cleaning caches was as expected and code is not being run again after cache working as expected.

There are basically no changes to WordPress that should not come along with a unit test. Something this important NEEDS them before the mege.

src/wp-includes/class-wp-theme-json-resolver.php

hellofromtonya · 2022-10-11T12:55:09Z

Currently looking at test coverage for the changes in this PR.

hellofromtonya · 2022-10-11T15:51:11Z

Okay, here's what I've done:

Tested it manually (though not as thorough as I'd like) - not seeing any issues
Added some additional PHPUnit tests for this PR including:
- WP_Theme_JSON_Resolver::has_same_registered_blocks() - though this is a non-public method, it's the heart of the changes here. So test coverage helps to validate it works as expected.
- WP_Theme_JSON_Resolver::get_core_data()

What else is needed?

More tests are needed.
The test class needs a lot of love (though out of scope for this PR).
A lot more manual testing is needed.
A lot more performance testing is needed.

IMO This PR is ready "enough" for RC1 with the condition that more tests and testing will happen by 6.1 RC2. Why? It's a significant enough performance regression to warrant getting it fixed. More extenders typically test during the RC cycle. So releasing as part of RC1 gives more testing and feedback exposure for any additional unknowns or work that may be needed.

ockham · 2022-10-11T16:02:45Z

Amazing, thank you very much for testing, @hellofromtonya!

WP_Theme_JSON_Resolver::has_same_registered_blocks() - though this is a non-public method, it's the heart of the changes here. So test coverage helps to validate it works as expected.

Awesome, exactly my thinking 👍

IMO This PR is ready "enough" for RC1 with the condition that more tests and testing will happen by 6.1 RC2. Why? It's a significant enough performance regression to warrant getting it fixed. More extenders typically test during the RC cycle. So releasing as part of RC1 gives more testing and feedback exposure for any additional unknowns or work that may be needed.

I agree 100%.

I wish I could've helped more getting this across the finish line, but I'm very very grateful we got this ready for RC1. Thanks again also to @oandregal for this fix, and your thorough profiling!

I'll make a note to add more test coverage before RC2.

* Removes "we" words * Adds data type to `@param` * Improves readability and consistency

hellofromtonya · 2022-10-11T17:16:16Z

Committed via changeset https://core.trac.wordpress.org/changeset/54493.

oandregal · 2022-10-11T17:47:52Z

I'm still investigating this for further improvement and have created #3441 as a follow-up.

ockham · 2022-10-13T15:28:02Z

@c4rl0sbr4v0 @michalczaplinski Since I'll be AFK tomorrow, would y'all mind working with @hellofromtonya to add unit test coverage (see #3418 (comment) and #3418 (comment)) in a follow-up PR? (Let's maybe also file a Trac ticket targeting 6.1 to have it on file.)

oandregal mentioned this pull request Oct 7, 2022

Performance regression in WP 6.1 for theme.json processing WordPress/gutenberg#44772

Closed

oandregal marked this pull request as ready for review October 7, 2022 22:56

spacedmonkey reviewed Oct 10, 2022

View reviewed changes

src/wp-includes/class-wp-theme-json-resolver.php Outdated Show resolved Hide resolved