Tests are back at 1h-1h40, depending on the actual testbot. It used to be down to 45m-1h after the plugin discovery namespace issue was resolved.
There's no obvious single big thing to point at, but I have a few ideas to improve performance. Note that the numbers below overlap, e.g. both dfac() and module enable trigger kernel rebuilds.
-
3 calls to dfac() per test method, 36% in total.
Do we need all these? Can we optimize the install process and skip unnecessary steps?
57% of that is menu_router_rebuild()
- 90% of that _menu_navigation_links_rebuild()
- 70% of that saving menu links
- 22% system_rebuild_module_data() -
24%
Drupal\Core\DrupalKernel::buildContainer()
54% yaml parsing (86 repeated calls to the same files)
37%ContainerBuilder::compile()with 17 calls.Can we statically cache loaded yml files? Prevent container compiles/dumps if nothing has changed?
-
We have a few more required modules than we used to:
module_enable()is 25% with 12 modules (11 + one of the test).- entity.module, datetime is now a dependency of node.
#1541298: Remove Node module dependency from Testing profile would remove that and datetime from a lot of tests. - field_sql_storage will away I guess when we merge field storage into the entity storage controllers.
- We want to remove entity.module, as we can now have plugins in components in a sane way.
- entity.module, datetime is now a dependency of node.
-
1000 calls to
Symfony\Component\Yaml\Parser::parse()
86 services yml files (53% of that)
772 calls fromdrupal_parse_info_file()(but only 28% of the time)
| Comment | File | Size | Author |
|---|---|---|---|
| #4 | yaml-static-cache-2006434-4.patch | 1.57 KB | berdir |
| #2 | 51a50c33caa7b.Drupal8.xhprof.gz | 108.72 KB | berdir |
Comments
Comment #1
berdirTagging.
Comment #2
berdirAttaching the xhprof file that I was looking at.
Note when you try to repeat this, remove the cpu flag from xhprof_enable(), that increases the overhead a lot, especially of the yaml parsing, as there are *a lot* of method calls involved.
Comment #3
cweagansInstead of calling Parser::parse() directly, we could call drupal_parse_info_file() (and maybe rename it). Any file parsed with this function is statically cached. However, I'm not sure how we have 1000 calls to Symfony\Component\Yaml\Parser::parse(). That seems a little weird.
Comment #4
berdirActually, it's not. It's drupal_static()'ally cached, which we clear 3 times in a test. Seems like we could easily make that a static(), no reason to reset it?
And the function does more than, it also checks version and stuff.
So I prefer to keep them separate static caches.
The attached patch does that, seeing a considerable performance improvement for even a test with a single test method. Should even be bigger for multiple test methods as we save even more calls.
Let's see what the testbot thinks about this.
Comment #5
chx commentedLovely!
Comment #6
tim.plunkettI opened #2006484: Remove dependency on datetime from node
Comment #8
tim.plunkett#4: yaml-static-cache-2006434-4.patch queued for re-testing.
Comment #9
cweagansThis is nice :)
Comment #10
berdirMaybe, but I'm not happy about the testbot results (not really seeing any improvements there), want to investigate some more and also do another profile run now that this is out of the way.
Maybe keep this is a meta task and create separate issues for specific patches?
Comment #11
moshe weitzman commentedIt would be ideal if we focused on refactoring and not just adding caching. Maybe the YAML files can be an exception but my point stands in general. Speeding up or ditching or otherwise dealing with menu links would be very much appreciated. Those gets rebuilt during regular cache clear of Drupal as well.
Do we have a meta for converting these to unit tests? That always helps, in an indirect way.
Comment #12
berdirOpened #2026367: Use static caches for parsed .services.yml and .info.yml files for the patch, to keep this open as a general profiling issue. Please RTBC the patch there :)
Comment #13
mile23#1938068: Convert UnitTestBase to PHPUnit
Comment #14
moshe weitzman commentedI was referring to the effort to convert from web tests to unit tests, not the effort to convert from one type of unit test to a better type of unit test.
Comment #15
sunI also noticed the issue of dfac() being called way more often in D8 in #2160091: drupal_rebuild() rebuilds container twice, since drupal_flush_all_caches() also rebuilds it
Comment #16
berdirSome new notes, when looking at an xhprof report for running views_ui\DisplayTest, which contains an impressive amount of 12 test methods. Runs 4min without xhprof, 5 m with.
* Parsing config schema still uses 20% of the time, we call FileStorage::readMultiple() 200x times from TypedConfigManager
=> I have no idea what to do about it :( Note that the overhead here is probably quite large as symfony yaml parsing involves a trillion method calls (some methods are called 4M times...)
* 17% of the time is deleting cache tags (6600 calls for 12 test methods)
** 9% of the whole time is entity render cache tags, 98% of those are menu_link'.
** 4.4% is menu_cache_clear(), which is also called for every saved menu link (for the menu)
=> menu_links currently define a view builder and don't use it, we can remove it and then that should save 10% of the time there. @amateescu is already working on an patch, see #2100467: Menu links are not ready to use a view builder so remove it from the annotation for now
=> We can look into doing something similar as we do with menu router rebuild and collect cache tags and write them at the end of the request. The most obvious advantage would be that we only need to update each tag once per request, for example for menu's, for example, on my pretty standard installation, I have 50 links in the admin menu, that means 50 Cache::deleteTags() calls for the same tag when rebuilding the menu links and real sites with have *a lot* more than that.
* Those 12 test methods result in 48 calls to drupal_flush_all_caches(), which takes up ~40% of the whole execution time for me. Those calls are coming from install_finished(), _install_profile_modules_finished() and 2x resetAll(), once in setUp() and once in enableViewsTestModule().
** 80% of that is RouteBuilder::rebuild(),
** 92% of that is spent in the event dispatcher rabbithole,
*** 70% of that is RouterRebuildSubscriber::onRouterRebuild(), this is what triggers menu_router_rebuild() and that menu_link_rebuild_defaults().
**** What's crazy is that we right now spend *83%* of the time it takes to save menu link entities in postSave(), most of that is deleting cache tags as mentioned above and 10% in preSave(), the actual saving of menu links is almost irrelevant ;)
*** 27% is RouteSubscriberBase::onAlterRoutes().
=> We have issues to limit the number of dfac() calls, looks like views ui tests add another call to the 3 common ones.
* DrupalKernel::buildContainer() is called 264 times in total, taking ~13% of the time. Looks like the whole compiler pass stuff takes up a lot of time, especially AnalyzeServiceReferencesPass is a slow one with 5% of the total execution time.
Comment #17
moshe weitzman commentedNice data!
Good news. All those file reads and yaml parsing is slated to go away completely with #2161591: Change default active config from file storage to DB storage.
Comment #18
berdirNope, it's not. That is
*only*config *schema*. Unless you want to move that to the database too? And even if we would, we'd still have to read from yml to put it in the database in the first place. Wouldn't change anything.Clarification: The actual yaml parsing calls are everything, but 75% of the config yaml parsing is config schema. And only meant that with those 20%, all FileStorage::read() is ~25%.
Comment #19
berdir#2171683: Remove all Simpletest overrides and rely on native multi-site functionality instead has apparently slowed down tests, the only thing I could find is that it now uses the Database cache during the installer, which leads to a ton of cache tag delete queries. Opened #2194273: Avoid repeated cache tag deletions to deal with that.
Comment #20
wim leers#16: impressive research — thank you!
I'm working on fixing/improving cache tags, one of the things I'll look into is cache tag deletion/invalidation performance. But… it seems like you've already fixed it at #2194273: Avoid repeated cache tag deletions? :)
Having worked on #2179083: Rendered menus (e.g. menu blocks) should set cache tags to inform the page cache, it was pretty obvious that the menu/menu link cache handling is a transitional state, I think it should be feasible to at least significantly clean that up, which would make it more understandable/prepared for perf improvements, and hopefully that'll lead to some perf wins already.
Comment #21
cameron tod commentedIs this addressed by #1851234: Slow yaml parsing slows down tests which load/save many config files (e.g. views)?
Comment #22
berdirDid some new tests, we did achieve some nice improvements over the last days.
It also looks like a number of other issues like the improved extension parsing and other issues (menu_router removal possibly? improved testbot run times a lot, the fast bots are currently < 30min, which is pretty impressive!
Comparing to the previous results is tricky as quite a few things changed including the total runtime went down quite a bit (3m22, but not sure if I had xdebug enabled then), a few notes:
* Cache::deleteTags() is down to ~1% of the whole runtime
** What's even more interesting is that 35% of that is drupal_get_complete_schema(), I just re-rolled #2185015: Remove SchemaCache and CacheArray which now removes that tag.
** Another 35% is caused by Drupal\Core\Config\CachedStorage::write(), aka the listByPrefix cache, I want to try and switch to a CacheCollector there... That tag is also deleted *a lot* on actual sites. (Should we reset those numbers on a full cache clear? Otherwise they'd climb forever?)
Config reading is actually up in terms of percentage, because that's not much faster, in comparison to improvements that were made elsewhere. But as mentioned before, there is probably quite some overhead hidden in all those method calls.
* Config::save() is 25% of the whole execution time now, 90% of that spent in typed config/type casting.
* FileStorage::read() is 32% of the time, a large part of it through save()/typed config, so those two numbers overlap a lot.
Enabling the yaml extension and trying again, total execution time is 2m17:
* Config::save() is now down to 3%
* FileStorage::read() is <1%.
To figure out how much of that is xhprof overhead, disabling it and running tests again:
With yaml extension: 1 min 51 sec (2m17 with xhprof)
Without: 2 min 48 sec ( 3m22 with xhprof)
Xhprof or not, the yaml extension makes an impressive difference, at least for tests.
Edit: Using the yaml extension needs the patch from #1920902: Add a Drupal Yaml wrapper so we can default to PECL Yaml component if it is available.
Comment #23
sunNot sure why this did not appear in profiling yet: #2209817: Duplicate initialization of maintenance theme registry
Comment #24
moshe weitzman commentedWould be great to get a new round of profiling here. It usually turns up new stuff. We still do a slow container rebuild for each module enable.
Comment #25
yesct commentedComment #34
cilefen commentedIt looks like tests may be under one hour now and this is anyway far out of date. Close?
Comment #38
quietone commentedCan across this and checked the latest test run on Drupal 10.1.x and it was under 1 year. I agree with @cilefen suggestion from 2 years ago.
Comment #39
xjmYeah, let's do this.