From a8f52aa253a39d202149b98b418f066e45b9e4a9 Mon Sep 17 00:00:00 2001 From: Alex Pott <alex.a.pott@googlemail.com> Date: Tue, 3 Oct 2023 17:25:30 +0100 Subject: [PATCH] Issue #3352459 by catch, Bhanu951, Wim Leers, smustgrave, Fabianx, heddn, alexpott: Add OpenTelemetry Application Performance Monitoring to core performance tests --- core/misc/cspell/dictionary.txt | 1 + .../NoJavaScriptAnonymousTest.php | 26 +- .../OpenTelemetryFrontPagePerformanceTest.php | 71 ++++ .../OpenTelemetryNodePagePerformanceTest.php | 87 +++++ .../FunctionalJavascript/PerformanceTest.php | 26 +- .../PerformanceTestBase.php | 93 +---- core/tests/Drupal/Tests/PerformanceData.php | 91 +++++ .../Drupal/Tests/PerformanceTestTrait.php | 327 ++++++++++++++++++ 8 files changed, 618 insertions(+), 104 deletions(-) create mode 100644 core/profiles/demo_umami/tests/src/FunctionalJavascript/OpenTelemetryFrontPagePerformanceTest.php create mode 100644 core/profiles/demo_umami/tests/src/FunctionalJavascript/OpenTelemetryNodePagePerformanceTest.php create mode 100644 core/tests/Drupal/Tests/PerformanceData.php create mode 100644 core/tests/Drupal/Tests/PerformanceTestTrait.php diff --git a/core/misc/cspell/dictionary.txt b/core/misc/cspell/dictionary.txt index 7b42dc8b4aa7..a8969359b43f 100644 --- a/core/misc/cspell/dictionary.txt +++ b/core/misc/cspell/dictionary.txt @@ -793,6 +793,7 @@ optin optionchecker orgchart ossp +otel otlp otsikko outdent diff --git a/core/modules/system/tests/src/FunctionalJavascript/NoJavaScriptAnonymousTest.php b/core/modules/system/tests/src/FunctionalJavascript/NoJavaScriptAnonymousTest.php index 6bccdb95a8d5..51fee59063be 100644 --- a/core/modules/system/tests/src/FunctionalJavascript/NoJavaScriptAnonymousTest.php +++ b/core/modules/system/tests/src/FunctionalJavascript/NoJavaScriptAnonymousTest.php @@ -2,6 +2,7 @@ namespace Drupal\Tests\system\FunctionalJavascript; +use Drupal\Tests\PerformanceData; use Drupal\FunctionalJavascriptTests\PerformanceTestBase; use Drupal\node\NodeInterface; @@ -46,30 +47,39 @@ public function testNoJavaScript() { ]); // Test frontpage. - $this->drupalGet(''); - $this->assertNoJavaScript(); + $performance_data = $this->collectPerformanceData(function () { + $this->drupalGet(''); + }); + $this->assertNoJavaScript($performance_data); // Test node page. - $this->drupalGet('node/1'); - $this->assertNoJavaScript(); + $performance_data = $this->collectPerformanceData(function () { + $this->drupalGet('node/1'); + }); + $this->assertNoJavaScript($performance_data); // Test user profile page. $user = $this->drupalCreateUser(); - $this->drupalGet('user/' . $user->id()); - $this->assertNoJavaScript(); + $performance_data = $this->collectPerformanceData(function () use ($user) { + $this->drupalGet('user/' . $user->id()); + }); + $this->assertNoJavaScript($performance_data); } /** * Passes if no JavaScript is found on the page. * + * @param Drupal\Tests\PerformanceData $performance_data + * A PerformanceData value object. + * * @internal */ - protected function assertNoJavaScript(): void { + protected function assertNoJavaScript(PerformanceData $performance_data): void { // Ensure drupalSettings is not set. $settings = $this->getDrupalSettings(); $this->assertEmpty($settings, 'drupalSettings is not set.'); $this->assertSession()->responseNotMatches('/\.js/'); - $this->assertSame(0, $this->scriptCount); + $this->assertSame(0, $performance_data->getScriptCount()); } } diff --git a/core/profiles/demo_umami/tests/src/FunctionalJavascript/OpenTelemetryFrontPagePerformanceTest.php b/core/profiles/demo_umami/tests/src/FunctionalJavascript/OpenTelemetryFrontPagePerformanceTest.php new file mode 100644 index 000000000000..6a16046f0123 --- /dev/null +++ b/core/profiles/demo_umami/tests/src/FunctionalJavascript/OpenTelemetryFrontPagePerformanceTest.php @@ -0,0 +1,71 @@ +<?php + +namespace Drupal\Tests\demo_umami\FunctionalJavascript; + +use Drupal\FunctionalJavascriptTests\PerformanceTestBase; + +/** + * Tests demo_umami profile performance. + * + * @group OpenTelemetry + * @group #slow + */ +class OpenTelemetryFrontPagePerformanceTest extends PerformanceTestBase { + + /** + * {@inheritdoc} + */ + protected $profile = 'demo_umami'; + + /** + * Logs front page tracing data with a cold cache. + */ + public function testFrontPageColdCache() { + // @todo: Chromedriver doesn't collect tracing performance logs for the very + // first request in a test, so warm it up. + // See https://www.drupal.org/project/drupal/issues/3379750 + $this->drupalGet('user/login'); + $this->rebuildAll(); + $this->collectPerformanceData(function () { + $this->drupalGet('<front>'); + }, 'umamiFrontPageColdCache'); + $this->assertSession()->pageTextContains('Umami'); + } + + /** + * Logs front page tracing data with a hot cache. + * + * Hot here means that all possible caches are warmed. + */ + public function testFrontPageHotCache() { + // Request the page twice so that asset aggregates and image derivatives are + // definitely cached in the browser cache. The first response builds the + // file and serves from PHP with private, no-store headers. The second + // request will get the file served directly from disk by the browser with + // cacheable headers, so only the third request actually has the files + // in the browser cache. + $this->drupalGet('<front>'); + $this->drupalGet('<front>'); + $this->collectPerformanceData(function () { + $this->drupalGet('<front>'); + }, 'umamiFrontPageWarmCache'); + } + + /** + * Logs front page tracing data with a lukewarm cache. + * + * Cool here means that 'global' site caches are warm but anything + * specific to the front page is cold. + */ + public function testFrontPageCoolCache() { + // First of all visit the front page to ensure the image style exists. + $this->drupalGet('<front>'); + $this->rebuildAll(); + // Now visit a different page to warm non-route-specific caches. + $this->drupalGet('/user/login'); + $this->collectPerformanceData(function () { + $this->drupalGet('<front>'); + }, 'umamiFrontPageCoolCache'); + } + +} diff --git a/core/profiles/demo_umami/tests/src/FunctionalJavascript/OpenTelemetryNodePagePerformanceTest.php b/core/profiles/demo_umami/tests/src/FunctionalJavascript/OpenTelemetryNodePagePerformanceTest.php new file mode 100644 index 000000000000..d8b22001cf96 --- /dev/null +++ b/core/profiles/demo_umami/tests/src/FunctionalJavascript/OpenTelemetryNodePagePerformanceTest.php @@ -0,0 +1,87 @@ +<?php + +namespace Drupal\Tests\demo_umami\FunctionalJavascript; + +use Drupal\FunctionalJavascriptTests\PerformanceTestBase; + +/** + * Tests demo_umami profile performance. + * + * @group OpenTelemetry + * @group #slow + */ +class OpenTelemetryNodePagePerformanceTest extends PerformanceTestBase { + + /** + * {@inheritdoc} + */ + protected $profile = 'demo_umami'; + + /** + * Logs node page tracing data with a cold cache. + */ + public function testNodePageColdCache() { + // @todo: Chromedriver doesn't collect tracing performance logs for the very + // first request in a test, so warm it up. + // See https://www.drupal.org/project/drupal/issues/3379750 + $this->drupalGet('user/login'); + $this->rebuildAll(); + $this->collectPerformanceData(function () { + $this->drupalGet('/node/1'); + }, 'umamiNodePageColdCache'); + $this->assertSession()->pageTextContains('quiche'); + } + + /** + * Logs node page tracing data with a hot cache. + * + * Hot here means that all possible caches are warmed. + */ + public function testNodePageHotCache() { + // Request the page twice so that asset aggregates are definitely cached in + // the browser cache. + $this->drupalGet('node/1'); + $this->drupalGet('node/1'); + $this->collectPerformanceData(function () { + $this->drupalGet('/node/1'); + }, 'umamiNodePageHotCache'); + $this->assertSession()->pageTextContains('quiche'); + } + + /** + * Logs node/1 tracing data with a cool cache. + * + * Cool here means that 'global' site caches are warm but anything + * specific to the route or path is cold. + */ + public function testNodePageCoolCache() { + // First of all visit the node page to ensure the image style exists. + $this->drupalGet('node/1'); + $this->rebuildAll(); + // Now visit a non-node page to warm non-route-specific caches. + $this->drupalGet('/user/login'); + $this->collectPerformanceData(function () { + $this->drupalGet('/node/1'); + }, 'umamiNodePageCoolCache'); + $this->assertSession()->pageTextContains('quiche'); + } + + /** + * Log node/1 tracing data with a warm cache. + * + * Warm here means that 'global' site caches and route-specific caches are + * warm but caches specific to this particular node/path are not. + */ + public function testNodePageWarmCache() { + // First of all visit the node page to ensure the image style exists. + $this->drupalGet('node/1'); + $this->rebuildAll(); + // Now visit a different node page to warm non-path-specific caches. + $this->drupalGet('/node/2'); + $this->collectPerformanceData(function () { + $this->drupalGet('/node/1'); + }, 'umamiNodePageWarmCache'); + $this->assertSession()->pageTextContains('quiche'); + } + +} diff --git a/core/profiles/demo_umami/tests/src/FunctionalJavascript/PerformanceTest.php b/core/profiles/demo_umami/tests/src/FunctionalJavascript/PerformanceTest.php index 9af5caf95ad6..d89ee8caad95 100644 --- a/core/profiles/demo_umami/tests/src/FunctionalJavascript/PerformanceTest.php +++ b/core/profiles/demo_umami/tests/src/FunctionalJavascript/PerformanceTest.php @@ -7,7 +7,7 @@ /** * Tests demo_umami profile performance. * - * @group performance + * @group Performance */ class PerformanceTest extends PerformanceTestBase { @@ -19,11 +19,19 @@ class PerformanceTest extends PerformanceTestBase { /** * Just load the front page. */ - public function testFrontPage(): void { - $this->drupalGet('<front>'); + public function testPagesAnonymous(): void { + $performance_data = $this->collectPerformanceData(function () { + $this->drupalGet('<front>'); + }); $this->assertSession()->pageTextContains('Umami'); - $this->assertSame(2, $this->stylesheetCount); - $this->assertSame(1, $this->scriptCount); + $this->assertSame(2, $performance_data->getStylesheetCount()); + $this->assertSame(1, $performance_data->getScriptCount()); + + $performance_data = $this->collectPerformanceData(function () { + $this->drupalGet('node/1'); + }); + $this->assertSame(2, $performance_data->getStylesheetCount()); + $this->assertSame(1, $performance_data->getScriptCount()); } /** @@ -32,10 +40,12 @@ public function testFrontPage(): void { public function testFrontPagePerformance(): void { $admin_user = $this->drupalCreateUser(['access toolbar']); $this->drupalLogin($admin_user); - $this->drupalGet('<front>'); + $performance_data = $this->collectPerformanceData(function () { + $this->drupalGet('<front>'); + }); $this->assertSession()->pageTextContains('Umami'); - $this->assertSame(2, $this->stylesheetCount); - $this->assertSame(2, $this->scriptCount); + $this->assertSame(2, $performance_data->getStylesheetCount()); + $this->assertSame(2, $performance_data->getScriptCount()); } } diff --git a/core/tests/Drupal/FunctionalJavascriptTests/PerformanceTestBase.php b/core/tests/Drupal/FunctionalJavascriptTests/PerformanceTestBase.php index 9d247a12b495..b7b2bed33ef6 100644 --- a/core/tests/Drupal/FunctionalJavascriptTests/PerformanceTestBase.php +++ b/core/tests/Drupal/FunctionalJavascriptTests/PerformanceTestBase.php @@ -4,8 +4,7 @@ namespace Drupal\FunctionalJavascriptTests; -use Drupal\Core\Url; -use Drupal\Tests\BrowserTestBase; +use Drupal\Tests\PerformanceTestTrait; use Symfony\Component\DependencyInjection\ContainerInterface; /** @@ -14,110 +13,28 @@ * @ingroup testing */ class PerformanceTestBase extends WebDriverTestBase { - - /** - * The number of stylesheets requested. - */ - protected int $stylesheetCount = 0; - - /** - * The number of scripts requested. - */ - protected int $scriptCount = 0; + use PerformanceTestTrait; /** * {@inheritdoc} */ protected function setUp(): void { parent::setUp(); - \Drupal::configFactory()->getEditable('system.performance') - ->set('css.preprocess', TRUE) - ->set('js.preprocess', TRUE) - ->save(); + $this->doSetUpTasks(); } /** * {@inheritdoc} */ protected function installModulesFromClassProperty(ContainerInterface $container) { - // Bypass everything that WebDriverTestBase does here to get closer to - // a production configuration. - BrowserTestBase::installModulesFromClassProperty($container); + $this->doInstallModulesFromClassProperty($container); } /** * {@inheritdoc} */ protected function getMinkDriverArgs() { - - // Add performance logging preferences to the existing driver arguments to - // avoid clobbering anything set via environment variables. - // @see https://chromedriver.chromium.org/logging/performance-log - $parent_driver_args = parent::getMinkDriverArgs(); - $driver_args = json_decode($parent_driver_args, TRUE); - - $driver_args[1]['goog:loggingPrefs'] = [ - 'browser' => 'ALL', - 'performance' => 'ALL', - 'performanceTimeline' => 'ALL', - ]; - $driver_args[1]['chromeOptions']['perfLoggingPrefs'] = [ - 'traceCategories' => 'devtools.timeline', - 'enableNetwork' => TRUE, - ]; - - return json_encode($driver_args); - } - - /** - * {@inheritdoc} - */ - public function drupalGet($path, array $options = [], array $headers = []): string { - // Reset the performance log from any previous HTTP requests. The log is - // cumulative until it is collected explicitly. - $session = $this->getSession(); - $session->getDriver()->getWebDriverSession()->log('performance'); - $return = parent::drupalGet($path, $options, $headers); - $this->getChromeDriverPerformanceMetrics($path); - return $return; - } - - /** - * Gets the chromedriver performance log and extracts metrics from it. - */ - protected function getChromeDriverPerformanceMetrics(string|Url $path): void { - $session = $this->getSession(); - $performance_log = $session->getDriver()->getWebDriverSession()->log('performance'); - - $messages = []; - foreach ($performance_log as $entry) { - $decoded = json_decode($entry['message'], TRUE); - $messages[] = $decoded['message']; - } - $this->collectNetworkData($path, $messages); - } - - /** - * Prepares data for assertions. - * - * @param string|\Drupal\Core\Url $path - * The path as passed to static::drupalGet(). - * @param array $messages - * The chromedriver performance log messages. - */ - protected function collectNetworkData(string|Url $path, array $messages): void { - $this->stylesheetCount = 0; - $this->scriptCount = 0; - foreach ($messages as $message) { - if ($message['method'] === 'Network.responseReceived') { - if ($message['params']['type'] === 'Stylesheet') { - $this->stylesheetCount++; - } - if ($message['params']['type'] === 'Script') { - $this->scriptCount++; - } - } - } + return $this->doGetMinkDriverArgs(); } } diff --git a/core/tests/Drupal/Tests/PerformanceData.php b/core/tests/Drupal/Tests/PerformanceData.php new file mode 100644 index 000000000000..528fefd81c95 --- /dev/null +++ b/core/tests/Drupal/Tests/PerformanceData.php @@ -0,0 +1,91 @@ +<?php + +namespace Drupal\Tests; + +/** + * Value object to store performance information collected from requests. + * + * @see Drupal\Tests\PerformanceTestTrait::collectPerformanceData(). + */ +class PerformanceData { + + /** + * The number of stylesheets requested. + */ + protected int $stylesheetCount = 0; + + /** + * The number of scripts requested. + */ + protected int $scriptCount = 0; + + /** + * The original return value. + */ + protected $returnValue; + + /** + * Sets the stylesheet request count. + * + * @param int $count + * The number of stylesheet requests recorded. + */ + public function setStylesheetCount(int $count): void { + $this->stylesheetCount = $count; + } + + /** + * Gets the stylesheet request count. + * + * @return int + * The number of stylesheet requests recorded. + */ + public function getStylesheetCount(): int { + return $this->stylesheetCount; + } + + /** + * Sets the script request count. + * + * @param int $count + * The number of script requests recorded. + */ + public function setScriptCount(int $count) { + $this->scriptCount = $count; + } + + /** + * Gets the script request count. + * + * @return int + * The number of script requests recorded. + */ + public function getScriptCount(): int { + return $this->scriptCount; + } + + /** + * Sets the original return value. + * + * @param mixed $return + * The original return value. + */ + public function setReturnValue($return): void { + $this->returnValue = $return; + } + + /** + * Gets the original return value. + * + * PerformanceTestTrait::collectPerformanceData() takes a callable as its + * argument. This method allows the original return value of the callable to + * be retrieved. + * + * @return mixed + * The original return value. + */ + public function getReturnValue() { + return $this->returnValue; + } + +} diff --git a/core/tests/Drupal/Tests/PerformanceTestTrait.php b/core/tests/Drupal/Tests/PerformanceTestTrait.php new file mode 100644 index 000000000000..61a697348077 --- /dev/null +++ b/core/tests/Drupal/Tests/PerformanceTestTrait.php @@ -0,0 +1,327 @@ +<?php + +declare(strict_types = 1); + +namespace Drupal\Tests; + +use OpenTelemetry\API\Trace\SpanKind; +use OpenTelemetry\Contrib\Otlp\OtlpHttpTransportFactory; +use OpenTelemetry\Contrib\Otlp\SpanExporter; +use OpenTelemetry\SDK\Trace\SpanProcessor\SimpleSpanProcessor; +use OpenTelemetry\SDK\Trace\TracerProvider; +use OpenTelemetry\SDK\Resource\ResourceInfo; +use OpenTelemetry\SDK\Resource\ResourceInfoFactory; +use OpenTelemetry\SDK\Common\Attribute\Attributes; +use OpenTelemetry\SemConv\ResourceAttributes; +use Symfony\Component\DependencyInjection\ContainerInterface; + +/** + * Provides various methods to aid in collecting performance data during tests. + * + * @ingroup testing + */ +trait PerformanceTestTrait { + + /** + * Helper for ::setUp(). + * + * Resets configuration to be closer to production settings. + * + * @see \Drupal\Tests\BrowserTestBase::setUp() + */ + private function doSetUpTasks(): void { + \Drupal::configFactory()->getEditable('system.performance') + ->set('css.preprocess', TRUE) + ->set('js.preprocess', TRUE) + ->save(); + } + + /** + * Helper for ::installModulesFromClassProperty(). + * + * To use this, override BrowserTestBase::installModulesFromClassProperty() + * and call this helper. + * + * @see \Drupal\Tests\BrowserTestBase::installModulesFromClassProperty() + */ + private function doInstallModulesFromClassProperty(ContainerInterface $container) { + // Bypass everything that WebDriverTestBase does here to get closer to + // a production configuration. + BrowserTestBase::installModulesFromClassProperty($container); + } + + /** + * Helper for ::getMinkDriverArgs(). + * + * To use this, override BrowserTestBase::getMinkDriverArgs() and call this + * helper. + * + * @return string + * The JSON encoded driver args with performance logging preferences added. + * + * @see \Drupal\Tests\BrowserTestBase::getMinkDriverArgs() + */ + private function doGetMinkDriverArgs(): string { + // Add performance logging preferences to the existing driver arguments to + // avoid clobbering anything set via environment variables. + // @see https://chromedriver.chromium.org/logging/performance-log + $parent_driver_args = parent::getMinkDriverArgs(); + $driver_args = json_decode($parent_driver_args, TRUE); + + $driver_args[1]['goog:loggingPrefs'] = [ + 'browser' => 'ALL', + 'performance' => 'ALL', + 'performanceTimeline' => 'ALL', + ]; + $driver_args[1]['chromeOptions']['perfLoggingPrefs'] = [ + 'traceCategories' => 'timeline,devtools.timeline,browser', + ]; + + return json_encode($driver_args); + } + + /** + * Executes a callable and collects performance data. + * + * @param callable $callable + * A callable, for example ::drupalGet(). + * @param string|null $service_name + * An optional human readable identifier to enable sending traces to an Open + * Telemetry endpoint (if configured). + * + * @return \Drupal\Tests\PerformanceData + * A PerformanceData value object. + */ + public function collectPerformanceData(callable $callable, ?string $service_name = NULL): PerformanceData { + $session = $this->getSession(); + $session->getDriver()->getWebDriverSession()->log('performance'); + $return = $callable(); + $performance_data = $this->processChromeDriverPerformanceLogs($service_name); + if (isset($return)) { + $performance_data->setReturnValue($performance_data); + } + + return $performance_data; + } + + /** + * Gets the chromedriver performance log and extracts metrics from it. + * + * The performance log is cumulative, and is emptied each time it is + * collected. If the log grows to the point it will overflow, it may also be + * emptied resulting in lost messages. There is no specific + * LargestContentfulPaint event, instead there are + * largestContentfulPaint::Candidate events which may be superseded by later + * events. From manual testing none of the core pages result in more than + * two largestContentfulPaint::Candidate events, so we keep looking until + * either two have been sent, or until 30 seconds has passed. + * + * @todo https://www.drupal.org/project/drupal/issues/3379757 + * + * @param string|null $service_name + * An optional human readable identifier so that traces can be grouped together. + * + * @return \Drupal\Tests\PerformanceData + * An instance of the performance data value object. + */ + protected function processChromeDriverPerformanceLogs(?string $service_name): PerformanceData { + $attempts = 0; + $lcp_count = 0; + $messages = []; + $session = $this->getSession(); + while ($attempts <= 30) { + $attempts++; + $performance_log = $session->getDriver()->getWebDriverSession()->log('performance'); + + foreach ($performance_log as $entry) { + $decoded = json_decode($entry['message'], TRUE); + $message = $decoded['message']; + if ($message['method'] === 'Tracing.dataCollected' && $message['params']['name'] === 'largestContentfulPaint::Candidate') { + $lcp_count++; + } + $messages[] = $message; + } + // Only check once if $service_name is not set, since + // largestContentfulPaint is not currently asserted on. + if ($lcp_count === 2 || !isset($service_name)) { + break; + } + sleep(1); + } + $performance_data = new PerformanceData(); + $this->collectNetworkData($messages, $performance_data); + + if (isset($service_name)) { + $this->openTelemetryTracing($messages, $service_name); + } + + return $performance_data; + } + + /** + * Prepares data for assertions. + * + * @param array $messages + * The chromedriver performance log messages. + * @param \Drupal\Tests\PerformanceData $performance_data + * An instance of the performance data value object. + */ + private function collectNetworkData(array $messages, PerformanceData $performance_data): void { + $stylesheet_count = 0; + $script_count = 0; + foreach ($messages as $message) { + if ($message['method'] === 'Network.responseReceived') { + if ($message['params']['type'] === 'Stylesheet') { + $stylesheet_count++; + } + if ($message['params']['type'] === 'Script') { + $script_count++; + } + } + } + $performance_data->setStylesheetCount($stylesheet_count); + $performance_data->setScriptCount($script_count); + } + + /** + * Sends metrics to OpenTelemetry. + * + * @param array $messages + * The ChromeDriver performance log messages. + * @param string $service_name + * A human readable identifier so that traces can be grouped together. + * + * @see https://opentelemetry.io/docs/instrumentation/php/manual/ + */ + private function openTelemetryTracing(array $messages, string $service_name): void { + // Open telemetry timestamps are always in nanoseconds. + // @todo: consider moving these to trait constants once we require PHP 8.2. + $nanoseconds_per_second = 1000_000_000; + $nanoseconds_per_millisecond = 1000_000; + $nanoseconds_per_microsecond = 1000; + + $collector = $_ENV['OTEL_COLLECTOR'] ?? NULL; + if ($collector === NULL) { + return; + } + $timestamp = NULL; + $url = NULL; + $dom_loaded_timestamp_page = NULL; + $dom_loaded_timestamp_timeline = NULL; + $timestamp_since_os_boot = NULL; + foreach ($messages as $message) { + // Since chrome timestamps are since OS start, we take the first network + // request as '0' and calculate offsets against that. + if ($timestamp === NULL && $message['method'] === 'Network.requestWillBeSent') { + $url = $message['url']; + $timestamp = (int) ($message['params']['wallTime'] * $nanoseconds_per_second); + // Network timestamps are formatted as a second float with three point + // precision. Record this so it can be compared against other + // timestamps. + $timestamp_since_os_boot = (int) ($message['params']['timestamp'] * $nanoseconds_per_second); + } + // The DOM content loaded event is in both the 'page' and 'timeline' + // sections of the performance log in different formats. This lets us + // compare 'ts' and 'timestamp' which are not only in two different + // formats, but appear to start from slightly different points in time. + // By subtracting one from the other, we can generate an offset to apply + // to all other 'ts' timestamps. Note that if the two events actually + // happen at different times, then the offset will be wrong by that + // difference. + // See https://bugs.chromium.org/p/chromium/issues/detail?id=1463436 + if ($dom_loaded_timestamp_page === NULL && $message['method'] === 'Page.domContentEventFired') { + $dom_loaded_timestamp_page = $message['params']['timestamp'] * $nanoseconds_per_second; + } + if ($dom_loaded_timestamp_timeline === NULL && $message['method'] === 'Tracing.dataCollected' && isset($message['params']['args']['data']['type']) && $message['params']['args']['data']['type'] === 'DOMContentLoaded') { + $dom_loaded_timestamp_timeline = $message['params']['ts'] * $nanoseconds_per_microsecond; + } + } + + $offset = $dom_loaded_timestamp_page - $dom_loaded_timestamp_timeline; + $entry = $this->getSession()->evaluateScript("window.performance.getEntriesByType('navigation')")[0]; + $first_request_timestamp = $entry['requestStart'] * $nanoseconds_per_millisecond; + $first_response_timestamp = $entry['responseStart'] * $nanoseconds_per_millisecond; + + // @todo: get commit hash from an environment variable and add this as an + // additional attribute. + // @see https://www.drupal.org/project/drupal/issues/3379761 + $resource = ResourceInfoFactory::merge(ResourceInfo::create(Attributes::create([ + ResourceAttributes::SERVICE_NAMESPACE => 'Drupal', + ResourceAttributes::SERVICE_NAME => $service_name, + ResourceAttributes::SERVICE_INSTANCE_ID => 1, + ResourceAttributes::SERVICE_VERSION => \Drupal::VERSION, + ResourceAttributes::DEPLOYMENT_ENVIRONMENT => 'local', + ])), ResourceInfoFactory::defaultResource()); + + $transport = (new OtlpHttpTransportFactory())->create($collector, 'application/x-protobuf'); + $exporter = new SpanExporter($transport); + $tracerProvider = new TracerProvider(new SimpleSpanProcessor($exporter), NULL, $resource); + $tracer = $tracerProvider->getTracer('Drupal'); + + $span = $tracer->spanBuilder('main') + ->setStartTimestamp($timestamp) + ->setAttribute('http.method', 'GET') + ->setAttribute('http.url', $url) + ->setSpanKind(SpanKind::KIND_SERVER) + ->startSpan(); + $last_timestamp = $first_byte_timestamp = (int) ($timestamp + ($first_response_timestamp - $first_request_timestamp)); + + try { + $scope = $span->activate(); + $first_byte_span = $tracer->spanBuilder('firstByte') + ->setStartTimestamp($timestamp) + ->setAttribute('http.url', $url) + ->startSpan(); + $first_byte_span->end($first_byte_timestamp); + // Largest contentful paint is not available from + // window.performance::getEntriesByType() so use the performance log + // messages to get it instead. + $lcp_timestamp = NULL; + $fcp_timestamp = NULL; + $lcp_size = 0; + foreach ($messages as $message) { + if ($message['method'] === 'Tracing.dataCollected' && $message['params']['name'] === 'firstContentfulPaint') { + if (!isset($fcp_timestamp)) { + // Tracing timestamps are microseconds since OS boot. However they + // appear to start from a slightly different point from page + // timestamps. Apply an offset calculated from DOM content loaded. + // See https://bugs.chromium.org/p/chromium/issues/detail?id=1463436 + $fcp_timestamp = ($message['params']['ts'] * $nanoseconds_per_microsecond) + $offset; + $fcp_span = $tracer->spanBuilder('firstContentfulPaint') + ->setStartTimestamp($timestamp) + ->setAttribute('http.url', $url) + ->startSpan(); + $last_timestamp = $first_contentful_paint_timestamp = (int) ($timestamp + ($fcp_timestamp - $timestamp_since_os_boot)); + $fcp_span->end($first_contentful_paint_timestamp); + } + } + + // There can be multiple largestContentfulPaint candidates, remember + // the largest one. + if ($message['method'] === 'Tracing.dataCollected' && $message['params']['name'] === 'largestContentfulPaint::Candidate' && $message['params']['args']['data']['size'] > $lcp_size) { + $lcp_timestamp = ($message['params']['ts'] * $nanoseconds_per_microsecond) + $offset; + $lcp_size = $message['params']['args']['data']['size']; + } + } + if (isset($lcp_timestamp)) { + $lcp_span = $tracer->spanBuilder('largestContentfulPaint') + ->setStartTimestamp($timestamp) + ->setAttribute('http.url', $url) + ->startSpan(); + $last_timestamp = $largest_contentful_paint_timestamp = (int) ($timestamp + ($lcp_timestamp - $timestamp_since_os_boot)); + $lcp_span->setAttribute('lcp.size', $lcp_size); + $lcp_span->end($largest_contentful_paint_timestamp); + } + } + finally { + // The scope must be detached before the span is ended, because it's + // created from the span. + if (isset($scope)) { + $scope->detach(); + } + $span->end($last_timestamp); + $tracerProvider->shutdown(); + } + } + +} -- GitLab