Magento2: Config loading locked for a long time

[QuentinFarizon]

Preconditions (*)

Magento : 2.2.8 EE
PHP: 7.1
Redis: 3.2.11

I have an issue with config loading being stalled by the new locking mechanism introduced in 2.2.8 by https://github.com/magento/magento2/commit/8136dd003b0e4052bd5bea2cad48bb03cc930dff
I understand the need for such a locking mechanism, and it would be normal that at some times it locks for a few milliseconds waiting for the new configuration to be inserted (the retry interval is at 100ms, so it should not lock for more than one or two times)
Furthermore, it should be on rare occasions (not on any page/ajax call)

But I observe in production that every calls have to wait for an important number of retries, thus delaying calls by a several hundreds of milliseconds or even seconds.

Please see two examples got using Blackfire (green paddings are calls to usleep in System::lockedLoadData), by calling GET https://afrimarket.bj/customer/section/load/ :

I may not be easy to reproduce since you need a system on heavy load (I do not reproduce it on our staging for example) but I'm open to any idea / suggestion / insight that can help me with the resolution of this issue.

Steps to reproduce (*)

Do any ajax call

Expected result (*)

Not more than one or two calls to usleep in System::lockedLoadData on a given endpoint/page

Actual result (*)

Several calls to usleep in System::lockedLoadData are done on each endpoint/page

Thanks !

[m2-assistant[bot]]

Hi @QuentinFarizonAfrimarket. Thank you for your report.
To help us process this issue please make sure that you provided the following information:

• [ ] Summary of the issue
• [ ] Information on your environment
• [ ] Steps to reproduce
• [ ] Expected and actual results

Please make sure that the issue is reproducible on the vanilla Magento instance following Steps to reproduce. To deploy vanilla Magento instance on our environment, please, add a comment to the issue:

@magento-engcom-team give me 2.3-develop instance - upcoming 2.3.x release

For more details, please, review the Magento Contributor Assistant documentation.

@QuentinFarizonAfrimarket do you confirm that you was able to reproduce the issue on vanilla Magento instance following steps to reproduce?

• [ ] yes
• [ ] no

[m2-assistant[bot]]

Hi @AlexWorking. Thank you for working on this issue.
In order to make sure that issue has enough information and ready for development, please read and check the following instruction: :point_down:

• [ ] 1. Verify that issue has all the required information. (Preconditions, Steps to reproduce, Expected result, Actual result).
  Details

  If the issue has a valid description, the label Issue: Format is valid will be added to the issue automatically. Please, edit issue description if needed, until label Issue: Format is valid appears.

• [ ] 2. Verify that issue has a meaningful description and provides enough information to reproduce the issue. If the report is valid, add Issue: Clear Description label to the issue by yourself.

• [ ] 3. Add Component: XXXXX label(s) to the ticket, indicating the components it may be related to.

• [ ] 4. Verify that the issue is reproducible on 2.3-develop branch

  Details

  - Add the comment @magento-engcom-team give me 2.3-develop instance to deploy test instance on Magento infrastructure.
  - If the issue is reproducible on 2.3-develop branch, please, add the label Reproduced on 2.3.x.
  - If the issue is not reproducible, add your comment that issue is not reproducible and close the issue and _stop verification process here_!
  

• [ ] 5. Verify that the issue is reproducible on 2.2-develop branch.

  Details

  - Add the comment @magento-engcom-team give me 2.2-develop instance to deploy test instance on Magento infrastructure.
  - If the issue is reproducible on 2.2-develop branch, please add the label Reproduced on 2.2.x

• [ ] 6. Add label Issue: Confirmed once verification is complete.

• [ ] 7. Make sure that automatic system confirms that report has been added to the backlog.

[QuentinFarizon]

Please find other examples :

[QuentinFarizon]

I have tried calling flushall on redis to be sure to start with a clean state, with no luck

[mariuscris]

Hello there,

I want to let you know that we have the same issue with our customer shop.

The shop uses:

• 2.3.1 Magento Commerce (EE)
• PHP 7.1.28
• Redis 3.2.11
• MySQL 5.6.36

Here is a screenshot of our new relic detailed issue:

The strange part is that is not occurring all the time.

Thank you.

[QuentinFarizon]

Hello @mariuscris

I have mitigated the issue by patching a behaviour in Enterprise version, where each time a back-office agent restricted to a certain website does any action, it flushes the whole config cache (call to StoreManagerInterface::reinitStores), which needless to say is a very bad idea.

I still see the issue occurring, I suspect there is similar bad code flushing the whole config cache, but haven't been able to track what code was responsible.

[mariuscris]

Hello @QuentinFarizonAfrimarket,

Thank you for your response and helpful suggestion.
I found a way to reproduce this effect in our customer shop.

Every time when you press the "Save config" button from Stores -> Configuration admin page and during this save request you quickly reload separately a shop page (or someone else uses the shop during the request), than we had the above issue with loading time.
Once the save request is done, the next page is loading normally. In our tests we used an admin user with Administrative role. Another mention regarding this test case is that we didn't need to modify a configuration and save it. We kept the same existing config and pressed save button.

I didn't determined what particular code could cause this yet. This issue happened with Production or Developer mode set on, and all caches enabled.

[QuentinFarizon]

Hello @mariuscris
Well what you're describing here is the normal scenario, and the reason they added the locking mechanism.
Before, when you tried to retrieve configurations that were not yet cached in redis, it was retrieved from the database, which could cause massive overload on the database.
Now, it waits for the config to be written in redis, and then retrieves it. I think it's far better this way.

Writing the config to redis should be quick enough (avoiding huge config values, like html snippets, certainly helps) and changing configuration in production is something that you won't do more than a few times a day at worst.

The issue we encountered and why I opened this ticket is that I see this config locking even when not changing/saving the configuration, and at heavy rate (configuration is written to redis several times a minute)

[hostep]

It looks like this PR is trying to resolve this issue I think, it sounds very related at least: https://github.com/magento/magento2/pull/22829
And https://github.com/magento/magento2/issues/22824 is probably a duplicate of this issue.

[QuentinFarizon]

Nice @hostep thanks, it should indeed be an improvement, so that all the requests do not get stuck writing.

But it won't solve (unless I'm mistaken) the fact that there shouldn't be so much config write, when no config is being changed by a human

[ilnytskyi]

We have similar or the same issue during order placement and customer section update

another profile

[ilnytskyi]

Probably found additional way to reproduce the issue when looked through all request profiles in order flow

The module https://amasty.com/custom-order-number-for-magento-2.html#changelog
Cleans the config cache in this url
POST /rest/store_code/V1/guest-carts/Dx7aqUmYJyd9TvcjIro4ZSmDk5qDlY/payment-information
Here is the highlighted timeline from PHP-SPX

@AmastyLtd Could you verify this in your module ? I do not think we need to clean config cache after order placement

[m2-assistant[bot]]

Hi @ihor-sviziev. Thank you for working on this issue.
In order to make sure that issue has enough information and ready for development, please read and check the following instruction: :point_down:

• [ ] 1. Verify that issue has all the required information. (Preconditions, Steps to reproduce, Expected result, Actual result).
  Details

  If the issue has a valid description, the label Issue: Format is valid will be added to the issue automatically. Please, edit issue description if needed, until label Issue: Format is valid appears.

• [ ] 2. Verify that issue has a meaningful description and provides enough information to reproduce the issue. If the report is valid, add Issue: Clear Description label to the issue by yourself.

• [ ] 3. Add Component: XXXXX label(s) to the ticket, indicating the components it may be related to.

• [ ] 4. Verify that the issue is reproducible on 2.4-develop branch

  Details

  - Add the comment @magento give me 2.4-develop instance to deploy test instance on Magento infrastructure.
  - If the issue is reproducible on 2.4-develop branch, please, add the label Reproduced on 2.4.x.
  - If the issue is not reproducible, add your comment that issue is not reproducible and close the issue and _stop verification process here_!

• [ ] 5. Add label Issue: Confirmed once verification is complete.

• [ ] 6. Make sure that automatic system confirms that report has been added to the backlog.

[ihor-sviziev]

@QuentinFarizon thank you for report!
I'm closing this issue as duplicate of https://github.com/magento/magento2/issues/22824, that was already confirmed.