Problem/Motivation

#3259188: Extend post update system to provide themes a way to install newly-required dependencies subscribed Drupal\Core\Update\UpdateRegistryto ConfigEvents::SAVE.

As a result Drupal\Core\Extension\ExtensionDiscovery::scan runs 7 times more often than before. The function is very costly, mainly because Drupal\Core\Extension\Extension::getName using basename to retrieve the extension name form the extension path.

Steps to reproduce

Run a functional test extending BrowserTestBase with config that enables a large number of contrib and core modules (150+).

Proposed resolution

Revert those changes in Drupal 9.x and fix it in Drupal 10.x. In addition, optimize Drupal\Core\Extension\Extension::getName to call basename less often.

Remaining tasks

User interface changes

API changes

Revert API changes from #3259188: Extend post update system to provide themes a way to install newly-required dependencies

Release notes snippet

Comments

phma created an issue. See original summary.

phma’s picture

Issue summary: View changes
StatusFileSize
new753 bytes

Maybe suggesting to revert the change is a little too drastically and we can fix the basename issue to mitigate the problem instead?

cilefen’s picture

Status: Active » Needs review
Issue tags: +Performance
phma’s picture

Status: Needs review » Needs work

The extension name is only retrieved once, so this can't be the solution either.

phma’s picture

While I still haven't found a better solution yet, I can confirm that reverting changes from #3279850: Theme post updates are not recognised when the theme is used in the installer and #3259188: Extend post update system to provide themes a way to install newly-required dependencies cause execution time to go back to what they roughly are with Drupal 9.3.x.

As an example: Our install test took over 6min on my machine with a sqlite database in memory on Drupal 9.4.x. Reverting the above changes brought them back down to about 2.5min again.

phma’s picture

Status: Needs work » Needs review
StatusFileSize
new4.58 KB

I managed to significantly reduce test running times on my local machine by slightly refactoring UpdateRegistry and ExtensionDiscovery .

I also added an option setting variable to enable file cache, which gives additional performance. But even without file cache, tests seem to run almost twice as fast. Would be nice to get some independent testing results though. I'm also wondering if there are any caveats when file cache is enabled.

Changes in the patch:

  1. Since we already retrieve the name of the extension once during Extension discovery, I propose that we pass it as a construct parameter to the Extension object instead of costly generate it from the path every time we request it. We can keep it optional for BC and still use basename() to generate it once if it's missing.
  2. UpdateRegistry::scanExtensionsAndLoadUpdateFiles() could now run multiple times, it's better do store ExtensionDiscovery in a property than constructing it from scratch every time.

Still, I can't get nowhere near the performance unless I complete revert the changes introduced, so there's probably room for more.

phma’s picture

StatusFileSize
new279.42 KB

I ran my test again with profiling enabled. There might be some additional potential for optimization in Drupal\Core\Extension\ExtensionDiscovery::sort and Drupal\Core\Extension\ExtensionDiscovery::process. See screenshot attached.

pooja saraah’s picture

StatusFileSize
new4.7 KB
new603 bytes

Fixed Failed commands on #6
Attached patch

Status: Needs review » Needs work

The last submitted patch, 8: 3294299-8.patch, failed testing. View results

alexpott’s picture

Status: Needs work » Needs review
StatusFileSize
new2.28 KB

@phma really nice find.

+++ b/core/lib/Drupal/Core/Update/UpdateRegistry.php
@@ -279,10 +287,13 @@ public function getModuleUpdateFunctions($module_name) {
-    $extension_discovery = new ExtensionDiscovery($this->root, FALSE, [], $this->sitePath);
-    $module_extensions = $extension_discovery->scan('module');
-    $theme_extensions = $this->includeThemes() ? $extension_discovery->scan('theme') : [];
-    $profile_extensions = $extension_discovery->scan('profile');
+    if (!isset($this->extensionDiscovery)) {
+      $use_file_cache = Settings::get('update_registry_use_file_cache', FALSE);
+      $this->extensionDiscovery = new ExtensionDiscovery($this->root, $use_file_cache, [], $this->sitePath);
+    }
+    $module_extensions = $this->extensionDiscovery->scan('module');
+    $theme_extensions = $this->includeThemes() ? $this->extensionDiscovery->scan('theme') : [];
+    $profile_extensions = $this->extensionDiscovery->scan('profile');

I think we should consider setting file cache to TRUE I think we should be using it here. I'm on the fence about adding an extension discovery as a class property. I think if we do this we should do this in the constructor.

We need to use extension discovery here because this is happening very very early... i.e. before the module handler is updated with the new module info.

I think we can make this much better by limiting the extensions returned by scanExtensionsAndLoadUpdateFiles() in specific circumstances... see patch attached. How does this compare for you?

phma’s picture

@alexpott I sensed that there was something else going on there. Thanks a lot.

With patch #9 I now get Time: 02:51.385, Memory: 18.00 MB.

With patch #6 it was Time: 03:53.055, Memory: 18.00 MB for the same test. Before it would take 6-8min.

When passing the name to Extension object like in #6, I could even get it down to Time: 02:37.555, Memory: 18.00 MB. Maybe we should open another issue for that?

alexpott’s picture

@phma I think it is worth doing these separately. It's really interesting that basename() is so expensive. It would also be great to know what was the test run time with #3259188: Extend post update system to provide themes a way to install newly-required dependencies reverted.

phma’s picture

StatusFileSize
new4.44 KB
new3.77 KB

I reverted all changes related to #3259188: Extend post update system to provide themes a way to install newly-required dependencies and ran my test twice:

Time: 01:51.212, Memory: 18.00 MB
Time: 02:02.254, Memory: 18.00 MB

I noticed that the time it takes to run the tests varies by about 10-20s. There are still a little faster, but it's not as bad as without the patch.

It's hard to say if skipping basename helps much. Profiling might make it look more costly than it actually is. It think the main issue is that it gets called over a billion times. So there should be some potential of saving time. I've attached a new patch which can apply together with #9 as a reference which could be posted as a separate issue.

catch’s picture

+++ b/core/lib/Drupal/Core/Extension/Extension.php
@@ -61,14 +68,17 @@ class Extension {
    */
-  public function __construct($root, $type, $pathname, $filename = NULL) {
+  public function __construct($root, $type, $pathname, $filename = NULL, $name = NULL) {
     // @see \Drupal\Core\Theme\ThemeInitialization::getActiveThemeByName()
     assert($pathname === 'core/core.info.yml' || ($pathname[0] !== '/' && file_exists($root . '/' . $pathname)), sprintf('The file specified by the given app root, relative path and file name (%s) do not exist.', $root . '/' . $pathname));

Should this always be optional or should it be the penultimate argument and deprecate passing NULL?

Status: Needs review » Needs work

The last submitted patch, 13: 3294299-extension-basename-fix-13.patch, failed testing. View results

alexpott’s picture

Status: Needs work » Needs review
StatusFileSize
new2.28 KB

Bringing back #10 as I think this is the patch to commit on this one. And yeah I'm suspicious about the cost of profiling and benefit of the changing the basename. #10 just does not do as much.

We could file a separate issue for #13 but in order to prove that that is necessary I think we'd need to profile it without any profiling tools and just look at raw execution times.

xjm’s picture

Priority: Normal » Major
phma’s picture

StatusFileSize
new6.74 KB
new6.11 KB

I found time to pick this up again after tests seems to have slowed down further on my machine.

I tried to reduce the number of times, the UpdateRegistry scans for extensions by adding an extra flag that skips the scan when called within a loop. We don't have to re-scan it for every single extension we are checking, right? It's unlikely something changes in between those calls.

Running times went from Time:03:01.750, Memory: 18.00 MB to Time: 02:33.451, Memory: 16.00 MB. There have been some changes to the code base and the environment in the meantime, so it's difficult to compare to my previous results. I will also have to do some more profiling with my new patch and compare with my earlier results.

EDIT: Looks like we missed to to describe extension in one of the comments.

alexpott’s picture

StatusFileSize
new2.28 KB

@phma can we do the smaller change that brings us back in line with the before times that's in #16 and make further improvements in separate issues?

I don't think the scan extensions flag is necessary and it add complexity and new ways to fail. Upping #9 again.

mikelutz’s picture

Status: Needs review » Reviewed & tested by the community

Alright, first off, this seems fine. I've gone over it a bit, I see no problems here, just an obvious efficiency improvement code-wise. I wonder if it could be improved slightly more with

    // Limit to a single extension.
    if ($extension && isset($extensions[$extension]) && in_array($extension, $this->enabledExtensions)) {
      $this->loadUpdateFile($extensions[$extension]);
    }
    else {
      $this->loadUpdateFiles($extensions);
    }

Just to avoid looping over all the enabled extensions in loadUpdateFiles() when we know there's only one we are interested in, but we are really talking minimal cycles saved there, and the current patch code is cleaner anyway.

Sadly, I was unable to really get a feel for what this saves in the typical case. I don't have a functional test that enables 150 modules, but I wanted to see what it would do for the typical core test suite and the improvement was not as exciting as I hoped. I ran the migrate MultilingualReviewPage test half a dozen times locally, which enables 10ish modules, and got averages of 39.47s without and 39.23s with this patch, which are well within the range of times this test took locally. Looking at the 3 times Alex posted the same patch, we have Functional test runtimes of 23:18m, 31:42m, 31:02m (avarege of 28:40m) against 9.4, and between the latest branch test and the one from yesterday, we have times of 30.47m and 31.43m for an average of 31:15, but if I take the 23:18 out as an outlier, then with this patch the average is 31:22, again with all the variance of machines we get spot instances of on amazon, its all well within margin of error.

So, I say it's still a good improvement, if not as useful in saving the DA on the AWS bill as I had hoped it would be. It will definitely help for some specialized tests.

borisson_’s picture

Status: Reviewed & tested by the community » Needs review

Thanks for getting those numbers @mikelutz, I think that proves that this is a small but real improvement for core +1

alexpott’s picture

Status: Needs review » Reviewed & tested by the community

There's no indication that #21 meant to un-rtbc this :)

  • catch committed 7bd98dd on 10.0.x
    Issue #3294299 by phma, alexpott, pooja saraah, mikelutz: Regression in...
  • catch committed fea90e5 on 10.1.x
    Issue #3294299 by phma, alexpott, pooja saraah, mikelutz: Regression in...
  • catch committed d6d4e00 on 9.4.x
    Issue #3294299 by phma, alexpott, pooja saraah, mikelutz: Regression in...
  • catch committed d3c4400 on 9.5.x
    Issue #3294299 by phma, alexpott, pooja saraah, mikelutz: Regression in...
catch’s picture

Status: Reviewed & tested by the community » Fixed

Committed/pushed to 10.1.x, cherry-picked to 10.0.x, 9.5.x, and 9.4.x, thanks!

phma’s picture

@alexpott Going with the smaller change was definitely the best way forward!

@catch Thanks for getting this in!

I've opened #3303751: Reduce the number of times Drupal scans for extensions and reposted my patch there as a place for further discussions. I'm not a big fan of the extensions flag either but I still believe there's potential to improve this and gain more speed without compromising on reliability.

Status: Fixed » Closed (fixed)

Automatically closed - issue fixed for 2 weeks with no activity.