From d66403c93dc2625f5bed27e7d954093c594b36cb Mon Sep 17 00:00:00 2001 From: Alex Pott <alex.a.pott@googlemail.com> Date: Thu, 22 Feb 2024 09:29:53 +0000 Subject: [PATCH] Issue #3421881 by catch, kristiaanvandeneynde, Wim Leers: Track cache tag queries separately in performance tests --- .../performance_test.services.yml | 5 ++ .../src/Cache/CacheTagOperation.php | 17 ++++ .../src/Cache/CacheTagsChecksumDecorator.php | 81 +++++++++++++++++++ .../src/PerformanceDataCollector.php | 14 ++++ ...nTelemetryAuthenticatedPerformanceTest.php | 7 +- .../OpenTelemetryFrontPagePerformanceTest.php | 5 +- .../StandardPerformanceTest.php | 24 ++++-- core/tests/Drupal/Tests/PerformanceData.php | 75 +++++++++++++++++ .../Drupal/Tests/PerformanceTestTrait.php | 31 ++++++- 9 files changed, 249 insertions(+), 10 deletions(-) create mode 100644 core/modules/system/tests/modules/performance_test/src/Cache/CacheTagOperation.php create mode 100644 core/modules/system/tests/modules/performance_test/src/Cache/CacheTagsChecksumDecorator.php diff --git a/core/modules/system/tests/modules/performance_test/performance_test.services.yml b/core/modules/system/tests/modules/performance_test/performance_test.services.yml index c1c49e6c24a4..4f095923e14d 100644 --- a/core/modules/system/tests/modules/performance_test/performance_test.services.yml +++ b/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'] diff --git a/core/modules/system/tests/modules/performance_test/src/Cache/CacheTagOperation.php b/core/modules/system/tests/modules/performance_test/src/Cache/CacheTagOperation.php new file mode 100644 index 000000000000..fb96e66a3a09 --- /dev/null +++ b/core/modules/system/tests/modules/performance_test/src/Cache/CacheTagOperation.php @@ -0,0 +1,17 @@ +<?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; +} diff --git a/core/modules/system/tests/modules/performance_test/src/Cache/CacheTagsChecksumDecorator.php b/core/modules/system/tests/modules/performance_test/src/Cache/CacheTagsChecksumDecorator.php new file mode 100644 index 000000000000..489786abcda0 --- /dev/null +++ b/core/modules/system/tests/modules/performance_test/src/Cache/CacheTagsChecksumDecorator.php @@ -0,0 +1,81 @@ +<?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, + ]); + } + +} diff --git a/core/modules/system/tests/modules/performance_test/src/PerformanceDataCollector.php b/core/modules/system/tests/modules/performance_test/src/PerformanceDataCollector.php index 0da0decd61b8..a3fc9edcb71f 100644 --- a/core/modules/system/tests/modules/performance_test/src/PerformanceDataCollector.php +++ b/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'); } diff --git a/core/profiles/demo_umami/tests/src/FunctionalJavascript/OpenTelemetryAuthenticatedPerformanceTest.php b/core/profiles/demo_umami/tests/src/FunctionalJavascript/OpenTelemetryAuthenticatedPerformanceTest.php index d0884c31b705..8e66e7df19ae 100644 --- a/core/profiles/demo_umami/tests/src/FunctionalJavascript/OpenTelemetryAuthenticatedPerformanceTest.php +++ b/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()); } } diff --git a/core/profiles/demo_umami/tests/src/FunctionalJavascript/OpenTelemetryFrontPagePerformanceTest.php b/core/profiles/demo_umami/tests/src/FunctionalJavascript/OpenTelemetryFrontPagePerformanceTest.php index 8e896ebc6575..f56c4a16dc59 100644 --- a/core/profiles/demo_umami/tests/src/FunctionalJavascript/OpenTelemetryFrontPagePerformanceTest.php +++ b/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()); } /** diff --git a/core/profiles/standard/tests/src/FunctionalJavascript/StandardPerformanceTest.php b/core/profiles/standard/tests/src/FunctionalJavascript/StandardPerformanceTest.php index 7f9078a055b0..c977aaf51d1c 100644 --- a/core/profiles/standard/tests/src/FunctionalJavascript/StandardPerformanceTest.php +++ b/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()); } /** diff --git a/core/tests/Drupal/Tests/PerformanceData.php b/core/tests/Drupal/Tests/PerformanceData.php index 4db5c05435e4..bd9d9c8a32f6 100644 --- a/core/tests/Drupal/Tests/PerformanceData.php +++ b/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. * diff --git a/core/tests/Drupal/Tests/PerformanceTestTrait.php b/core/tests/Drupal/Tests/PerformanceTestTrait.php index 5315fd1cbd97..b2d05dfe1f08 100644 --- a/core/tests/Drupal/Tests/PerformanceTestTrait.php +++ b/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; -- GitLab