Updated: Comment #1

Problem/Motivation

During the install, on step 9/10,
"Translate configuration",
the batch (Updating configuration translations: 80 von 184 abgeschlossen [80 of 184 completed]) takes a very long time.

5-15 minutes reported by people working with a local installation on their laptops, and 30 minutes reported on shared hosting.

Steps to reproduce

install in the UI
pick a language other than English, for example: Deutsch
click through the next pages.

Proposed resolution

TBD.

Remaining tasks

  • Investigate what is causing the slowness.
  • Discuss a couple possible resolutions.

User interface changes

No.

API changes

Probably no.

Support from Acquia helps fund testing for Drupal Acquia logo

Comments

droplet’s picture

YesCT’s picture

Issue summary: View changes

was able to get the exact name of the step and the step number (make window narrow to get mobile which has step numbers instead of checklist of steps)

YesCT’s picture

fixing tags.

Pancho’s picture

Priority: Normal » Critical
Issue tags: +Needs tests, +Regression

Added to #1744302: [meta] Resolve known performance regressions in Drupal 8. As I stated there, for non-English installs, this might be the most noticeable performance regression at all. New users would get the impression that Drupal 8 is unacceptably slow, so I'd say, D8 can't ship without this being vastly improved. Therefore raising to critical.

Pancho’s picture

Issue tags: -Needs tests, -Regression

Sorry, crossposted.

Anonymous’s picture

i just tried this with italian (one minute) and german (two minutes), so i'm not sure this is critical.

Gábor Hojtsy’s picture

Priority: Critical » Major
pounard’s picture

I did it with french took 20 minutes.

EDIT: It was some days ago, master moved a lot since, I will retry as soon as I some spare time.

Gábor Hojtsy’s picture

@alexpott says that if you try with PECL YAML extension and #1920902: Add a Drupal Yaml wrapper so we can default to PECL Yaml component if it is available, it would be great to see if that improves. I think this used to be *much* quicker. Something happened that slowed this down. Some caches being regenerated, cleared, whatever.

kfritsche’s picture

Assigned: Unassigned » kfritsche

Will try the Yaml Wrapper and report back with some Profile I did yesterday.

kfritsche’s picture

Assigned: Unassigned » kfritsche
Status: Needs review » Active
FileSize
204.04 KB
1.8 KB

I did a run with XHProf added to the index file.
Like expected it created a lot of Profiles. One for each queue item. For the second step we have 184 queue items so we are loading the core a lot.

Looking at one of these queue item runs: (seems all of them are very similar)
Functions which takes the most time are:
2 calls of Drupal\locale\Locale::config() (50.9%)
1 call of Drupal\locale\LocaleTypedConfig::getTranslation() (47.0%)
Called from locale_config_update_multiple().
Called from locale_config_batch_refresh_name().

Drupal\locale\Locale::config() and Drupal\locale\LocaleTypedConfig::getTranslation is cached for every call. I did a quick and dirty try to add 10 items to one batch job. The time the batch job needs for 10 items is more or less the same like the time it needs for 1 item and then its just 19 instead of 184 queue items. Around 6 seconds per item on my machine, which means from 18 minutes to 2 minutes. For 20 items its around 9 seconds and 17 seconds for all items. Attached the XHProf profiles and the patch I worked with.
Best would maybe to find a count for items per queue which works on big machines but also on shared hosts.

----

Seconds approach was testing with #1920902: Add a Drupal Yaml wrapper so we can default to PECL Yaml component if it is available applied and PECL yaml installed and without the patch above, so back to 1 item per queue item.

Looking again at one of these queue item runs: (seems all of them are very similar)
Functions which takes the most time are:
34 calls of Drupal\locale\Locale::config() (30.9%)
11 calls of Drupal\locale\LocaleTypedConfig::getTranslation() (10.9%)
17 calls of Drupal\locale\LocaleConfigManager::get (15.5%)
...
Called from locale_config_update_multiple(). (17 times)
Called from locale_config_batch_refresh_name(). (17 times)

So in one run now 17 queue items are processed in just around 1 seconds which improves the speed alot. With a total of 12 runs with an average of 15 queue items per run.

kfritsche’s picture

Assigned: kfritsche » Unassigned
Status: Active » Needs review

Moving to unassign and set needs review to just check if with the patch something fails. But I think there are no real tests for this, so probably it should go green.

Hope the investigation I posted above helps to figure out how we want to proceed here.

Damien Tournoud’s picture

The analysis in #10 implies that we completely broke the Batch API sometimes recently?

The Batch API is supposed to execute several items in a row until it reaches half of the PHP maximum execution time. As a consequence, we should be executing several of those locale_config_update_multiple(), which, if I read the code correctly, should have essentially the same effect as the patch in #10.

kfritsche’s picture

Thanks for pointing this out.
Maybe thats why different user experience different results here (from 1 to 30 minutes).
Mine is currently set to 30s.

And in the yaml test it worked as it was called around 15 times per run.

pounard’s picture

@#12 Or maybe the PHP time limit is wrongly interpreted?

kfritsche’s picture

Assigned: kfritsche » Unassigned
Status: Active » Needs review

Is it maybe running in progressive? As it comes from a form_submit. And in this case it stops after 1 second which is that what happens at my side.

from batch.inc:

    // If we are in progressive mode, break processing after 1 second.
    if ($batch['progressive'] && timer_read('batch_processing') > 1000) {

This also explains to me why nothing changed after setting execution time to 3000.

Gábor Hojtsy’s picture

Is that a recent change?

kfritsche’s picture

The copied lines of code are there since D6.
Found a Issue for D6/D7 (#638712: Make non-progressive batch operations possible) where it seems that its not even possible to set it to non-progressive. But I never worked with batches in D8 so I don't know where the code mentioned in the linked issue could be now and what this 'progressive' really means for batches... I just wanted to stated this out, as it seems to me the problem here :)

Damien Tournoud’s picture

Yes, that's true. The "half the time limit" actually only apply to "non-progressive" batches. So, and easy fix that should vastly improve the performance of the installation process across the board would be to increase this "abort every 1s to report progress" to "abort every 10s to report progress". Even for very small batches I don't see the point of updating every second.

Gábor Hojtsy’s picture

We could alternatively make this a progressive batch but that would put all the time management into the batch operation... May not be the best.

Kristen Pol’s picture

I just installed in German (no patch) and it was pretty fast... less than 1 minute for the first batch of translations (UI?) and about 2 minutes for the configuration translations (that text wasn't translated into German so I could read that ;)

But, it was definitely faster with the patch. Less than a minute for both rounds of translations.

Yeah! :)

Gábor Hojtsy’s picture

Let's try the option of increasing it to 10s then as Damien suggested? How would that work / improve the situation for people?

Gábor Hojtsy’s picture

Status: Needs review » Needs work
Damien Tournoud’s picture

Status: Needs work » Reviewed & tested by the community

I did some testing yesterday on Commerce Kickstart (Drupal 7):

  • Stock Drupal: 52s initial install + 163s data import
  • Changing the 1000 into a 10000: 43s initial install + 109s data import

So this is clearly hurting us right now. We need to improve how the Batch API works in interactive mode. But that's really orthogonal to this particular issue, so let's get #10 in and improve the general case in a separate issue.

penyaskito’s picture

+++ b/core/modules/locale/locale.bulk.incundefined
@@ -793,8 +793,18 @@ function locale_config_batch_update_components(array $options, $langcodes = arra
+    if ($i % 20 == 0) {

IMHO this should be documented somehow: why 20 and not 25?

https://en.wikipedia.org/wiki/Magic_number_(programming)#Accepted_limited_use_of_magic_numbers

But can be in a follow-up...

Gábor Hojtsy’s picture

Status: Reviewed & tested by the community » Needs work
Damien Tournoud’s picture

It is a batching size, so arguably not a magic number. We don't have the habit of naming those... for example in node_update_8006():

$nids = db_query_range('SELECT nid FROM {node} WHERE nid > :nid AND uuid IS NULL ORDER BY nid ASC', 0, 10, array(':nid' => $sandbox['last']))->fetchCol();
Gábor Hojtsy’s picture

I think a comment would still be great. Something like "We handle 20 config keys at once because config data building in separate requests is very expensive". Any better wording suggestions?

Damien Tournoud’s picture

Quick suggestion:

// During installation the caching of configuration objects is disabled
// so it is very expensive to initialize the config() object on each request.
// We batch a small number of configuration object upgrades together to
// improve the overall performance of the process.
Damien Tournoud’s picture

Title: configuration translation step in the installation takes a reeeeaaallly long time when installing in a non-English language » Configuration translation step in the installation takes a reeeeaaallly long time when installing in a non-English language
penyaskito’s picture

Status: Needs work » Needs review
FileSize
2.08 KB
822 bytes

Added Damien suggestion.

Gábor Hojtsy’s picture

Status: Needs review » Reviewed & tested by the community

This looks stellar. Thanks Damien!

Dries’s picture

Status: Reviewed & tested by the community » Fixed

I didn't see good performance tests in this issue but decided to commit it anyway. It should be faster we just don't know if it is actually fast enough. Given that it is the installer, I'm not too worried about it right now. Thanks!

Status: Fixed » Closed (fixed)

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

Gábor Hojtsy’s picture

Issue tags: -sprint

Yay!

Gábor Hojtsy’s picture

Issue summary: View changes

added related from #1

gg4’s picture