Same name and namespace 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();
  }
}

---