feat(tracing): Add experiment to capture http timings (#8371)

This adds an experiment that will allow http timings to be captured. We
currently capture timings on Sentry SaaS with some custom code and
append them to the spans, which has been helpful to identify some
performance problems that were previously hidden (http/1.1 stall time).
Following this work we can add these to the waterfall to represent
measurements as subtimings and will power an upcoming http/1.1 stall
performance issue.

Author: k-fish

packages/browser-integration-tests/suites/tracing/browsertracing/http-timings/init.js

@@ -0,0 +1,17 @@
+import * as Sentry from '@sentry/browser';
+import { Integrations } from '@sentry/tracing';
+
+window.Sentry = Sentry;
+
+Sentry.init({
+  dsn: 'https://public@dsn.ingest.sentry.io/1337',
+  integrations: [
+    new Integrations.BrowserTracing({
+      idleTimeout: 1000,
+      _experiments: {
+        enableHTTPTimings: true,
+      },
+    }),
+  ],
+  tracesSampleRate: 1,
+});

packages/browser-integration-tests/suites/tracing/browsertracing/http-timings/subject.js

@@ -0,0 +1 @@
+fetch('http://example.com/0').then(fetch('http://example.com/1').then(fetch('http://example.com/2')));

packages/browser-integration-tests/suites/tracing/browsertracing/http-timings/test.ts

@@ -0,0 +1,50 @@
+import { expect } from '@playwright/test';
+import type { Event } from '@sentry/types';
+
+import { sentryTest } from '../../../../utils/fixtures';
+import { getMultipleSentryEnvelopeRequests, shouldSkipTracingTest } from '../../../../utils/helpers';
+
+sentryTest('should create fetch spans with http timing', async ({ browserName, getLocalTestPath, page }) => {
+  const supportedBrowsers = ['chromium', 'firefox'];
+
+  if (shouldSkipTracingTest() || !supportedBrowsers.includes(browserName)) {
+    sentryTest.skip();
+  }
+  await page.route('http://example.com/*', async route => {
+    const request = route.request();
+    const postData = await request.postDataJSON();
+
+    await route.fulfill({
+      status: 200,
+      contentType: 'application/json',
+      body: JSON.stringify(Object.assign({ id: 1 }, postData)),
+    });
+  });
+
+  const url = await getLocalTestPath({ testDir: __dirname });
+
+  const envelopes = await getMultipleSentryEnvelopeRequests<Event>(page, 2, { url, timeout: 10000 });
+  const tracingEvent = envelopes[envelopes.length - 1]; // last envelope contains tracing data on all browsers
+
+  const requestSpans = tracingEvent.spans?.filter(({ op }) => op === 'http.client');
+
+  expect(requestSpans).toHaveLength(3);
+
+  await page.pause();
+  requestSpans?.forEach((span, index) =>
+    expect(span).toMatchObject({
+      description: `GET http://example.com/${index}`,
+      parent_span_id: tracingEvent.contexts?.trace?.span_id,
+      span_id: expect.any(String),
+      start_timestamp: expect.any(Number),
+      timestamp: expect.any(Number),
+      trace_id: tracingEvent.contexts?.trace?.trace_id,
+      data: expect.objectContaining({
+        'http.request.connect_start': expect.any(Number),
+        'http.request.request_start': expect.any(Number),
+        'http.request.response_start': expect.any(Number),
+        'network.protocol.version': expect.any(String),
+      }),
+    }),
+  );
+});

packages/tracing-internal/src/browser/browsertracing.ts

@@ -111,6 +111,7 @@ export interface BrowserTracingOptions extends RequestInstrumentationOptions {
   _experiments: Partial<{
     enableLongTask: boolean;
     enableInteractions: boolean;
+    enableHTTPTimings: boolean;
     onStartRouteTransaction: (t: Transaction | undefined, ctx: TransactionContext, getCurrentHub: () => Hub) => void;
   }>;
 
@@ -145,7 +146,6 @@ const DEFAULT_BROWSER_TRACING_OPTIONS: BrowserTracingOptions = {
   startTransactionOnLocationChange: true,
   startTransactionOnPageLoad: true,
   enableLongTask: true,
-  _experiments: {},
   ...defaultRequestInstrumentationOptions,
 };
 
@@ -283,6 +283,9 @@ export class BrowserTracing implements Integration {
       traceXHR,
       tracePropagationTargets,
       shouldCreateSpanForRequest,
+      _experiments: {
+        enableHTTPTimings: _experiments.enableHTTPTimings,
+      },
     });
   }
 

packages/tracing-internal/src/browser/request.ts

@@ -4,6 +4,7 @@ import type { DynamicSamplingContext, Span } from '@sentry/types';
 import {
   addInstrumentationHandler,
   BAGGAGE_HEADER_NAME,
+  browserPerformanceTimeOrigin,
   dynamicSamplingContextToSentryBaggageHeader,
   isInstanceOf,
   SENTRY_XHR_DATA_KEY,
@@ -14,6 +15,13 @@ export const DEFAULT_TRACE_PROPAGATION_TARGETS = ['localhost', /^\/(?!\/)/];
 
 /** Options for Request Instrumentation */
 export interface RequestInstrumentationOptions {
+  /**
+   * Allow experiments for the request instrumentation.
+   */
+  _experiments: Partial<{
+    enableHTTPTimings: boolean;
+  }>;
+
   /**
    * @deprecated Will be removed in v8.
    * Use `shouldCreateSpanForRequest` to control span creation and `tracePropagationTargets` to control
@@ -108,12 +116,13 @@ export const defaultRequestInstrumentationOptions: RequestInstrumentationOptions
   // TODO (v8): Remove this property
   tracingOrigins: DEFAULT_TRACE_PROPAGATION_TARGETS,
   tracePropagationTargets: DEFAULT_TRACE_PROPAGATION_TARGETS,
+  _experiments: {},
 };
 
 /** Registers span creators for xhr and fetch requests  */
 export function instrumentOutgoingRequests(_options?: Partial<RequestInstrumentationOptions>): void {
   // eslint-disable-next-line deprecation/deprecation
-  const { traceFetch, traceXHR, tracePropagationTargets, tracingOrigins, shouldCreateSpanForRequest } = {
+  const { traceFetch, traceXHR, tracePropagationTargets, tracingOrigins, shouldCreateSpanForRequest, _experiments } = {
     traceFetch: defaultRequestInstrumentationOptions.traceFetch,
     traceXHR: defaultRequestInstrumentationOptions.traceXHR,
     ..._options,
@@ -132,15 +141,63 @@ export function instrumentOutgoingRequests(_options?: Partial<RequestInstrumenta
 
   if (traceFetch) {
     addInstrumentationHandler('fetch', (handlerData: FetchData) => {
-      fetchCallback(handlerData, shouldCreateSpan, shouldAttachHeadersWithTargets, spans);
+      const createdSpan = fetchCallback(handlerData, shouldCreateSpan, shouldAttachHeadersWithTargets, spans);
+      if (_experiments?.enableHTTPTimings && createdSpan) {
+        addHTTPTimings(createdSpan);
+      }
     });
   }
 
   if (traceXHR) {
     addInstrumentationHandler('xhr', (handlerData: XHRData) => {
-      xhrCallback(handlerData, shouldCreateSpan, shouldAttachHeadersWithTargets, spans);
+      const createdSpan = xhrCallback(handlerData, shouldCreateSpan, shouldAttachHeadersWithTargets, spans);
+      if (_experiments?.enableHTTPTimings && createdSpan) {
+        addHTTPTimings(createdSpan);
+      }
+    });
+  }
+}
+
+/**
+ * Creates a temporary observer to listen to the next fetch/xhr resourcing timings,
+ * so that when timings hit their per-browser limit they don't need to be removed.
+ *
+ * @param span A span that has yet to be finished, must contain `url` on data.
+ */
+function addHTTPTimings(span: Span): void {
+  const url = span.data.url;
+  const observer = new PerformanceObserver(list => {
+    const entries = list.getEntries() as PerformanceResourceTiming[];
+    entries.forEach(entry => {
+      if ((entry.initiatorType === 'fetch' || entry.initiatorType === 'xmlhttprequest') && entry.name.endsWith(url)) {
+        const spanData = resourceTimingEntryToSpanData(entry);
+        spanData.forEach(data => span.setData(...data));
+        observer.disconnect();
+      }
     });
+  });
+  observer.observe({
+    entryTypes: ['resource'],
+  });
+}
+
+function resourceTimingEntryToSpanData(resourceTiming: PerformanceResourceTiming): [string, string | number][] {
+  const version = resourceTiming.nextHopProtocol.split('/')[1] || 'none';
+
+  const timingSpanData: [string, string | number][] = [];
+  if (version) {
+    timingSpanData.push(['network.protocol.version', version]);
+  }
+
+  if (!browserPerformanceTimeOrigin) {
+    return timingSpanData;
   }
+  return [
+    ...timingSpanData,
+    ['http.request.connect_start', (browserPerformanceTimeOrigin + resourceTiming.connectStart) / 1000],
+    ['http.request.request_start', (browserPerformanceTimeOrigin + resourceTiming.requestStart) / 1000],
+    ['http.request.response_start', (browserPerformanceTimeOrigin + resourceTiming.responseStart) / 1000],
+  ];
 }
 
 /**
@@ -154,13 +211,15 @@ export function shouldAttachHeaders(url: string, tracePropagationTargets: (strin
 
 /**
  * Create and track fetch request spans
+ *
+ * @returns Span if a span was created, otherwise void.
  */
-export function fetchCallback(
+function fetchCallback(
   handlerData: FetchData,
   shouldCreateSpan: (url: string) => boolean,
   shouldAttachHeaders: (url: string) => boolean,
   spans: Record<string, Span>,
-): void {
+): Span | void {
   if (!hasTracingEnabled() || !(handlerData.fetchData && shouldCreateSpan(handlerData.fetchData.url))) {
     return;
   }
@@ -229,6 +288,7 @@ export function fetchCallback(
         options,
       );
     }
+    return span;
   }
 }
 
@@ -301,13 +361,15 @@ export function addTracingHeadersToFetchRequest(
 
 /**
  * Create and track xhr request spans
+ *
+ * @returns Span if a span was created, otherwise void.
  */
-export function xhrCallback(
+function xhrCallback(
   handlerData: XHRData,
   shouldCreateSpan: (url: string) => boolean,
   shouldAttachHeaders: (url: string) => boolean,
   spans: Record<string, Span>,
-): void {
+): Span | void {
   const xhr = handlerData.xhr;
   const sentryXhrData = xhr && xhr[SENTRY_XHR_DATA_KEY];
 
@@ -370,5 +432,7 @@ export function xhrCallback(
         // Error: InvalidStateError: Failed to execute 'setRequestHeader' on 'XMLHttpRequest': The object's state must be OPENED.
       }
     }
+
+    return span;
   }
 }