Merge pull request #1 from BedrockStreaming/feat/early-expiry

Add back early expiry feature from symfony & add a few debug logs

README.md

@@ -20,6 +20,7 @@ bedrock_stale_cache:
         stale_cache_service_id:                    # Desired id for this new stale cache instance
             cache_pool: cache_pool_id              # Cache pool on top of which stale cache will be used 
             max_stale: 3600                        # Stale period duration, in seconds
+            enable_debug_logs: true                # Optional (defaults to false), produce a bunch of debug logs
 ```
 
 It will declare a `@stale_cache_service_id`, that you can use as an injected dependency.
@@ -37,9 +38,10 @@ The method `allowStaleCacheUsage` can be used for some custom logic, or you can
 
 A `Bedrock\StaleCacheBundle\Event\StaleCacheUsage` event is sent on stale cache usage. It is strongly advised to log it, with the associated error.
 
-### Remarks
+### Logs
 
-This bundle disables [the stampede prevention from Symfony Cache](https://symfony.com/doc/current/components/cache.html#stampede-prevention).
+Debug logs can be enabled to ensure correct stale cache usage.
+It should not be enabled in a production environment since it can cause performance issue.
 
 ## Contribute
 

composer.json

@@ -25,6 +25,7 @@
   "require": {
     "php": "^7.4 || ^8.0",
     "psr/event-dispatcher": "^1.0",
+    "psr/log": "^1 || ^2 || ^3",
     "symfony/dependency-injection": "^4.4 || ^5.4 || ^6.0" ,
     "symfony/http-kernel": "^4.4 || ^5.4 || ^6.0",
     "symfony/cache-contracts": "^1.0 || ^2.0",

src/Cache/Stale.php

@@ -7,6 +7,7 @@
 use Bedrock\StaleCacheBundle\Event\StaleCacheUsage;
 use Bedrock\StaleCacheBundle\Exception\UnavailableResourceException;
 use Psr\EventDispatcher\EventDispatcherInterface;
+use Psr\Log\LoggerInterface;
 use Symfony\Component\Cache\CacheItem;
 use Symfony\Contracts\Cache\CacheInterface;
 use Symfony\Contracts\Cache\ItemInterface;
@@ -20,16 +21,20 @@ class Stale implements TagAwareCacheInterface
 
     private int $maxStale;
 
+    private ?LoggerInterface $logger;
+
     private ?int $defaultLifetime = null;
 
     public function __construct(
         CacheInterface $internalCache,
         EventDispatcherInterface $dispatcher,
-        int $maxStale
+        int $maxStale,
+        ?LoggerInterface $logger = null
     ) {
         $this->internalCache = $internalCache;
         $this->dispatcher = $dispatcher;
         $this->maxStale = $maxStale;
+        $this->logger = $logger;
     }
 
     /**
@@ -53,18 +58,36 @@ public function get(string $key, callable $callback, float $beta = null, array &
         // $beta = 0 to disable early recompute
         $value = $this->internalCache->get($key, $callbackWithIncreasedCacheTime, 0, $metadata);
 
-        // If value is cached and we're in stale mode, try to force recomputing it
-        // Ignore correctly marked exceptions: this is where the stale mode should work as a fallback
-        if ($isHit && $this->isStale($metadata)) {
+        $recompute = false;
+        if ($this->isStale($metadata)) {
+            $this->logDebugMessage('Value is stale, try to recompute it', $key);
+            $recompute = true;
+        }
+
+        if (!$recompute && $this->shouldTriggerEarlyCacheExpiry($metadata, $beta)) {
+            $this->logDebugMessage('Value elected to early expiration, try to recompute it', $key);
+            $recompute = true;
+        }
+
+        if ($isHit && $recompute) {
             try {
                 // $beta = \INF to force an early recompute
                 $value = $this->internalCache->get($key, $callbackWithIncreasedCacheTime, \INF, $metadata);
             } catch (UnavailableResourceException $exception) {
                 if (!$exception->allowStaleCacheUsage()) {
+                    $this->logDebugMessage('Cannot fallback to stale mode', $key, $exception);
                     throw $exception;
                 }
 
-                $this->dispatcher->dispatch(new StaleCacheUsage($exception));
+                $this->logDebugMessage('Fallback to stale mode', $key, $exception);
+                $this->dispatcher->dispatch(new StaleCacheUsage($exception, $key));
+            } catch (\Throwable $throwable) {
+                $this->logDebugMessage(
+                    sprintf('Exception %s do not allow stale cache, it will be rethrown', get_class($throwable)),
+                    $key, $throwable
+                );
+
+                throw $throwable;
             }
         }
 
@@ -120,4 +143,31 @@ private function isStale(?array $metadata): bool
 
         return ($currentExpiry - $this->maxStale) < microtime(true);
     }
+
+    /**
+     * @param ?array{"expiry"?: ?int, "ctime"?: ?int} $metadata
+     */
+    private function shouldTriggerEarlyCacheExpiry(?array $metadata, ?float $beta): bool
+    {
+        $expiry = $metadata[ItemInterface::METADATA_EXPIRY] ?? null;
+        $ctime = $metadata[ItemInterface::METADATA_CTIME] ?? null;
+
+        if ($expiry === null || $ctime === null) {
+            return false;
+        }
+
+        // See https://github.com/symfony/cache-contracts/blob/aa79ac322ca42cfed7d744cb55777b9425a93d2d/CacheTrait.php#L58
+        // The random part is between about -19 and 0 (averaging around -1),
+        // ctime should not be that big (a few hundreds of ms, depending on time to compute the item),
+        // so with beta = 1,
+        // it should be triggered a few hundreds of ms before due time.
+        return ($expiry - $this->maxStale) <= microtime(true) - $ctime / 1000 * $beta * log(random_int(1, \PHP_INT_MAX) / \PHP_INT_MAX);
+    }
+
+    private function logDebugMessage(string $message, string $cacheKey, ?\Throwable $throwable = null): void
+    {
+        if ($this->logger) {
+            $this->logger->debug($message, ['cache_key' => $cacheKey, 'exception' => $throwable]);
+        }
+    }
 }

src/DependencyInjection/AddStaleCacheLifetime.php

@@ -33,7 +33,7 @@ public function process(ContainerBuilder $container): void
      */
     private function findCachePoolDefaultLifetime(string $cachePool, array $cachePoolServices): ?int
     {
-        foreach ($cachePoolServices as $serviceId => $tags) {
+        foreach ($cachePoolServices as $tags) {
             foreach ($tags as $tag) {
                 if (array_key_exists('name', $tag) && $tag['name'] === $cachePool) {
                     return $tag['default_lifetime'] ?? null;

src/DependencyInjection/BedrockStaleCacheExtension.php

@@ -36,5 +36,11 @@ private function configureStaleCacheService(ContainerBuilder $container, string
         $definition->setAutoconfigured(true);
         $definition->setAutowired(true);
         $definition->addTag('bedrock_stale_cache.stale_cache', $options);
+
+        // By default, disable debug logs
+        $enableDebugLogs = $options['enable_debug_logs'] ?? false;
+        if (!$enableDebugLogs) {
+            $definition->setArgument('$logger', null);
+        }
     }
 }

src/Event/StaleCacheUsage.php

@@ -10,14 +10,21 @@
 class StaleCacheUsage extends Event
 {
     private UnavailableResourceException $exception;
+    private string $cacheKey;
 
-    public function __construct(UnavailableResourceException $exception)
+    public function __construct(UnavailableResourceException $exception, string $cacheKey)
     {
         $this->exception = $exception;
+        $this->cacheKey = $cacheKey;
     }
 
     public function getException(): UnavailableResourceException
     {
         return $this->exception;
     }
+
+    public function getCacheKey(): string
+    {
+        return $this->cacheKey;
+    }
 }