Issue #3396196 by catch, kristiaanvandeneynde, Kingdutch: Separate cache...

Issue #3396196 by catch, kristiaanvandeneynde, Kingdutch: Separate cache operations from database queries in OpenTelemetry and assertions

core/modules/system/tests/modules/performance_test/performance_test.services.yml

@@ -7,3 +7,8 @@ services:
     arguments: ['@database']
     tags:
       - { name: http_middleware, priority: 1000, responder: true }
+  performance_test.cache_factory:
+    class: Drupal\performance_test\Cache\CacheFactoryDecorator
+    public: false
+    decorates: cache_factory
+    arguments: ['@performance_test.cache_factory.inner', '@Drupal\performance_test\PerformanceDataCollector']

core/modules/system/tests/modules/performance_test/src/Cache/CacheBackendDecorator.php

+<?php
+
+declare(strict_types = 1);
+
+namespace Drupal\performance_test\Cache;
+
+use Drupal\Core\Cache\Cache;
+use Drupal\Core\Cache\CacheBackendInterface;
+use Drupal\Core\Cache\CacheTagsInvalidatorInterface;
+use Drupal\performance_test\PerformanceDataCollector;
+
+/**
+ * Wraps an existing cache backend to track calls to the cache backend.
+ */
+class CacheBackendDecorator implements CacheBackendInterface, CacheTagsInvalidatorInterface {
+
+  public function __construct(protected readonly PerformanceDataCollector $performanceDataCollector, protected readonly CacheBackendInterface $cacheBackend, protected readonly string $bin) {}
+
+  /**
+   * Logs a cache operation.
+   *
+   * @param string|array $cids
+   *   The cache IDs.
+   * @param float $start
+   *   The start microtime.
+   * @param float $stop
+   *   The stop microtime.
+   * @param string $operation
+   *   The type of operation being logged.
+   *
+   * @return void
+   */
+  protected function logCacheOperation(string|array $cids, float $start, float $stop, string $operation): void {
+    $this->performanceDataCollector->addCacheOperation([
+      'operation' => $operation,
+      'cids' => implode(', ', (array) $cids),
+      'bin' => $this->bin,
+      'start' => $start,
+      'stop' => $stop,
+    ]);
+  }
+
+  /**
+   * {@inheritdoc}
+   */
+  public function get($cid, $allow_invalid = FALSE): object|bool {
+    $start = microtime(TRUE);
+    $cache = $this->cacheBackend->get($cid, $allow_invalid);
+    $stop = microtime(TRUE);
+    $this->logCacheOperation($cid, $start, $stop, 'get');
+    return $cache;
+  }
+
+  /**
+   * {@inheritdoc}
+   */
+  public function getMultiple(&$cids, $allow_invalid = FALSE): array {
+    $cids_copy = $cids;
+    $start = microtime(TRUE);
+    $cache = $this->cacheBackend->getMultiple($cids, $allow_invalid);
+    $stop = microtime(TRUE);
+    $this->logCacheOperation($cids_copy, $start, $stop, 'getMultiple');
+
+    return $cache;
+  }
+
+  /**
+   * {@inheritdoc}
+   */
+  public function set($cid, $data, $expire = Cache::PERMANENT, array $tags = []) {
+    $start = microtime(TRUE);
+    $this->cacheBackend->set($cid, $data, $expire, $tags);
+    $stop = microtime(TRUE);
+    $this->logCacheOperation($cid, $start, $stop, 'set');
+  }
+
+  /**
+   * {@inheritdoc}
+   */
+  public function setMultiple(array $items) {
+    $cids = array_keys($items);
+    $start = microtime(TRUE);
+    $this->cacheBackend->setMultiple($items);
+    $stop = microtime(TRUE);
+    $this->logCacheOperation($cids, $start, $stop, 'setMultiple');
+  }
+
+  /**
+   * {@inheritdoc}
+   */
+  public function delete($cid) {
+    $start = microtime(TRUE);
+    $this->cacheBackend->delete($cid);
+    $stop = microtime(TRUE);
+    $this->logCacheOperation($cid, $start, $stop, 'delete');
+  }
+
+  /**
+   * {@inheritdoc}
+   */
+  public function deleteMultiple(array $cids) {
+    $start = microtime(TRUE);
+    $this->cacheBackend->deleteMultiple($cids);
+    $stop = microtime(TRUE);
+    $this->logCacheOperation($cids, $start, $stop, 'deleteMultiple');
+  }
+
+  /**
+   * {@inheritdoc}
+   */
+  public function deleteAll() {
+    $start = microtime(TRUE);
+    $this->cacheBackend->deleteAll();
+    $stop = microtime(TRUE);
+    $this->logCacheOperation([], $start, $stop, 'deleteAll');
+  }
+
+  /**
+   * {@inheritdoc}
+   */
+  public function invalidate($cid) {
+    $start = microtime(TRUE);
+    $this->cacheBackend->invalidate($cid);
+    $stop = microtime(TRUE);
+    $this->logCacheOperation($cid, $start, $stop, 'invalidate');
+  }
+
+  /**
+   * {@inheritdoc}
+   */
+  public function invalidateMultiple(array $cids) {
+    $start = microtime(TRUE);
+    $this->cacheBackend->invalidateMultiple($cids);
+    $stop = microtime(TRUE);
+    $this->logCacheOperation($cids, $start, $stop, 'invalidateMultiple');
+  }
+
+  /**
+   * {@inheritdoc}
+   */
+  public function invalidateTags(array $tags) {
+    if ($this->cacheBackend instanceof CacheTagsInvalidatorInterface) {
+      $this->cacheBackend->invalidateTags($tags);
+    }
+  }
+
+  /**
+   * {@inheritdoc}
+   */
+  public function invalidateAll() {
+    $start = microtime(TRUE);
+    $this->cacheBackend->invalidateAll();
+    $stop = microtime(TRUE);
+    $this->logCacheOperation([], $start, $stop, 'invalidateAll');
+  }
+
+  /**
+   * {@inheritdoc}
+   */
+  public function garbageCollection() {
+    $this->cacheBackend->garbageCollection();
+  }
+
+  /**
+   * {@inheritdoc}
+   */
+  public function removeBin() {
+    $this->cacheBackend->removeBin();
+  }
+
+}

core/modules/system/tests/modules/performance_test/src/Cache/CacheFactoryDecorator.php

+<?php
+
+declare(strict_types = 1);
+
+namespace Drupal\performance_test\Cache;
+
+use Drupal\Core\Cache\CacheBackendInterface;
+use Drupal\Core\Cache\CacheFactoryInterface;
+use Drupal\Core\Cache\MemoryCache\MemoryCacheInterface;
+use Drupal\Core\Cache\MemoryBackend;
+use Drupal\performance_test\PerformanceDataCollector;
+
+/**
+ * Decorates a cache factory to register all calls to the cache system.
+ */
+class CacheFactoryDecorator implements CacheFactoryInterface {
+
+  /**
+   * All wrapped cache backends.
+   *
+   * @var \Drupal\performance_data\Cache\CacheBackendDecorator[]
+   */
+  protected array $cacheBackends = [];
+
+  public function __construct(protected readonly CacheFactoryInterface $cacheFactory, protected readonly PerformanceDataCollector $performanceDataCollector) {}
+
+  /**
+   * {@inheritdoc}
+   */
+  public function get($bin): CacheBackendInterface {
+    if (!isset($this->cacheBackends[$bin])) {
+      $cache_backend = $this->cacheFactory->get($bin);
+      // Don't log memory cache operations.
+      if (!$cache_backend instanceof MemoryCacheInterface && !$cache_backend instanceof MemoryBackend) {
+        $this->cacheBackends[$bin] = new CacheBackendDecorator($this->performanceDataCollector, $cache_backend, $bin);
+      }
+      else {
+        $this->cacheBackends[$bin] = $cache_backend;
+      }
+    }
+
+    return $this->cacheBackends[$bin];
+  }
+
+}

core/modules/system/tests/modules/performance_test/src/PerformanceDataCollector.php

@@ -15,6 +15,11 @@ class PerformanceDataCollector implements EventSubscriberInterface, Destructable
    */
   protected array $databaseEvents = [];
 
+  /**
+   * Cache operations collected during the request.
+   */
+  protected array $cacheOperations = [];
+
   /**
    * {@inheritdoc}
    */
@@ -32,6 +37,13 @@ public function onStatementExecutionEnd(StatementExecutionEndEvent $event): void
     $this->databaseEvents[] = $event;
   }
 
+  /**
+   * Adds a cache operation.
+   */
+  public function addCacheOperation(array $operation) {
+    $this->cacheOperations[] = $operation;
+  }
+
   /**
    * {@inheritdoc}
    */
@@ -40,12 +52,24 @@ public function destruct(): void {
     // logging does not become part of the recorded data.
     $database_events = $this->databaseEvents;
 
-    // Deliberately do not use an injected key value service to avoid any
-    // overhead up until this point.
+    // Deliberately do not use an injected key value or lock service to avoid
+    // any overhead up until this point.
+    $lock = \Drupal::lock();
+
+    // This loop should be safe because we know a very finite number of requests
+    // will be trying to acquire a lock at any one time.
+    while (!$lock->acquire('performance_test')) {
+      $lock->wait();
+    }
     $collection = \Drupal::keyValue('performance_test');
-    $existing_data = $collection->get('performance_test_data') ?? ['database_events' => []];
+    $existing_data = $collection->get('performance_test_data') ?? [
+      'database_events' => [],
+      'cache_operations' => [],
+    ];
     $existing_data['database_events'] = array_merge($existing_data['database_events'], $database_events);
+    $existing_data['cache_operations'] = array_merge($existing_data['cache_operations'], $this->cacheOperations);
     $collection->set('performance_test_data', $existing_data);
+    $lock->release('performance_test');
   }
 
 }

core/profiles/demo_umami/tests/src/FunctionalJavascript/OpenTelemetryAuthenticatedPerformanceTest.php

@@ -35,9 +35,8 @@ public function testFrontPageAuthenticatedWarmCache(): void {
     $performance_data = $this->collectPerformanceData(function () {
       $this->drupalGet('<front>');
     }, 'authenticatedFrontPage');
-    $this->assertLessThanOrEqual(16, $performance_data->getQueryCount());
-    $this->assertGreaterThanOrEqual(15, $performance_data->getQueryCount());
-    $this->assertSame(15, $performance_data->getCacheGetCount());
+    $this->assertSame(15, $performance_data->getQueryCount());
+    $this->assertSame(43, $performance_data->getCacheGetCount());
     $this->assertSame(0, $performance_data->getCacheSetCount());
     $this->assertSame(0, $performance_data->getCacheDeleteCount());
   }

core/profiles/standard/tests/src/FunctionalJavascript/StandardPerformanceTest.php

@@ -53,18 +53,11 @@ public function testAnonymous() {
     // Test frontpage.
     $performance_data = $this->collectPerformanceData(function () {
       $this->drupalGet('');
-    });
+    }, 'standardFrontPage');
     $this->assertNoJavaScript($performance_data);
-    // This test observes a variable number of cache operations and database
-    // queries, so to avoid  random test failures, assert greater than equal
-    // the highest and lowest number of observed during test runs.
-    // See https://www.drupal.org/project/drupal/issues/3402610
-    $this->assertGreaterThanOrEqual(58, $performance_data->getQueryCount());
-    $this->assertLessThanOrEqual(68, $performance_data->getQueryCount());
-    $this->assertGreaterThanOrEqual(129, $performance_data->getCacheGetCount());
-    $this->assertLessThanOrEqual(132, $performance_data->getCacheGetCount());
-    $this->assertGreaterThanOrEqual(59, $performance_data->getCacheSetCount());
-    $this->assertLessThanOrEqual(68, $performance_data->getCacheSetCount());
+    $this->assertSame(66, $performance_data->getQueryCount());
+    $this->assertSame(135, $performance_data->getCacheGetCount());
+    $this->assertSame(47, $performance_data->getCacheSetCount());
     $this->assertSame(0, $performance_data->getCacheDeleteCount());
 
     // Test node page.
@@ -73,17 +66,9 @@ public function testAnonymous() {
     });
     $this->assertNoJavaScript($performance_data);
 
-    // This test observes a variable number of cache operations and database
-    // queries, so to avoid  random test failures, assert greater than equal
-    // the highest and lowest number of observed during test runs.
-    // See https://www.drupal.org/project/drupal/issues/3402610
-
-    $this->assertGreaterThanOrEqual(38, $performance_data->getQueryCount());
-    $this->assertLessThanOrEqual(39, $performance_data->getQueryCount());
-    $this->assertGreaterThanOrEqual(87, $performance_data->getCacheGetCount());
-    $this->assertLessThanOrEqual(88, $performance_data->getCacheGetCount());
-    $this->assertGreaterThanOrEqual(20, $performance_data->getCacheSetCount());
-    $this->assertLessThanOrEqual(28, $performance_data->getCacheSetCount());
+    $this->assertSame(38, $performance_data->getQueryCount());
+    $this->assertSame(94, $performance_data->getCacheGetCount());
+    $this->assertSame(16, $performance_data->getCacheSetCount());
     $this->assertSame(0, $performance_data->getCacheDeleteCount());
 
     // Test user profile page.
@@ -93,15 +78,8 @@ public function testAnonymous() {
     });
     $this->assertNoJavaScript($performance_data);
     $this->assertSame(40, $performance_data->getQueryCount());
-
-    // This test observes a variable number of cache gets and sets, so to avoid
-    // random test failures, assert greater than equal the highest and lowest
-    // number of queries observed during test runs.
-    // See https://www.drupal.org/project/drupal/issues/3402610
-    $this->assertGreaterThanOrEqual(74, $performance_data->getCacheGetCount());
-    $this->assertLessThanOrEqual(80, $performance_data->getCacheGetCount());
-    $this->assertGreaterThanOrEqual(19, $performance_data->getCacheSetCount());
-    $this->assertLessThanOrEqual(27, $performance_data->getCacheSetCount());
+    $this->assertSame(80, $performance_data->getCacheGetCount());
+    $this->assertSame(16, $performance_data->getCacheSetCount());
     $this->assertSame(0, $performance_data->getCacheDeleteCount());
   }
 
@@ -127,15 +105,9 @@ public function testLogin(): void {
       $this->submitLoginForm($account);
     });
 
-    // This test observes a variable number of database queries, so to avoid
-    // random test failures, assert greater than equal the highest and lowest
-    // number of queries observed during test runs.
-    // See https://www.drupal.org/project/drupal/issues/3402610
-    $this->assertLessThanOrEqual(42, $performance_data->getQueryCount());
-    $this->assertGreaterThanOrEqual(38, $performance_data->getQueryCount());
-    $this->assertSame(28, $performance_data->getCacheGetCount());
-    $this->assertLessThanOrEqual(2, $performance_data->getCacheSetCount());
-    $this->assertGreaterThanOrEqual(1, $performance_data->getCacheSetCount());
+    $this->assertSame(38, $performance_data->getQueryCount());
+    $this->assertSame(62, $performance_data->getCacheGetCount());
+    $this->assertSame(1, $performance_data->getCacheSetCount());
     $this->assertSame(1, $performance_data->getCacheDeleteCount());
   }
 
@@ -163,17 +135,9 @@ public function testLoginBlock(): void {
     $performance_data = $this->collectPerformanceData(function () use ($account) {
       $this->submitLoginForm($account);
     });
-    $this->assertLessThanOrEqual(51, $performance_data->getQueryCount());
-    $this->assertGreaterThanOrEqual(47, $performance_data->getQueryCount());
-    // This test observes a variable number of cache operations, so to avoid random
-    // test failures, assert greater than equal the highest and lowest number
-    // observed during test runs.
-    // See https://www.drupal.org/project/drupal/issues/3402610
-    $this->assertLessThanOrEqual(32, $performance_data->getCacheGetCount());
-    $this->assertGreaterThanOrEqual(30, $performance_data->getCacheGetCount());
-
-    $this->assertLessThanOrEqual(4, $performance_data->getCacheSetCount());
-    $this->assertGreaterThanOrEqual(1, $performance_data->getCacheSetCount());
+    $this->assertSame(47, $performance_data->getQueryCount());
+    $this->assertSame(83, $performance_data->getCacheGetCount());
+    $this->assertSame(1, $performance_data->getCacheSetCount());
     $this->assertSame(1, $performance_data->getCacheDeleteCount());
   }
 

core/tests/Drupal/Tests/PerformanceTestTrait.php

@@ -124,28 +124,23 @@ public function collectPerformanceData(callable $callable, ?string $service_name
       $cache_set_count = 0;
       $cache_delete_count = 0;
       foreach ($performance_test_data['database_events'] as $event) {
-        if (isset($event->caller['class']) && is_a(str_replace('\\\\', '\\', $event->caller['class']), '\Drupal\Core\Cache\DatabaseBackend', TRUE)) {
-          $method = strtolower($event->caller['function']);
-          if (str_contains($method, 'get')) {
-            $cache_get_count++;
-          }
-          elseif (str_contains($method, 'set')) {
-            $cache_set_count++;
-          }
-          elseif (str_contains($method, 'delete')) {
-            $cache_delete_count++;
-          }
-          elseif ($event->caller['function'] === 'ensureBinExists') {
-            // Don't record anything for ensureBinExists().
-          }
-          else {
-            throw new \Exception("Tried to record a cache operation but did not recognize {$event->caller['function']}");
-          }
-        }
-        else {
+        // Don't log queries from the database cache backend because they're
+        // logged separately as cache operations.
+        if (!(isset($event->caller['class']) && is_a(str_replace('\\\\', '\\', $event->caller['class']), '\Drupal\Core\Cache\DatabaseBackend', TRUE))) {
           $query_count++;
         }
       }
+      foreach ($performance_test_data['cache_operations'] as $operation) {
+        if (in_array($operation['operation'], ['get', 'getMultiple'], TRUE)) {
+          $cache_get_count++;
+        }
+        elseif (in_array($operation['operation'], ['set', 'setMultiple'], TRUE)) {
+          $cache_set_count++;
+        }
+        elseif (in_array($operation['operation'], ['delete', 'deleteMultiple'], TRUE)) {
+          $cache_delete_count++;
+        }
+      }
       $performance_data->setQueryCount($query_count);
       $performance_data->setCacheGetCount($cache_get_count);
       $performance_data->setCacheSetCount($cache_set_count);
@@ -344,6 +339,9 @@ private function openTelemetryTracing(array $messages, string $service_name): vo
       $performance_test_data = $collection->get('performance_test_data');
       $query_events = $performance_test_data['database_events'] ?? [];
       foreach ($query_events as $key => $event) {
+        if (isset($event->caller['class']) && is_a(str_replace('\\\\', '\\', $event->caller['class']), '\Drupal\Core\Cache\DatabaseBackend', TRUE)) {
+          continue;
+        }
         // Use the first part of the database query for the span name.
         $query_span = $tracer->spanBuilder(substr($event->queryString, 0, 64))
           ->setStartTimestamp((int) ($event->startTime * $nanoseconds_per_second))
@@ -353,6 +351,17 @@ private function openTelemetryTracing(array $messages, string $service_name): vo
           ->startSpan();
         $query_span->end((int) ($event->time * $nanoseconds_per_second));
       }
+      $cache_operations = $performance_test_data['cache_operations'] ?? [];
+      foreach ($cache_operations as $operation) {
+        $cache_span = $tracer->spanBuilder($operation['operation'] . ' ' . $operation['bin'])
+          ->setStartTimestamp((int) ($operation['start'] * $nanoseconds_per_second))
+          ->setAttribute('cache.operation', $operation['operation'])
+          ->setAttribute('cache.cids', $operation['cids'])
+          ->setAttribute('cache.bin', $operation['bin'])
+          ->startSpan();
+        $cache_span->end((int) ($operation['stop'] * $nanoseconds_per_second));
+      }
+
       $lcp_timestamp = NULL;
       $fcp_timestamp = NULL;
       $lcp_size = 0;