From feb3b91e3750d52859e329c1c99b52483d1fa516 Mon Sep 17 00:00:00 2001 From: k-fish Date: Thu, 8 Jun 2023 09:48:00 -0400 Subject: [PATCH] feat(tracing): Add experiment to capture http timings 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). We will likely change the span waterfall to represent some of these as subtimings and are also considering adding a http/1.1 stall performance issue. --- .../browsertracing/http-timings/init.js | 17 +++++ .../browsertracing/http-timings/subject.js | 1 + .../browsertracing/http-timings/test.ts | 47 ++++++++++++ .../src/browser/browsertracing.ts | 5 +- .../tracing-internal/src/browser/request.ts | 71 +++++++++++++++++-- 5 files changed, 133 insertions(+), 8 deletions(-) create mode 100644 packages/browser-integration-tests/suites/tracing/browsertracing/http-timings/init.js create mode 100644 packages/browser-integration-tests/suites/tracing/browsertracing/http-timings/subject.js create mode 100644 packages/browser-integration-tests/suites/tracing/browsertracing/http-timings/test.ts diff --git a/packages/browser-integration-tests/suites/tracing/browsertracing/http-timings/init.js b/packages/browser-integration-tests/suites/tracing/browsertracing/http-timings/init.js new file mode 100644 index 000000000000..efe1e2ef9778 --- /dev/null +++ b/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, +}); diff --git a/packages/browser-integration-tests/suites/tracing/browsertracing/http-timings/subject.js b/packages/browser-integration-tests/suites/tracing/browsertracing/http-timings/subject.js new file mode 100644 index 000000000000..f62499b1e9c5 --- /dev/null +++ b/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'))); diff --git a/packages/browser-integration-tests/suites/tracing/browsertracing/http-timings/test.ts b/packages/browser-integration-tests/suites/tracing/browsertracing/http-timings/test.ts new file mode 100644 index 000000000000..9ca7b640338a --- /dev/null +++ b/packages/browser-integration-tests/suites/tracing/browsertracing/http-timings/test.ts @@ -0,0 +1,47 @@ +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 ({ getLocalTestPath, page }) => { + if (shouldSkipTracingTest()) { + sentryTest.skip(); + } + await page.route('https://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(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); + + 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.client.connectStart': expect.any(Number), + 'http.client.requestStart': expect.any(Number), + 'http.client.responseStart': expect.any(Number), + 'network.protocol.version': expect.any(String), + }), + }), + ); +}); diff --git a/packages/tracing-internal/src/browser/browsertracing.ts b/packages/tracing-internal/src/browser/browsertracing.ts index deb240ec4233..ba4d32b989a2 100644 --- a/packages/tracing-internal/src/browser/browsertracing.ts +++ b/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, }; @@ -253,6 +253,9 @@ export class BrowserTracing implements Integration { traceXHR, tracePropagationTargets, shouldCreateSpanForRequest, + _experiments: { + enableHTTPTimings: _experiments.enableHTTPTimings, + }, }); } diff --git a/packages/tracing-internal/src/browser/request.ts b/packages/tracing-internal/src/browser/request.ts index 284d8f339435..cede8f339216 100644 --- a/packages/tracing-internal/src/browser/request.ts +++ b/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): 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,17 +141,58 @@ export function instrumentOutgoingRequests(_options?: Partial { - 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][] { + if (!browserPerformanceTimeOrigin) { + return [['network.protocol.version', resourceTiming.nextHopProtocol]]; + } + return [ + ['network.protocol.version', resourceTiming.nextHopProtocol], + ['http.client.connectStart', (browserPerformanceTimeOrigin + resourceTiming.connectStart) / 1000], + ['http.client.requestStart', (browserPerformanceTimeOrigin + resourceTiming.requestStart) / 1000], + ['http.client.responseStart', (browserPerformanceTimeOrigin + resourceTiming.responseStart) / 1000], + ]; +} + /** * A function that determines whether to attach tracing headers to a request. * This was extracted from `instrumentOutgoingRequests` to make it easier to test shouldAttachHeaders. @@ -154,13 +204,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, -): void { +): Span | void { if (!hasTracingEnabled() || !(handlerData.fetchData && shouldCreateSpan(handlerData.fetchData.url))) { return; } @@ -230,6 +282,7 @@ export function fetchCallback( options, ); } + return span; } } @@ -302,13 +355,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, -): void { +): Span | void { const xhr = handlerData.xhr; const sentryXhrData = xhr && xhr[SENTRY_XHR_DATA_KEY]; @@ -372,5 +427,7 @@ export function xhrCallback( // Error: InvalidStateError: Failed to execute 'setRequestHeader' on 'XMLHttpRequest': The object's state must be OPENED. } } + + return span; } }