Using nested cache contracts can cause deadlock between processes #41130

bvklim · 2021-05-07T14:09:38Z

Symfony version(s) affected: 5.2.*

Description
Using nested cache contracts can cause deadlock between processes

How to reproduce
test-deadlock.php:

#!/usr/bin/env php
<?php

require __DIR__.'/vendor/autoload.php';
use Symfony\Component\Console\Application;
use Symfony\Component\Console\Command\Command;
use Symfony\Component\Console\Input\InputArgument;
use Symfony\Component\Console\Input\InputInterface;
use Symfony\Component\Console\Output\OutputInterface;
use Symfony\Component\Cache\Adapter\MemcachedAdapter;
use Symfony\Contracts\Cache\ItemInterface;

class TestCommand extends Command {
    protected static $defaultName = 'test' ;

    private $keys = [
        'a' => ["abc_5", "def_4"],
        'b' => ["fgh_17", "ijk_21"],
    ];

    public function __construct() {
        $this->cache = new MemcachedAdapter(MemcachedAdapter::createConnection('memcached://localhost'));
        parent::__construct();
    }

    protected function configure() {
        $this->addArgument('key_set', InputArgument::REQUIRED);
    }

    public function execute(InputInterface $input, OutputInterface $output) {
        $key_set = $input->getArgument('key_set');
        $value = $this->cache->get($this->keys[$key_set][0], function (ItemInterface $item) use ($key_set) {
            sleep(10);
            $value2 = $this->cache->get($this->keys[$key_set][1], function (ItemInterface $item) {
                sleep(10);
                $item->expiresAfter(1);
                return 1;
            });
            $item->expiresAfter(1);
            return 1;
        });
        $output->writeln("All done");
        return 0;
    }
}

$app = new Application();
$app->add(new TestCommand());
$app->run();

composer.json:

{
    "require": {
        "symfony/console": "5.2.*",
        "symfony/framework-bundle": "5.2.*"
    }
}

memcached daemon should be running on localhost
run
composer install
if you then run the scripts sequentially,
php test-deadlock.php test a
php test-deadlock.php test b
then they exit correctly, after 20 seconds each
But if run them in parallel in different terminals, they will never finish.
If we look at the locks when the scripts are running, we will see something like this:

$ lslocks | grep php
php             32014 FLOCK 21.6K READ* 0     0   0 /.../vendor/symfony/cache/Adapter/PdoAdapter.php
php             32018 FLOCK 21.6K WRITE 0     0   0 /.../vendor/symfony/cache/Adapter/PdoAdapter.php
php             32018 FLOCK  1.9K READ* 0     0   0 /.../vendor/symfony/cache/Adapter/Psr16Adapter.php
php             32014 FLOCK  1.9K WRITE 0     0   0 /.../vendor/symfony/cache/Adapter/Psr16Adapter.php

Possible Solution
Please make using flock() in cache contract optional, or add to the documentation that using nested cache contracts is dangerous.
Additional context

The text was updated successfully, but these errors were encountered:

nicolas-grekas · 2021-05-19T09:11:22Z

I'm not sure we can fix this in Symfony itself.
What you need to do is to call LockRegistry::setFiles([]) from within your subprocesses to disable locking in them.

n3o77 · 2021-06-17T14:33:02Z

@nicolas-grekas do you think it's possible to have some more checks to display a warning in logs or the profiler? Maybe even throwing an exception instead of a deadlock?

I'm asking because we recently had the same issue. We display some overall statistics which are gathered from more detailed statistics which both are in caches. Under the right circumstances we ran into the same deadlock problem which after some time blocked all our apache workers from closing (keeping them in sending state) which lead to downtimes. Unfortunately it took us quite some time to isolate the problem in a live environment. Not even sure how you would find the issue in some hosting environments where you can't strace processes etc..

nicolas-grekas · 2021-06-17T14:48:08Z

Can you please try this patch and let me know if it work around the issue?

--- a/src/Symfony/Component/Cache/LockRegistry.php
+++ b/src/Symfony/Component/Cache/LockRegistry.php
@@ -83,7 +83,7 @@ final class LockRegistry
     {
         $key = self::$files ? abs(crc32($item->getKey())) % \count(self::$files) : -1;
 
-        if ($key < 0 || (self::$lockedFiles[$key] ?? false) || !$lock = self::open($key)) {
+        if ($key < 0 || (self::$lockedFiles[$key] ?? false) || ($_SERVER['SYMFONY_CACHE_SKIP_LOCK_'.$key] ?? $_ENV['SYMFONY_CACHE_SKIP_LOCK_'.$key] ?? false) || !$lock = self::open($key)) {
             return $callback($item, $save);
         }
 
@@ -95,6 +95,7 @@ final class LockRegistry
                 if ($locked || !$wouldBlock) {
                     $logger && $logger->info(sprintf('Lock %s, now computing item "{key}"', $locked ? 'acquired' : 'not supported'), ['key' => $item->getKey()]);
                     self::$lockedFiles[$key] = true;
+                    $_ENV['SYMFONY_CACHE_SKIP_LOCK_'.$key] = '1';
 
                     $value = $callback($item, $save);
 
@@ -115,6 +116,7 @@ final class LockRegistry
             } finally {
                 flock($lock, \LOCK_UN);
                 unset(self::$lockedFiles[$key]);
+                unset($_ENV['SYMFONY_CACHE_SKIP_LOCK_'.$key]);
             }
             static $signalingException, $signalingCallback;
             $signalingException = $signalingException ?? unserialize("O:9:\"Exception\":1:{s:16:\"\0Exception\0trace\";a:0:{}}");

If yes, can you please submit it in a PR, with a test case ideally?

This is going to work only if you're using the Process component to launch subprocesses btw.

n3o77 · 2021-06-17T14:56:19Z

Sorry if i wasn't clear. This didn't happen to us in a process / command but through a controller action (calling different services which used the cache contract then in a nested manner).

Basically: Controller -> Overall Statistics Service using cache contract -> Detailed Statistics Service using cache contract

nicolas-grekas · 2021-06-17T15:10:42Z

This is not supposed to happen, because a process cannot dead-lock itself. Please share a reproducer if you can!

n3o77 · 2021-06-17T15:34:55Z

I'll try to reproduce it in the next days. But it wasn't that the same process was blocking itself rather than another request which then caused the lock. Basically the same as the example from @bvklim with the command but on different apache processes. Sorry for not having more details for now. I've deployed calling LockRegistry::setFiles([]) in Overall Statistics Service ~6 days ago and since then the problem doesn't happen anymore (before it happened at least twice per day). I'll get back to you asap.

Thank you very much for the help!

n3o77 · 2021-06-21T14:08:53Z

I tried to get this reproduced but so far i didn't manage to. But as soon i remove the LockRegistry::setFiles([]); within a few hours the problem happens again and all apache requests get stuck in sending over time.

What i noticed during testing with the code below is that each request runs longer. So maybe if enough requests are coming in and the "right" cache keys are triggered for a re-calculation things get stuck. In my local example i open the same url in 4 different browsers and i get the following timings:

Request 1: 20s
Request 2: 21s
Request 3: 50.5s
Request 4: 74.5s

As it only happens on a live system and i can't trigger the behavior myself, debugging this in detail is currently not possible.

class TestController extends AbstractController
{

    private $cache;

    public function __construct(TagAwareCacheInterface $cache)
    {
        $this->cache = $cache;
    }

    /**
     * @Route("/test", name="test")
     */
    public function test(): Response
    {
        $value = $this->cache->get('a', function (ItemInterface $item) {
            sleep(10);
            $item->expiresAfter(1);
            return $this->cache->get('b', function (ItemInterface $item) {
                sleep(10);
                $item->expiresAfter(1);

                return 1;
            });
        });

        return $this->render('test.html.twig');
    }

}

nicolas-grekas · 2021-06-21T14:17:15Z

The TTL must not be shorter than the computation time. If that's the case on your system, that's the issue you need to solve.
Do you have a controller that triggers an HTTP request to the same host maybe?

n3o77 · 2021-06-21T14:29:51Z

I will add some more logs to see if a too short TTL is set. As far i'm aware no controllers trigger a request to the same host. Thanks again, much appreciated!

sgehrig · 2021-09-15T15:30:51Z

I can confirm that we experience the same issue. I cannot reproduce this reliably at the moment though - just as @n3o77.
For our case it does not seem to be related to cache item expiration dates or lifetimes because we ensure that the expiration is well beyond the request duration.
Currently I can only say that it happens in production with a Redis backed taggable cache.app (injected via \Symfony\Contracts\Cache\TagAwareCacheInterface). Depending on some circumstances (not sure which currently) the PHP process locks up and finally this drains the PHP-FPM pool until no more workers are available.

nicolas-grekas · 2021-09-15T15:38:27Z

In Symfony 5.4, locks will be done using semaphores. That should help prevent this issue. See #41989

sgehrig · 2021-09-16T06:54:24Z

Thanks @nicolas-grekas for your quick response. Unfortunately the affected application is still on 4.4 (don't look at me like that 😉) so there some way to go to move to 5.4. From an implementation perspective: would switching to Symfony\Component\Cache\Adapter\RedisTagAwareAdapter make anything better? As far as I can see, it'd still use Symfony\Component\Cache\Traits\ContractsTrait and therefore Symfony\Component\Cache\LockRegistry. Correct?

So Symfony\Component\Cache\LockRegistry::setFiles([]) seems to be the only quick fix. Right?

cussack · 2021-10-21T13:12:38Z

I can confirm the issue with nested caching inside parallel AJAX requests and unfortunate key combinations. Reproducing it manually becomes pretty easy if you reduce the amount of files available for locking to only two, but it's still hard to build an automated test case in plain PHP since it's a concurrency issue.

The real issue here is that there's no timeout to the locks, and a timeout would probably do no harm for the use case of a stampede protection.

Wouldn't it be an option to use the great Symfony Lock component (which has a timeout) for stampede protection instead of the custom implementation at hand?

nicolas-grekas · 2021-11-09T19:05:11Z

Wouldn't it be an option to use the great Symfony Lock component

I don't know if it's a good idea but it should be possible to wire the Lock component yes.
Until someone is willing to have a closer look, I only have two solutions:

call LockRegistry::setFiles([])
~~upgrade to 5.4 where semaphores should make this rare~~

Closing meanwhile.

nicolas-grekas · 2021-12-16T16:51:31Z

See #44669 for a fix.

This PR was merged into the 4.4 branch. Discussion ---------- [Cache] disable lock on CLI | Q | A | ------------- | --- | Branch? | 5.4 | Bug fix? | yes | New feature? | no | Deprecations? | | Tickets | Fix #41130 | License | MIT | Doc PR | - I thought using semaphores would fix the linked issue but I'm proposing to revert them in #44667 Instead, I think we should disable the lock on CLI processes. The purpose of having locks enabled by default is to prevent cache stamped at deploy time. Disabling the lock on CLI still provides this protection on eg FPM. For ppl that really want a lock between eg crons and FPM, the lock component should be used instead. Commits ------- b968514 [Cache] disable lock on CLI

qurben · 2021-12-27T10:41:33Z

Maybe it is a good idea to document that nested cache lookups are prone to deadlocks? (Or creating a solution with a reasonable amount of locks.) With only 25 locks available any application which makes extensive use of the Cache component will run into deadlocks, potentially grinding the entire php-fpm process to a halt.

We ran across this bug and had a hard time pinpointing the issue to this specific component. Our server stopped responding to requests after filling up the php-fpm pool. Usually a couple of hours after deploy. The first time we encountered this bug was 24/06/2020, since then it was an occasional nuisance which was fixed by just killing all php-fpm processes (and hoping nobody was doing important stuff, glad we aren't running anything really important). Just a week ago we found out that it had to do with nested cache lookups. For us php-fpm's slowlog option really helped finding this problem, the traces logged by this option clearly showed recursive lookups to the cache as the culprit.

When a deadlock is encountered the pool of available locks (25) becomes even smaller, this makes likelihood of a new deadlock occurring even larger. This starts cascading and using every single lock, making every new process wait and making it very likely that new new deadlocks are created once file locks are cleared (after the processes are killed by php-fpm).

Having such a small amount of locks here doesn't really make sense, cache stampede prevention is about recalculating the same key way to often. In the current implementation, besides preventing this issue for two items with the same key will also limit the global number of concurrent cache recalculations to 25 (if you're unlucky you need much more than 25 processes to fill up this limit). On top of that, the very high likelihood that two different strings share the same key (1/25) will very quickly cause deadlocks when nested cache lookups are used (when exceeding some number of concurrent cache recalculations at the same time of course).

Removing nested cache lookups is fairly straightforward to implement for us, but actually finding that this was a problem took the most time. A solution where the chance of overlapping keys is close to zero would be an even better solution of course.

nicolas-grekas · 2021-12-27T10:48:41Z

Can you describe how lookups are nested in your case? Do you do HTTP requests? Or start external processes (then #44669 should help)? Or?

qurben · 2021-12-27T11:01:36Z

The main thing we are caching are permission strings which can result in a series of database lookups if the permission string mentions multiple groups a user can be a member of (so no http or external processes). These permission checks are done ad-hoc all around the code (if they are not yet cached they will be) and are also done inside computation that is later saved into another part of the cache.

Finding if a user has permission for a specific permission string usually takes only a couple of milliseconds, but happens quite often. On an empty cache hundreds of different permission strings can be calculated.

We can replace permission lookups with an uncached version in specific places, but this increases the complexity of our code and brings the potential that this bug is re-introduced.

cussack · 2021-12-27T11:16:17Z

Sounds like the same issue I had. We are using two levels of caching, one in the controller and one close to the database. Every few weeks we would have a deadlock caused by two simultaneous HTTP requests.

It happened for two requests, one resolving to stampede protection key A in the controller and key B at the database, the other request the other way round.

Although it was hard to track down, the solution was pretty simple, we established a policy that stampede protection may only be enables for caching at the outermost (controller) level, for all other caches we disabled it using setCallbackWrapper(null)

In my opinion a warning bubble in the documentation that mentions the risk of deadlocks would be totally sufficient.

@knorrie

Oke, een korte uiteenzetting van waardoor het komt dat de stek af en toe niet meer wil werken en de op dit moment gevonden oplossing(en). Zoals ik het nu zie gaat het mis als er twee processen zijn die op hetzelfde moment bezig zijn met het berekenen van een waarde in de cache. Het ene proces berekent een waarde met sleutel `a` en heeft voor die waarde een waarde met sleutel `b` nodig, en het andere process berekent een waarde met sleutel `b` en heeft hier een waarde met sleutel `a` nodig. Voordat het systeem een waarde gaat berekenen lockt het proces de sleutel, zodat er geen andere processen dezelfde waarde gaan berekenen, maar netjes wachten totdat het huidige proces klaar is met berekenen. De processen wachten nu op elkaar totdat ze klaar zijn (of totdat ze afgeschoten worden). Oftewel je klassieke [deadlock](https://en.wikipedia.org/wiki/Deadlock) probleem, en ook al worden processen afgeschoten na een paar seconden ontstaat er zo een gigantische wachtrij aan requests dat het bijna onmogelijk is om hier bovenop te komen en zorgt de vloed aan processen er voor dat nieuwe deadlocks ontstaan. Maar hoe kan dit probleem dan ontstaan? In de code hebben we nergens dat er een deadlock zou moeten kunnen ontstaan omdat dingen elkaar nodig hebben bij het vullen van de cache. Als er iets in de cache moet worden gemaakt wordt er inderdaad soms nóg iets nieuws in de cache gezet, maar dit is áltijd kleiner (en heeft dus niet dezelfde sleutel). Er zijn op dit moment twee onderdelen die expliciet cachen: - Menu, deze bevat Permissie (per menu item wordt aangegeven wie deze mag zien) - Permissie, deze bevat een substring van Permissie (bijv: `bestuur,commissie:SocCie` moet `bestuur` en `commissie:SocCie` opzoeken) (noot: in de huidige versie wordt hier geen recursieve cache-lookup meer gedaan) Op deze manier kan niet zomaar een deadlock ontstaan, omdat er geen overlap bestaat in sleutels. (Als a er voor zorgt dat b nodig is, zal het nooit voorkomen dat b er voor zorgt dat a nodig is) Het probleem zit hem vooral in de oude implementatie van het locken in symfony/cache. De locks werden aangemaakt mbv bestanden, er werden 23 bestanden gebruikt om locks te creëren voor het schrijven naar de cache. Waarschijnlijk omdat het te zwaar is om nieuwe bestanden naar de schijf te schrijven en omdat je sowieso zeker weet dat deze bestanden daar staan. De volgende code werd gebruikt om een sleutel te genereren (uit `symfony/cache:5.3`): ```php $key = self::$files ? abs(crc32($item->getKey())) % \count(self::$files) : -1; ``` Dit zorgt ervoor dat er maar 23 verschillende sleutels zijn. Nu is de kans opeens erg groot dat sleutel a een waarde met sleutel b bevat en omgekeerd, het gaat hier namelijk om honderden lookups als een pagina voor het eerst wordt geladen (ongeveer 350 voor de thuispagina met een lege cache). Deze sleutels zijn ook nog eens gedeeld tussen processen. Een nieuwe deploy met een lege cache heeft nu opeens een best grote kans op een deadlock, zeker als er verschillende mensen tegelijk de stek bezoeken en er pagina's met honderden plaatjes parallel geladen worden. De nieuwe logica (met semaphores, aka php's ingebouwde manier van locks fixen zonder bestanden) zijn er zo'n 4.4 miljard verschillende locks te verkrijgen en is de kans op dubbele sleutels véél kleiner geworden. Dit is de code die nu de sleutels genereerd (uit `symfony/cache:5.4`): ```php $key = unpack('i', md5($item->getKey(), true))[1]; ``` De kans dat de md5 hashes van twee verschillende sleutels hetzelfde is is heel erg klein (én dat dit twee keer op hetzelfde moment gebeurt én dat het precies zo gebeurt dat er een deadlock ontstaat). Ik denk dat het voorkomen van geneste cache lookups nog steeds iets is wat we moeten fixen, zodat vergelijkbare problemen niet nog een keer voorkomen. En het uberhaupt niet kan voorkomen dat er eventueel een deadlock ontstaat hier. Helaas is deze verandering weer terug gedraaid omdat semaphores blijkbaar op andere plekken voor onverwachte problemen kunnen zorgen. Deze fout zit dus nog steeds in en dus zijn geneste cache lookups in symfony/cache gevaarlijk omdat ze snel deadlocks kunnen veroorzaken. Daarnaast vraag je je misschien af, waarom zou je het laden van de cache locken? Fix je al deze problemen niet gewoon door potentieel dingen vaker te berekenen, ook al kost dat wat extra rekenkracht. Dit cachen is geimplementeerd om ["Cache Stampede"](https://en.wikipedia.org/wiki/Cache_stampede) te voorkomen. Het idee hiervan is dat bij een lege (of verlopen) cache het kan zijn dat heel veel mensen tegelijk een specifieke waarde willen hebben en dat je de server kan overbelasten als je dit allemaal wil berekenen en dat het dus beter is om de waarde maar één keer te berekenen en de rest maar te laten wachten. In de stek is dit niet een heel erg reeel probleem, maar zou er kunnen zorgen dat de stek nóg meer onder druk komt te staan na een nieuwe deploy, zeker als op een later moment nog meer dingen in een cache belanden (die misschien nog zwaarder zijn om te berekenen). Ik denk dat cache stampede voor ons geen reëel probleem is op dit moment en dat we dit op dit moment kunnen uitzetten. De boel refactoren om vanuit Menu een call te doen naar een niet-gecachede permissie check is misschien ook iets moois om te hebben. Zeker als we op een later moment nog meer coole dingen met de cache gaan doen, maar dan is het misschien ook een goed idee om de cache op te splitsen. Het vinden van deze bug was een flinke klus, de fout was niet zomaar te reproduceren, en soms zat er maanden tussen twee crashes. De laatste weken ging de frequentie omhoog, en daarmee ook de urgentie. Op een gegeven moment konden we wel binnen vijf minuten zeggen dat de stek eruit lag, maar hadden we nog geen idee waar het precies vandaan kwam. Gelukkig kwamen we op een gegeven moment de slowlog optie in de server tegen, deze optie schiet een te lang draaiend proces af én geeft een overzicht van wat dat proces op dat moment aan het doen was. Hierna was het al snel duidelijk waar de fout voorkwam en kon er gericht gezocht worden naar een oplossing (schreeuw uit naar @knorrie voor het instellen van slowlog én het scherp lezen van de logs). Hopelijk is dit de daadwerkelijke oorzaak van deze fout en kunnen we na bijna anderhalf jaar (sinds 24/06/2020!) dit hoofdstuk afsluiten. Linkjes: - Een melding van een vergelijkbaar probleem: symfony/symfony#41130 - De fix voor het aantal sleutels in symfony/cache: symfony/symfony#41989 - Documentatie over slowlog: https://robertbasic.com/blog/php-fpm-slow-log/ - Fix in hasPermission in de stek (en de introductie van een nieuwe bug, kan jij m spotten?): e0b7a66

nicolas-grekas · 2021-12-28T11:00:56Z

Please let me know what you think of #44820

…-grekas) This PR was merged into the 4.4 branch. Discussion ---------- [Cache] Don't lock when doing nested computations | Q | A | ------------- | --- | Branch? | 4.4 | Bug fix? | yes | New feature? | no | Deprecations? | no | Tickets | Fix #41130 | License | MIT | Doc PR | - Commits ------- be8cbd2 [Cache] Don't lock when doing nested computations

qurben · 2021-12-28T15:01:19Z

That'll definitely solve the problem for me. Maybe it's still a nice addition to mention that cache stampede protection and nested cache lookups don't play together nicely?

bvklim added the Bug label May 7, 2021

carsonbot added the Status: Needs Review label May 7, 2021

derrabus added the Cache label May 9, 2021

nicolas-grekas closed this as completed Jun 11, 2021

nicolas-grekas reopened this Jun 17, 2021

nicolas-grekas closed this as completed Nov 9, 2021

nicolas-grekas mentioned this issue Dec 16, 2021

[Cache] disable lock on CLI #44669

Merged

qurben mentioned this issue Dec 27, 2021

Willekeurige crashes na deploy (cache problemen) csrdelft/csrdelft.nl#948

Closed

nicolas-grekas mentioned this issue Dec 28, 2021

[Cache] Don't lock when doing nested computations #44820

Merged

sbelyshkin mentioned this issue Jan 6, 2025

[Cache] TagAwareAdapter and LockRegistry possibly causing deadlocks #59191

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Uh oh!

Using nested cache contracts can cause deadlock between processes #41130

Using nested cache contracts can cause deadlock between processes #41130

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Using nested cache contracts can cause deadlock between processes #41130

Using nested cache contracts can cause deadlock between processes #41130

Comments

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!