From 847a9bb86d012c09cd0669e5d157d5d8e0e094c5 Mon Sep 17 00:00:00 2001 From: Nicolas Grekas Date: Wed, 3 Apr 2019 11:22:52 +0200 Subject: [PATCH] [Cache] add logs on early-recomputation and locking --- src/Symfony/Component/Cache/LockRegistry.php | 7 ++++++- src/Symfony/Component/Cache/Traits/ContractsTrait.php | 7 ++++--- src/Symfony/Contracts/Cache/CacheTrait.php | 9 +++++++-- 3 files changed, 17 insertions(+), 6 deletions(-) diff --git a/src/Symfony/Component/Cache/LockRegistry.php b/src/Symfony/Component/Cache/LockRegistry.php index 81f7db459f..eee7948aab 100644 --- a/src/Symfony/Component/Cache/LockRegistry.php +++ b/src/Symfony/Component/Cache/LockRegistry.php @@ -11,6 +11,7 @@ namespace Symfony\Component\Cache; +use Psr\Log\LoggerInterface; use Symfony\Contracts\Cache\CacheInterface; use Symfony\Contracts\Cache\ItemInterface; @@ -75,7 +76,7 @@ final class LockRegistry return $previousFiles; } - public static function compute(callable $callback, ItemInterface $item, bool &$save, CacheInterface $pool, \Closure $setMetadata = null) + public static function compute(callable $callback, ItemInterface $item, bool &$save, CacheInterface $pool, \Closure $setMetadata = null, LoggerInterface $logger = null) { $key = self::$files ? crc32($item->getKey()) % \count(self::$files) : -1; @@ -87,6 +88,7 @@ final class LockRegistry try { // race to get the lock in non-blocking mode if (flock($lock, LOCK_EX | LOCK_NB)) { + $logger && $logger->info('Lock acquired, now computing item "{key}"', ['key' => $item->getKey()]); self::$lockedFiles[$key] = true; $value = $callback($item, $save); @@ -103,6 +105,7 @@ final class LockRegistry return $value; } // if we failed the race, retry locking in blocking mode to wait for the winner + $logger && $logger->info('Item "{key}" is locked, waiting for it to be released', ['key' => $item->getKey()]); flock($lock, LOCK_SH); } finally { flock($lock, LOCK_UN); @@ -114,6 +117,7 @@ final class LockRegistry try { $value = $pool->get($item->getKey(), $signalingCallback, 0); + $logger && $logger->info('Item "{key}" retrieved after lock was released', ['key' => $item->getKey()]); $save = false; return $value; @@ -121,6 +125,7 @@ final class LockRegistry if ($signalingException !== $e) { throw $e; } + $logger && $logger->info('Item "{key}" not found while lock was released, now retrying', ['key' => $item->getKey()]); } } } diff --git a/src/Symfony/Component/Cache/Traits/ContractsTrait.php b/src/Symfony/Component/Cache/Traits/ContractsTrait.php index bd7be08dd5..c91c14d90f 100644 --- a/src/Symfony/Component/Cache/Traits/ContractsTrait.php +++ b/src/Symfony/Component/Cache/Traits/ContractsTrait.php @@ -11,6 +11,7 @@ namespace Symfony\Component\Cache\Traits; +use Psr\Log\LoggerInterface; use Symfony\Component\Cache\Adapter\AdapterInterface; use Symfony\Component\Cache\CacheItem; use Symfony\Component\Cache\Exception\InvalidArgumentException; @@ -40,7 +41,7 @@ trait ContractsTrait public function setCallbackWrapper(?callable $callbackWrapper): callable { $previousWrapper = $this->callbackWrapper; - $this->callbackWrapper = $callbackWrapper ?? function (callable $callback, ItemInterface $item, bool &$save, CacheInterface $pool, \Closure $setMetadata) { + $this->callbackWrapper = $callbackWrapper ?? function (callable $callback, ItemInterface $item, bool &$save, CacheInterface $pool, \Closure $setMetadata, ?LoggerInterface $logger) { return $callback($item, $save); }; @@ -82,13 +83,13 @@ trait ContractsTrait try { $value = $callbackWrapper($callback, $item, $save, $pool, function (CacheItem $item) use ($setMetadata, $startTime, &$metadata) { $setMetadata($item, $startTime, $metadata); - }); + }, $this->logger ?? null); $setMetadata($item, $startTime, $metadata); return $value; } finally { $this->callbackWrapper = $callbackWrapper; } - }, $beta, $metadata); + }, $beta, $metadata, $this->logger ?? null); } } diff --git a/src/Symfony/Contracts/Cache/CacheTrait.php b/src/Symfony/Contracts/Cache/CacheTrait.php index 918d5559b7..7bbdef087e 100644 --- a/src/Symfony/Contracts/Cache/CacheTrait.php +++ b/src/Symfony/Contracts/Cache/CacheTrait.php @@ -13,6 +13,7 @@ namespace Symfony\Contracts\Cache; use Psr\Cache\CacheItemPoolInterface; use Psr\Cache\InvalidArgumentException; +use Psr\Log\LoggerInterface; /** * An implementation of CacheInterface for PSR-6 CacheItemPoolInterface classes. @@ -37,7 +38,7 @@ trait CacheTrait return $this->deleteItem($key); } - private function doGet(CacheItemPoolInterface $pool, string $key, callable $callback, ?float $beta, array &$metadata = null) + private function doGet(CacheItemPoolInterface $pool, string $key, callable $callback, ?float $beta, array &$metadata = null, LoggerInterface $logger = null) { if (0 > $beta = $beta ?? 1.0) { throw new class(sprintf('Argument "$beta" provided to "%s::get()" must be a positive number, %f given.', \get_class($this), $beta)) extends \InvalidArgumentException implements InvalidArgumentException { @@ -52,9 +53,13 @@ trait CacheTrait $expiry = $metadata[ItemInterface::METADATA_EXPIRY] ?? false; $ctime = $metadata[ItemInterface::METADATA_CTIME] ?? false; - if ($recompute = $ctime && $expiry && $expiry <= microtime(true) - $ctime / 1000 * $beta * log(random_int(1, PHP_INT_MAX) / PHP_INT_MAX)) { + if ($recompute = $ctime && $expiry && $expiry <= ($now = microtime(true)) - $ctime / 1000 * $beta * log(random_int(1, PHP_INT_MAX) / PHP_INT_MAX)) { // force applying defaultLifetime to expiry $item->expiresAt(null); + $this->logger && $this->logger->info('Item "{key}" elected for early recomputation {delta}s before its expiration', [ + 'key' => $key, + 'delta' => sprintf('%.1f', $expiry - $now), + ]); } }