Cache stampede prevention fails when calculation time is less than a second #33837
Description
Symfony version(s) affected: 4.3.4
Description
When using cache contracts, if the callback that generates the data to cache takes less than a second to run, the stampede prevention logic will never fire.
How to reproduce
I'm not quite sure how to demonstrate this as a unit test, but I was able to reproduce it using a console command. You can see from the output, the stampede protection doesn't start firing until the delay reaches 1 second.
<?php
namespace App\Command;
use Psr\Log\LoggerInterface;
use Symfony\Component\Cache\Adapter\FilesystemAdapter;
use Symfony\Component\Console\Command\Command;
use Symfony\Component\Console\Input\InputInterface;
use Symfony\Component\Console\Output\OutputInterface;
use Symfony\Contracts\Cache\ItemInterface;
class TestStampede extends Command
{
protected static $defaultName = 'test:stampede';
protected $logger;
public function __construct(LoggerInterface $logger)
{
parent::__construct();
$this->logger = $logger;
}
protected function execute(InputInterface $input, OutputInterface $output)
{
$cache = new FilesystemAdapter(
'test',
0,
'/tmp/test'
);
$cache->setLogger($this->logger);
foreach ([100000, 500000, 900000, 1000000] as $delay) {
$this->logger->info('running with a {delay}s delay', [
'delay' => sprintf('%0.2f', $delay / 1000000.0)
]);
$key = 'test-' . random_int(1, PHP_INT_MAX);
for ($x = 0; $x < 1000000; $x++) {
$value = $cache->get($key, function (ItemInterface $item) use ($delay) {
$item->expiresAfter(15);
usleep($delay);
return 'test.data';
});
}
}
}
}run with bin/console -vv test:stampede
Note that this will push load up on your machine, because we're brute forcing our way in to the stampede protection.
Possible Solution
The easiest way I've found to fix this is to adjust the math that calculates CTIME in Symfony\Component\Cache\Traits\ContractsTrait.
Replace
$item->newMetadata[CacheItem::METADATA_CTIME] = $metadata[CacheItem::METADATA_CTIME] = 1000 * (int) ($endTime - $startTime);with
$item->newMetadata[CacheItem::METADATA_CTIME] = $metadata[CacheItem::METADATA_CTIME] = (int) (1000 * ($endTime - $startTime));Additional context
The stampede prevention math in Symfony\Contacts\Cache\CacheTrait is where the other half of this bug lives; the 0 value in $ctime short-circuits the formula that otherwise works brilliantly.