feature #60498 [HttpCache] Add a waiting trace when finding the cache locked (mpdude)

fabpot · fabpot · commit 1152edfcfa65 · 2025-05-30T08:41:20.000+02:00
This PR was squashed before being merged into the 7.4 branch. Discussion ---------- [HttpCache] Add a `waiting` trace when finding the cache locked | Q | A | ------------- | --- | Branch? | 7.3 | Bug fix? | no | New feature? | yes | Deprecations? | no | Issues | | License | MIT This adds a new `waiting` trace that will be recorded by the `HttpCache` when the cache had to wait for another, concurrent request to the same resource to finish first. The information can be used for profiling - a high rate of `waiting` requests means there is a lot of concurrency, so that it might be beneficial to either speed up request processing or consider using `stale-while-revalidate`. Commits ------- 79d8097 [HttpCache] Add a `waiting` trace when finding the cache locked
diff --git a/src/Symfony/Component/HttpKernel/CHANGELOG.md b/src/Symfony/Component/HttpKernel/CHANGELOG.md
@@ -4,11 +4,12 @@ CHANGELOG
 7.3
 ---
 
+ * Record a `waiting` trace in the `HttpCache` when the cache had to wait for another request to finish
  * Add `$key` argument to `#[MapQueryString]` that allows using a specific key for argument resolving
  * Support `Uid` in `#[MapQueryParameter]`
  * Add `ServicesResetterInterface`, implemented by `ServicesResetter`
  * Allow configuring the logging channel per type of exceptions in ErrorListener
- 
+
 7.2
 ---
 
diff --git a/src/Symfony/Component/HttpKernel/HttpCache/HttpCache.php b/src/Symfony/Component/HttpKernel/HttpCache/HttpCache.php
@@ -558,6 +558,8 @@ protected function lock(Request $request, Response $entry): bool
             return true;
         }
 
+        $this->record($request, 'waiting');
+
         // wait for the lock to be released
         if ($this->waitForLock($request)) {
             // replace the current entry with the fresh one
diff --git a/src/Symfony/Component/HttpKernel/Tests/HttpCache/HttpCacheTest.php b/src/Symfony/Component/HttpKernel/Tests/HttpCache/HttpCacheTest.php
@@ -17,6 +17,7 @@
 use Symfony\Component\HttpKernel\Event\TerminateEvent;
 use Symfony\Component\HttpKernel\HttpCache\Esi;
 use Symfony\Component\HttpKernel\HttpCache\HttpCache;
+use Symfony\Component\HttpKernel\HttpCache\Store;
 use Symfony\Component\HttpKernel\HttpCache\StoreInterface;
 use Symfony\Component\HttpKernel\HttpKernelInterface;
 use Symfony\Component\HttpKernel\Kernel;
@@ -662,6 +663,7 @@ public function testDegradationWhenCacheLocked()
          */
         sleep(10);
 
+        $this->store = $this->createStore(); // create another store instance that does not hold the current lock
         $this->request('GET', '/');
         $this->assertHttpKernelIsNotCalled();
         $this->assertEquals(200, $this->response->getStatusCode());
@@ -680,6 +682,32 @@ public function testDegradationWhenCacheLocked()
         $this->assertEquals('Old response', $this->response->getContent());
     }
 
+    public function testTraceAddedWhenCacheLocked()
+    {
+        if ('\\' === \DIRECTORY_SEPARATOR) {
+            $this->markTestSkipped('Skips on windows to avoid permissions issues.');
+        }
+
+        // Disable stale-while-revalidate, which circumvents blocking access
+        $this->cacheConfig['stale_while_revalidate'] = 0;
+
+        // The presence of Last-Modified makes this cacheable
+        $this->setNextResponse(200, ['Cache-Control' => 'public, no-cache', 'Last-Modified' => 'some while ago'], 'Old response');
+        $this->request('GET', '/'); // warm the cache
+
+        $primedStore = $this->store;
+
+        $this->store = $this->createMock(Store::class);
+        $this->store->method('lookup')->willReturnCallback(fn (Request $request) => $primedStore->lookup($request));
+        // Assume the cache is locked at the first attempt, but immediately treat the lock as released afterwards
+        $this->store->method('lock')->willReturnOnConsecutiveCalls(false, true);
+        $this->store->method('isLocked')->willReturn(false);
+
+        $this->request('GET', '/');
+
+        $this->assertTraceContains('waiting');
+    }
+
     public function testHitsCachedResponseWithSMaxAgeDirective()
     {
         $time = \DateTimeImmutable::createFromFormat('U', time() - 5);
diff --git a/src/Symfony/Component/HttpKernel/Tests/HttpCache/HttpCacheTestCase.php b/src/Symfony/Component/HttpKernel/Tests/HttpCache/HttpCacheTestCase.php
@@ -30,7 +30,7 @@ abstract class HttpCacheTestCase extends TestCase
     protected $responses;
     protected $catch;
     protected $esi;
-    protected Store $store;
+    protected ?Store $store = null;
 
     protected function setUp(): void
     {
@@ -115,7 +115,9 @@ public function request($method, $uri = '/', $server = [], $cookies = [], $esi =
 
         $this->kernel->reset();
 
-        $this->store = new Store(sys_get_temp_dir().'/http_cache');
+        if (!$this->store) {
+            $this->store = $this->createStore();
+        }
 
         if (!isset($this->cacheConfig['debug'])) {
             $this->cacheConfig['debug'] = true;
@@ -183,4 +185,9 @@ public static function clearDirectory($directory)
 
         closedir($fp);
     }
+
+    protected function createStore(): Store
+    {
+        return new Store(sys_get_temp_dir().'/http_cache');
+    }
 }

Original file line number	Diff line number	Diff line change
`@@ -558,6 +558,8 @@ protected function lock(Request $request, Response $entry): bool`
`558`	`558`	`return true;`
`559`	`559`	`}`
`560`	`560`
	`561`	`+ $this->record($request, 'waiting');`
	`562`	`+`
`561`	`563`	`// wait for the lock to be released`
`562`	`564`	`if ($this->waitForLock($request)) {`
`563`	`565`	`// replace the current entry with the fresh one`