Same name in other branches

1. 11.x core/tests/Drupal/Tests/PerformanceTestTrait.php \Drupal\Tests\PerformanceTestTrait::openTelemetryTracing()

Sends metrics to OpenTelemetry.

Parameters

array $messages: The ChromeDriver performance log messages.

string $service_name: A human readable identifier so that traces can be grouped together.

See also

https://opentelemetry.io/docs/instrumentation/php/manual/

1 call to PerformanceTestTrait::openTelemetryTracing()

PerformanceTestTrait::processChromeDriverPerformanceLogs in core/tests/Drupal/Tests/PerformanceTestTrait.php

Gets the chromedriver performance log and extracts metrics from it.

File

core/tests/Drupal/Tests/PerformanceTestTrait.php, line 422

Class

PerformanceTestTrait

Provides various methods to aid in collecting performance data during tests.

Namespace

Drupal\Tests

Code

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 = 1000000000;
    $nanoseconds_per_millisecond = 1000000;
    $nanoseconds_per_microsecond = 1000;
    $collector = getenv('OTEL_COLLECTOR');
    if (!$collector) {
        return;
    }
    $first_request_timestamp = NULL;
    $first_response_timestamp = NULL;
    $request_wall_time = NULL;
    $response_wall_time = NULL;
    $url = NULL;
    foreach ($messages as $message) {
        // Since chrome timestamps are since OS start, we take the first network
        // 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;
        }
    }
    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.
    //   @see https://www.drupal.org/project/drupal/issues/3379761
    $resource = ResourceInfoFactory::defaultResource();
    $resource = $resource->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',
    ])));
    $otel_collector_headers = getenv('OTEL_COLLECTOR_HEADERS') ?: [];
    if ($otel_collector_headers) {
        $otel_collector_headers = json_decode($otel_collector_headers, TRUE);
    }
    $transport = (new OtlpHttpTransportFactory())->create($collector, 'application/x-protobuf', $otel_collector_headers);
    $exporter = new SpanExporter($transport);
    $tracerProvider = new TracerProvider(new SimpleSpanProcessor($exporter), NULL, $resource);
    $tracer = $tracerProvider->getTracer('Drupal');
    $span = $tracer->spanBuilder('main')
        ->setStartTimestamp($request_wall_time)
        ->setAttribute('http.method', 'GET')
        ->setAttribute('http.url', $url)
        ->setSpanKind(SpanKind::KIND_SERVER)
        ->startSpan();
    $last_timestamp = $response_wall_time;
    try {
        $scope = $span->activate();
        $first_byte_span = $tracer->spanBuilder('firstByte')
            ->setStartTimestamp($request_wall_time)
            ->setAttribute('http.url', $url)
            ->startSpan();
        $first_byte_span->end($response_wall_time);
        $collection = \Drupal::keyValue('performance_test');
        $performance_test_data = $collection->get('performance_test_data');
        $query_events = $performance_test_data['database_events'] ?? [];
        foreach ($query_events as $key => $event) {
            if (static::isDatabaseCache($event)) {
                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))
                ->setAttribute('query.string', $event->queryString)
                ->setAttribute('query.args', var_export($event->args, TRUE))
                ->setAttribute('query.caller', var_export($event->caller, TRUE))
                ->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('cache ' . $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));
        }
        $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;
        $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.
                    $fcp_timestamp = $message['params']['ts'] * $nanoseconds_per_microsecond;
                    $fcp_span = $tracer->spanBuilder('firstContentfulPaint')
                        ->setStartTimestamp($request_wall_time)
                        ->setAttribute('http.url', $url)
                        ->startSpan();
                    $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;
                $lcp_size = $message['params']['args']['data']['size'];
            }
        }
        if (isset($lcp_timestamp)) {
            $lcp_span = $tracer->spanBuilder('largestContentfulPaint')
                ->setStartTimestamp($request_wall_time)
                ->setAttribute('http.url', $url)
                ->startSpan();
            $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_wall_time);
        }
    } 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();
    }
}

---