Issue #3421881 by catch, kristiaanvandeneynde, Wim Leers: Track cache tag...

Issue #3421881 by catch, kristiaanvandeneynde, Wim Leers: Track cache tag queries separately in performance tests

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

@@ -12,3 +12,8 @@ services:
     public: false
     decorates: cache_factory
     arguments: ['@performance_test.cache_factory.inner', '@Drupal\performance_test\PerformanceDataCollector']
+  performance_test.cache_tags.invalidator.checksum:
+    class: Drupal\performance_test\Cache\CacheTagsChecksumDecorator
+    public: false
+    decorates: cache_tags.invalidator.checksum
+    arguments: ['@performance_test.cache_tags.invalidator.checksum.inner', '@Drupal\performance_test\PerformanceDataCollector']

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

+<?php
+
+declare(strict_types=1);
+
+namespace Drupal\performance_test\Cache;
+
+/**
+ * The cache tag operations we are tracking as part of our performance data.
+ *
+ * @see \Drupal\Core\Cache\CacheTagsChecksumInterface
+ * @see \Drupal\Core\Cache\CacheTagsInvalidatorInterface
+ */
+enum CacheTagOperation {
+  case getCurrentChecksum;
+  case invalidateTags;
+  case isValid;
+}

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

+<?php
+
+declare(strict_types=1);
+
+namespace Drupal\performance_test\Cache;
+
+use Drupal\Core\Cache\CacheTagsChecksumInterface;
+use Drupal\Core\Cache\CacheTagsInvalidatorInterface;
+use Drupal\performance_test\PerformanceDataCollector;
+
+/**
+ * Wraps an existing cache tags checksum invalidator to track calls separately.
+ */
+class CacheTagsChecksumDecorator implements CacheTagsChecksumInterface, CacheTagsInvalidatorInterface {
+
+  public function __construct(protected readonly CacheTagsChecksumInterface $checksumInvalidator, protected readonly PerformanceDataCollector $performanceDataCollector) {}
+
+  /**
+   * {@inheritdoc}
+   */
+  public function getCurrentChecksum(array $tags) {
+    $start = microtime(TRUE);
+    $return = $this->checksumInvalidator->getCurrentChecksum($tags);
+    $stop = microtime(TRUE);
+    $this->logCacheTagOperation($tags, $start, $stop, CacheTagOperation::getCurrentChecksum);
+    return $return;
+  }
+
+  /**
+   * {@inheritdoc}
+   */
+  public function isValid($checksum, array $tags) {
+    $start = microtime(TRUE);
+    $return = $this->checksumInvalidator->isValid($checksum, $tags);
+    $stop = microtime(TRUE);
+    $this->logCacheTagOperation($tags, $start, $stop, CacheTagOperation::isValid);
+    return $return;
+  }
+
+  /**
+   * {@inheritdoc}
+   */
+  public function invalidateTags(array $tags) {
+    $start = microtime(TRUE);
+    $return = $this->checksumInvalidator->invalidateTags($tags);
+    $stop = microtime(TRUE);
+    $this->logCacheTagOperation($tags, $start, $stop, CacheTagOperation::invalidateTags);
+    return $return;
+  }
+
+  /**
+   * {@inheritdoc}
+   */
+  public function reset() {
+    $this->checksumInvalidator->reset();
+  }
+
+  /**
+   * Logs a cache tag operation.
+   *
+   * @param string[] $tags
+   *   The cache tags.
+   * @param float $start
+   *   The start microtime.
+   * @param float $stop
+   *   The stop microtime.
+   * @param \Drupal\performance_test\Cache\CacheTagOperation $operation
+   *   The type of operation being logged.
+   *
+   * @return void
+   */
+  protected function logCacheTagOperation(array $tags, float $start, float $stop, CacheTagOperation $operation): void {
+    $this->performanceDataCollector->addCacheTagOperation([
+      'operation' => $operation,
+      'tags' => implode(', ', $tags),
+      'start' => $start,
+      'stop' => $stop,
+    ]);
+  }
+
+}

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

@@ -20,6 +20,11 @@ class PerformanceDataCollector implements EventSubscriberInterface, Destructable
    */
   protected array $cacheOperations = [];
 
+  /**
+   * Cache tag operations collected during the request.
+   */
+  protected array $cacheTagOperations = [];
+
   /**
    * {@inheritdoc}
    */
@@ -44,6 +49,13 @@ public function addCacheOperation(array $operation) {
     $this->cacheOperations[] = $operation;
   }
 
+  /**
+   * Adds a cache tag operation.
+   */
+  public function addCacheTagOperation(array $operation) {
+    $this->cacheTagOperations[] = $operation;
+  }
+
   /**
    * {@inheritdoc}
    */
@@ -65,9 +77,11 @@ public function destruct(): void {
     $existing_data = $collection->get('performance_test_data') ?? [
       'database_events' => [],
       'cache_operations' => [],
+      'cache_tag_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);
+    $existing_data['cache_tag_operations'] = array_merge($existing_data['cache_tag_operations'], $this->cacheTagOperations);
     $collection->set('performance_test_data', $existing_data);
     $lock->release('performance_test');
   }

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

@@ -35,11 +35,14 @@ public function testFrontPageAuthenticatedWarmCache(): void {
     $performance_data = $this->collectPerformanceData(function () {
       $this->drupalGet('<front>');
     }, 'authenticatedFrontPage');
-    $this->assertGreaterThanOrEqual(15, $performance_data->getQueryCount());
-    $this->assertLessThanOrEqual(17, $performance_data->getQueryCount());
+    $this->assertGreaterThanOrEqual(10, $performance_data->getQueryCount());
+    $this->assertLessThanOrEqual(12, $performance_data->getQueryCount());
     $this->assertSame(45, $performance_data->getCacheGetCount());
     $this->assertSame(0, $performance_data->getCacheSetCount());
     $this->assertSame(0, $performance_data->getCacheDeleteCount());
+    $this->assertSame(0, $performance_data->getCacheTagChecksumCount());
+    $this->assertSame(54, $performance_data->getCacheTagIsValidCount());
+    $this->assertSame(0, $performance_data->getCacheTagInvalidationCount());
   }
 
 }

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

@@ -52,10 +52,13 @@ public function testFrontPageHotCache() {
       $this->drupalGet('<front>');
     }, 'umamiFrontPageHotCache');
     $this->assertSession()->pageTextContains('Umami');
-    $this->assertSame(1, $performance_data->getQueryCount());
+    $this->assertSame(0, $performance_data->getQueryCount());
     $this->assertSame(1, $performance_data->getCacheGetCount());
     $this->assertSame(0, $performance_data->getCacheSetCount());
     $this->assertSame(0, $performance_data->getCacheDeleteCount());
+    $this->assertSame(0, $performance_data->getCacheTagChecksumCount());
+    $this->assertSame(1, $performance_data->getCacheTagIsValidCount());
+    $this->assertSame(0, $performance_data->getCacheTagInvalidationCount());
   }
 
   /**

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

@@ -55,10 +55,13 @@ public function testAnonymous() {
       $this->drupalGet('');
     }, 'standardFrontPage');
     $this->assertNoJavaScript($performance_data);
-    $this->assertCountBetween(68, 69, $performance_data->getQueryCount());
+    $this->assertCountBetween(33, 35, $performance_data->getQueryCount());
     $this->assertSame(137, $performance_data->getCacheGetCount());
     $this->assertSame(47, $performance_data->getCacheSetCount());
     $this->assertSame(0, $performance_data->getCacheDeleteCount());
+    $this->assertCountBetween(143, 146, $performance_data->getCacheTagChecksumCount());
+    $this->assertCountBetween(177, 180, $performance_data->getCacheTagIsValidCount());
+    $this->assertSame(0, $performance_data->getCacheTagInvalidationCount());
 
     // Test node page.
     $performance_data = $this->collectPerformanceData(function () {
@@ -66,10 +69,13 @@ public function testAnonymous() {
     });
     $this->assertNoJavaScript($performance_data);
 
-    $this->assertSame(39, $performance_data->getQueryCount());
+    $this->assertSame(13, $performance_data->getQueryCount());
     $this->assertSame(95, $performance_data->getCacheGetCount());
     $this->assertSame(16, $performance_data->getCacheSetCount());
     $this->assertSame(0, $performance_data->getCacheDeleteCount());
+    $this->assertCountBetween(79, 80, $performance_data->getCacheTagChecksumCount());
+    $this->assertCountBetween(149, 150, $performance_data->getCacheTagIsValidCount());
+    $this->assertSame(0, $performance_data->getCacheTagInvalidationCount());
 
     // Test user profile page.
     $user = $this->drupalCreateUser();
@@ -77,10 +83,12 @@ public function testAnonymous() {
       $this->drupalGet('user/' . $user->id());
     });
     $this->assertNoJavaScript($performance_data);
-    $this->assertSame(41, $performance_data->getQueryCount());
+    $this->assertSame(17, $performance_data->getQueryCount());
     $this->assertSame(81, $performance_data->getCacheGetCount());
     $this->assertSame(16, $performance_data->getCacheSetCount());
     $this->assertSame(0, $performance_data->getCacheDeleteCount());
+    $this->assertCountBetween(129, 130, $performance_data->getCacheTagIsValidCount());
+    $this->assertSame(0, $performance_data->getCacheTagInvalidationCount());
   }
 
   /**
@@ -105,10 +113,13 @@ public function testLogin(): void {
       $this->submitLoginForm($account);
     });
 
-    $this->assertCountBetween(38, 43, $performance_data->getQueryCount());
+    $this->assertCountBetween(26, 31, $performance_data->getQueryCount());
     $this->assertSame(64, $performance_data->getCacheGetCount());
     $this->assertSame(1, $performance_data->getCacheSetCount());
     $this->assertSame(1, $performance_data->getCacheDeleteCount());
+    $this->assertSame(1, $performance_data->getCacheTagChecksumCount());
+    $this->assertSame(69, $performance_data->getCacheTagIsValidCount());
+    $this->assertSame(0, $performance_data->getCacheTagInvalidationCount());
   }
 
   /**
@@ -135,10 +146,13 @@ public function testLoginBlock(): void {
     $performance_data = $this->collectPerformanceData(function () use ($account) {
       $this->submitLoginForm($account);
     });
-    $this->assertCountBetween(49, 52, $performance_data->getQueryCount());
+    $this->assertCountBetween(31, 34, $performance_data->getQueryCount());
     $this->assertSame(85, $performance_data->getCacheGetCount());
     $this->assertSame(1, $performance_data->getCacheSetCount());
     $this->assertSame(1, $performance_data->getCacheDeleteCount());
+    $this->assertSame(1, $performance_data->getCacheTagChecksumCount());
+    $this->assertSame(107, $performance_data->getCacheTagIsValidCount());
+    $this->assertSame(0, $performance_data->getCacheTagInvalidationCount());
   }
 
   /**

core/tests/Drupal/Tests/PerformanceData.php

@@ -41,6 +41,21 @@ class PerformanceData {
    */
   protected int $cacheDeleteCount = 0;
 
+  /**
+   * The number of cache tag checksum checks.
+   */
+  protected int $cacheTagChecksumCount = 0;
+
+  /**
+   * The number of cache tag validity checks.
+   */
+  protected int $cacheTagIsValidCount = 0;
+
+  /**
+   * The number of cache tag invalidations.
+   */
+  protected int $cacheTagInvalidationCount = 0;
+
   /**
    * The original return value.
    */
@@ -166,6 +181,66 @@ public function getCacheDeleteCount(): int {
     return $this->cacheDeleteCount;
   }
 
+  /**
+   * Sets the cache tag checksum count.
+   *
+   * @param int $count
+   *   The number of cache tag checksum checks recorded.
+   */
+  public function setCacheTagChecksumCount(int $count): void {
+    $this->cacheTagChecksumCount = $count;
+  }
+
+  /**
+   * Gets the cache tag checksum count.
+   *
+   * @return int
+   *   The number of cache tag checksum checks recorded.
+   */
+  public function getCacheTagChecksumCount(): int {
+    return $this->cacheTagChecksumCount;
+  }
+
+  /**
+   * Sets the cache tag isValid count.
+   *
+   * @param int $count
+   *   The number of cache tag isValid checks recorded.
+   */
+  public function setCacheTagIsValidCount(int $count): void {
+    $this->cacheTagIsValidCount = $count;
+  }
+
+  /**
+   * Gets the cache tag isValid count.
+   *
+   * @return int
+   *   The number of cache tag isValid checks recorded.
+   */
+  public function getCacheTagIsValidCount(): int {
+    return $this->cacheTagIsValidCount;
+  }
+
+  /**
+   * Sets the cache tag invalidation count.
+   *
+   * @param int $count
+   *   The number of cache tag invalidations recorded.
+   */
+  public function setCacheTagInvalidationCount(int $count): void {
+    $this->cacheTagInvalidationCount = $count;
+  }
+
+  /**
+   * Gets the cache tag invalidation count.
+   *
+   * @return int
+   *   The number of cache tag invalidations recorded.
+   */
+  public function getCacheTagInvalidationCount(): int {
+    return $this->cacheTagInvalidationCount;
+  }
+
   /**
    * Sets the original return value.
    *

core/tests/Drupal/Tests/PerformanceTestTrait.php

@@ -4,6 +4,7 @@
 
 namespace Drupal\Tests;
 
+use Drupal\performance_test\Cache\CacheTagOperation;
 use OpenTelemetry\API\Trace\SpanKind;
 use OpenTelemetry\Contrib\Otlp\OtlpHttpTransportFactory;
 use OpenTelemetry\Contrib\Otlp\SpanExporter;
@@ -123,10 +124,17 @@ public function collectPerformanceData(callable $callable, ?string $service_name
       $cache_get_count = 0;
       $cache_set_count = 0;
       $cache_delete_count = 0;
+      $cache_tag_is_valid_count = 0;
+      $cache_tag_invalidation_count = 0;
+      $cache_tag_checksum_count = 0;
       foreach ($performance_test_data['database_events'] as $event) {
         // 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))) {
+        $database_cache = FALSE;
+        if (isset($event->caller['class'])) {
+          $database_cache = is_a(str_replace('\\\\', '\\', $event->caller['class']), '\Drupal\Core\Cache\DatabaseBackend', TRUE) || is_a(str_replace('\\\\', '\\', $event->caller['class']), 'Drupal\Core\Cache\DatabaseCacheTagsChecksum', TRUE);
+        }
+        if (!$database_cache) {
           $query_count++;
         }
       }
@@ -141,10 +149,20 @@ public function collectPerformanceData(callable $callable, ?string $service_name
           $cache_delete_count++;
         }
       }
+      foreach ($performance_test_data['cache_tag_operations'] as $operation) {
+        match($operation['operation']) {
+          CacheTagOperation::getCurrentChecksum => $cache_tag_checksum_count++,
+          CacheTagOperation::isValid => $cache_tag_is_valid_count++,
+          CacheTagOperation::invalidateTags => $cache_tag_invalidation_count++,
+        };
+      }
       $performance_data->setQueryCount($query_count);
       $performance_data->setCacheGetCount($cache_get_count);
       $performance_data->setCacheSetCount($cache_set_count);
       $performance_data->setCacheDeleteCount($cache_delete_count);
+      $performance_data->setCacheTagChecksumCount($cache_tag_checksum_count);
+      $performance_data->setCacheTagIsValidCount($cache_tag_is_valid_count);
+      $performance_data->setCacheTagInvalidationCount($cache_tag_invalidation_count);
     }
 
     return $performance_data;
@@ -357,7 +375,7 @@ private function openTelemetryTracing(array $messages, string $service_name): vo
       }
       $cache_operations = $performance_test_data['cache_operations'] ?? [];
       foreach ($cache_operations as $operation) {
-        $cache_span = $tracer->spanBuilder($operation['operation'] . ' ' . $operation['bin'])
+        $cache_span = $tracer->spanBuilder('cache ' . $operation['operation'] . ' ' . $operation['bin'])
           ->setStartTimestamp((int) ($operation['start'] * $nanoseconds_per_second))
           ->setAttribute('cache.operation', $operation['operation'])
           ->setAttribute('cache.cids', $operation['cids'])
@@ -365,6 +383,15 @@ private function openTelemetryTracing(array $messages, string $service_name): vo
           ->startSpan();
         $cache_span->end((int) ($operation['stop'] * $nanoseconds_per_second));
       }
+      $cache_tag_operations = $performance_test_data['cache_tag_operations'] ?? [];
+      foreach ($cache_tag_operations as $operation) {
+        $cache_tag_span = $tracer->spanBuilder('cache_tag ' . $operation['operation']->name . ' ' . $operation['tags'])
+          ->setStartTimestamp((int) ($operation['start'] * $nanoseconds_per_second))
+          ->setAttribute('cache_tag.operation', $operation['operation']->name)
+          ->setAttribute('cache_tag.tags', $operation['tags'])
+          ->startSpan();
+        $cache_tag_span->end((int) ($operation['stop'] * $nanoseconds_per_second));
+      }
 
       $lcp_timestamp = NULL;
       $fcp_timestamp = NULL;