From e242a5aad6cf88c776c43193b37fbaa736cd762a Mon Sep 17 00:00:00 2001 From: Alex Pott Date: Fri, 3 Nov 2023 15:17:09 +0000 Subject: [PATCH] Issue #3391689 by catch, alexpott, smustgrave: Add a performance tests job to gitlab and send data to OpenTelemetry --- .gitlab-ci.yml | 20 ++-- .gitlab-ci/pipeline.yml | 25 ++++- core/.deprecation-ignore.txt | 1 + .../Drupal/Tests/PerformanceTestTrait.php | 96 +++++++++---------- 4 files changed, 80 insertions(+), 62 deletions(-) diff --git a/.gitlab-ci.yml b/.gitlab-ci.yml index 5a04137b214..92973a9eef6 100644 --- a/.gitlab-ci.yml +++ b/.gitlab-ci.yml @@ -65,7 +65,7 @@ stages: # Templates # ############# -.default-job-settings: &default-job-settings-lint +.default-job-settings: &default-job-settings interruptible: true allow_failure: false retry: @@ -78,10 +78,6 @@ stages: - scheduler_failure image: name: $_CONFIG_DOCKERHUB_ROOT/php-$_TARGET_PHP-apache:production - rules: - - if: $CI_PIPELINE_SOURCE == "push" && $CI_PROJECT_ROOT_NAMESPACE == "project" - - if: $CI_PIPELINE_SOURCE == "schedule" && $CI_PROJECT_ROOT_NAMESPACE == "project" - - if: $CI_PIPELINE_SOURCE == "merge_request_event" .with-composer: &with-composer needs: @@ -91,6 +87,11 @@ stages: needs: - '📦️ Yarn' +.default-job-settings-lint: &default-job-settings-lint + <<: [*default-job-settings] + rules: + - if: $PERFORMANCE_TEST != "1" + .junit-artifacts: &junit-artifacts artifacts: expose_as: junit @@ -128,7 +129,7 @@ stages: .run-daily: &run-daily rules: - - if: $CI_PIPELINE_SOURCE == "schedule" && $CI_PROJECT_ROOT_NAMESPACE == "project" + - if: $CI_PIPELINE_SOURCE == "schedule" && $CI_PROJECT_ROOT_NAMESPACE == "project" && $DAILY_TEST == "1" - if: $CI_PIPELINE_SOURCE == "merge_request_event" when: manual allow_failure: true @@ -139,9 +140,12 @@ stages: variables: _TARGET_PHP: "8.2" _TARGET_DB: "mysql-8" + PERFORMANCE_TEST: $PERFORMANCE_TEST + OTEL_COLLECTOR: $OTEL_COLLECTOR rules: - if: $CI_PIPELINE_SOURCE == "push" && $CI_PROJECT_ROOT_NAMESPACE == "project" - if: $CI_PIPELINE_SOURCE == "merge_request_event" + - if: $PERFORMANCE_TEST == "1" # Run on commit, or manually. 'PHP 8.1 MySQL 5.7': @@ -223,7 +227,7 @@ stages: ################ '📦️ Composer': - <<: *default-job-settings-lint + <<: *default-job-settings variables: <<: *default-lint-variables KUBERNETES_CPU_REQUEST: "1" @@ -245,7 +249,7 @@ stages: - composer install '📦️ Yarn': - <<: *default-job-settings-lint + <<: *default-job-settings variables: <<: *default-lint-variables KUBERNETES_CPU_REQUEST: "2" diff --git a/.gitlab-ci/pipeline.yml b/.gitlab-ci/pipeline.yml index a38c9d0a889..ac0385f09fe 100644 --- a/.gitlab-ci/pipeline.yml +++ b/.gitlab-ci/pipeline.yml @@ -22,7 +22,7 @@ stages: image: name: $_CONFIG_DOCKERHUB_ROOT/php-$_TARGET_PHP-apache:production rules: - - if: $CI_PIPELINE_SOURCE == "parent_pipeline" + - if: $CI_PIPELINE_SOURCE == "parent_pipeline" && $PERFORMANCE_TEST != "1" .junit-artifacts: &junit-artifacts artifacts: @@ -274,3 +274,26 @@ stages: REPEAT_TEST_CLASS: 'Drupal\Tests\Change\Me' services: - <<: *with-database + +'🚲 Performance tests': + <<: [ *with-composer, *phpunit-artifacts, *setup-webserver, *default-job-settings ] + rules: + - if: $PERFORMANCE_TEST == "1" + variables: + <<: *test-variables + KUBERNETES_CPU_REQUEST: "24" + services: + - <<: *with-database + - <<: *with-chrome + script: + # Determine DB driver. + - | + [[ $_TARGET_DB == sqlite* ]] && export SIMPLETEST_DB=sqlite://localhost/subdirectory/sites/default/files/db.sqlite?module=sqlite + [[ $_TARGET_DB == mysql* ]] && export SIMPLETEST_DB=mysql://$MYSQL_USER:$MYSQL_PASSWORD@database/$MYSQL_DATABASE?module=mysql + [[ $_TARGET_DB == mariadb* ]] && export SIMPLETEST_DB=mysql://$MYSQL_USER:$MYSQL_PASSWORD@database/$MYSQL_DATABASE?module=mysql + [[ $_TARGET_DB == pgsql* ]] && export SIMPLETEST_DB=pgsql://$POSTGRES_USER:$POSTGRES_PASSWORD@database/$POSTGRES_DB?module=pgsql + - export OTEL_COLLECTOR="$OTEL_COLLECTOR" + - mkdir -p ./sites/simpletest ./sites/default/files ./build/logs/junit /var/www/.composer + - chown -R www-data:www-data ./sites ./build/logs/junit ./vendor /var/www/ + - sudo -u www-data git config --global --add safe.directory $CI_PROJECT_DIR + - for run in {1..3}; do sudo SIMPLETEST_BASE_URL="$SIMPLETEST_BASE_URL" SIMPLETEST_DB="$SIMPLETEST_DB" MINK_DRIVER_ARGS_WEBDRIVER="$MINK_DRIVER_ARGS_WEBDRIVER" OTEL_COLLECTOR="$OTEL_COLLECTOR" -u www-data ./vendor/bin/phpunit -c core --group OpenTelemetry --log-junit=./sites/default/files/simpletest/phpunit-performance.xml; done diff --git a/core/.deprecation-ignore.txt b/core/.deprecation-ignore.txt index 921a981e5c9..2fc93ec6bdb 100644 --- a/core/.deprecation-ignore.txt +++ b/core/.deprecation-ignore.txt @@ -17,6 +17,7 @@ %Method "Twig\\NodeVisitor\\AbstractNodeVisitor::[^"]+" might add "[^"]+" as a native return type declaration in the future. Do the same in (child class|implementation) "[^"]+" now to avoid errors or add an explicit @return annotation to suppress this message% %Method "Twig\\NodeVisitor\\NodeVisitorInterface::[^"]+" might add "[^"]+" as a native return type declaration in the future. Do the same in (child class|implementation) "[^"]+" now to avoid errors or add an explicit @return annotation to suppress this message% %Method "Twig\\TokenParser\\TokenParserInterface::[^"]+" might add "[^"]+" as a native return type declaration in the future. Do the same in (child class|implementation) "[^"]+" now to avoid errors or add an explicit @return annotation to suppress this message% +%Method "WebDriver\\Service\\CurlServiceInterface::[^"]+" might add "[^"]+" as a native return type declaration in the future. Do the same in implementation "[^"]+" now to avoid errors or add an explicit @return annotation to suppress this message% # Skip root namespace native DebugClassLoader forward compatibility warnings. # These mostly refer to PHP native classes, could be fixed for PHP 8.1. diff --git a/core/tests/Drupal/Tests/PerformanceTestTrait.php b/core/tests/Drupal/Tests/PerformanceTestTrait.php index 0906a42c0f8..77bdfb21573 100644 --- a/core/tests/Drupal/Tests/PerformanceTestTrait.php +++ b/core/tests/Drupal/Tests/PerformanceTestTrait.php @@ -218,47 +218,42 @@ trait PerformanceTestTrait { $nanoseconds_per_millisecond = 1000_000; $nanoseconds_per_microsecond = 1000; - $collector = $_ENV['OTEL_COLLECTOR'] ?? NULL; - if ($collector === NULL) { + $collector = getenv('OTEL_COLLECTOR'); + if (!$collector) { return; } - $timestamp = NULL; + $first_request_timestamp = NULL; + $first_response_timestamp = NULL; + $request_wall_time = NULL; + $response_wall_time = 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['params']['request']['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; + // request and response, determine the wall times of each, then calculate + // offsets from those for everything else. + if ($message['method'] === 'Tracing.dataCollected' + && isset($message['params']['name']) + && $message['params']['name'] === 'ResourceReceiveResponse') { + $first_response_timestamp = (int) ($message['params']['ts'] * $nanoseconds_per_microsecond); + + // Get the actual timestamp of the response which is a millisecond unix + // epoch timestamp. The log doesn't provide this for the request. + $response_wall_time = (int) ($message['params']['args']['data']['responseTime'] * $nanoseconds_per_millisecond); + + // 'requestTime' is in the format 'seconds since OS boot with + // microsecond precision'. + $first_request_timestamp = (int) ($message['params']['args']['data']['timing']['requestTime'] * $nanoseconds_per_second); + // By subtracting the request timestamp from the response wall time we + // get the request wall time. + $request_wall_time = ($response_wall_time - ($first_response_timestamp - $first_request_timestamp)); + break; } } - - $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; + if ($first_response_timestamp === NULL) { + // If the $first_response_timestamp is null, this means we got an + // incomplete log from chromedriver, mark the test as skipped. + $this->markTestSkipped('Incomplete log from chromedriver, giving up.'); + } // @todo: get commit hash from an environment variable and add this as an // additional attribute. @@ -278,58 +273,53 @@ trait PerformanceTestTrait { $tracer = $tracerProvider->getTracer('Drupal'); $span = $tracer->spanBuilder('main') - ->setStartTimestamp($timestamp) + ->setStartTimestamp($request_wall_time) ->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)); + + $last_timestamp = $response_wall_time; try { $scope = $span->activate(); $first_byte_span = $tracer->spanBuilder('firstByte') - ->setStartTimestamp($timestamp) + ->setStartTimestamp($request_wall_time) ->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. + $first_byte_span->end($response_wall_time); $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; + // Tracing timestamps are microseconds since OS boot. + $fcp_timestamp = $message['params']['ts'] * $nanoseconds_per_microsecond; $fcp_span = $tracer->spanBuilder('firstContentfulPaint') - ->setStartTimestamp($timestamp) + ->setStartTimestamp($request_wall_time) ->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); + $last_timestamp = $first_contentful_paint_wall_time = (int) ($request_wall_time + ($fcp_timestamp - $first_request_timestamp)); + $fcp_span->end($first_contentful_paint_wall_time); } } // 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_timestamp = $message['params']['ts'] * $nanoseconds_per_microsecond; $lcp_size = $message['params']['args']['data']['size']; } } if (isset($lcp_timestamp)) { $lcp_span = $tracer->spanBuilder('largestContentfulPaint') - ->setStartTimestamp($timestamp) + ->setStartTimestamp($request_wall_time) ->setAttribute('http.url', $url) ->startSpan(); - $last_timestamp = $largest_contentful_paint_timestamp = (int) ($timestamp + ($lcp_timestamp - $timestamp_since_os_boot)); + $last_timestamp = $largest_contentful_paint_wall_time = (int) ($request_wall_time + ($lcp_timestamp - $first_request_timestamp)); $lcp_span->setAttribute('lcp.size', $lcp_size); - $lcp_span->end($largest_contentful_paint_timestamp); + $lcp_span->end($largest_contentful_paint_wall_time); } } finally {