From feb3b91e3750d52859e329c1c99b52483d1fa516 Mon Sep 17 00:00:00 2001 From: k-fish Date: Thu, 8 Jun 2023 09:48:00 -0400 Subject: [PATCH 1/5] 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; } } From d8ebd8627f7b336452492248cdfd25ba81f170d4 Mon Sep 17 00:00:00 2001 From: k-fish Date: Tue, 27 Jun 2023 14:13:04 -0400 Subject: [PATCH 2/5] Fix names for span data --- .../tracing-internal/src/browser/request.ts | 17 ++++++++++++----- 1 file changed, 12 insertions(+), 5 deletions(-) diff --git a/packages/tracing-internal/src/browser/request.ts b/packages/tracing-internal/src/browser/request.ts index cede8f339216..fc44b312cf92 100644 --- a/packages/tracing-internal/src/browser/request.ts +++ b/packages/tracing-internal/src/browser/request.ts @@ -182,14 +182,21 @@ function addHTTPTimings(span: Span): void { } function resourceTimingEntryToSpanData(resourceTiming: PerformanceResourceTiming): [string, string | number][] { + const version = resourceTiming.nextHopProtocol.split('/')[1]; + + const timingSpanData : [string, string | number][] = []; + if (version) { + timingSpanData.push(['network.protocol.version', version]); + } + if (!browserPerformanceTimeOrigin) { - return [['network.protocol.version', resourceTiming.nextHopProtocol]]; + return timingSpanData; } 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], + ...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], ]; } From 1abbe42042ca358c5794be191a030a517f3800b8 Mon Sep 17 00:00:00 2001 From: k-fish Date: Tue, 27 Jun 2023 14:31:05 -0400 Subject: [PATCH 3/5] Prettier --- packages/tracing-internal/src/browser/request.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/tracing-internal/src/browser/request.ts b/packages/tracing-internal/src/browser/request.ts index fc44b312cf92..cce3791698b0 100644 --- a/packages/tracing-internal/src/browser/request.ts +++ b/packages/tracing-internal/src/browser/request.ts @@ -184,7 +184,7 @@ function addHTTPTimings(span: Span): void { function resourceTimingEntryToSpanData(resourceTiming: PerformanceResourceTiming): [string, string | number][] { const version = resourceTiming.nextHopProtocol.split('/')[1]; - const timingSpanData : [string, string | number][] = []; + const timingSpanData: [string, string | number][] = []; if (version) { timingSpanData.push(['network.protocol.version', version]); } From 12da8367571b47c3352bc98c965349975a4a5ca6 Mon Sep 17 00:00:00 2001 From: k-fish Date: Tue, 27 Jun 2023 14:51:23 -0400 Subject: [PATCH 4/5] Fix test --- .../suites/tracing/browsertracing/http-timings/test.ts | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) 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 index 9ca7b640338a..1ef777b9f4fe 100644 --- a/packages/browser-integration-tests/suites/tracing/browsertracing/http-timings/test.ts +++ b/packages/browser-integration-tests/suites/tracing/browsertracing/http-timings/test.ts @@ -37,9 +37,9 @@ sentryTest('should create fetch spans with http timing', async ({ getLocalTestPa 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), + 'http.client.connect_start': expect.any(Number), + 'http.client.request_start': expect.any(Number), + 'http.client.response_start': expect.any(Number), 'network.protocol.version': expect.any(String), }), }), From 6312fc19ee9beeb62fa7508f93d22d95eef7d92e Mon Sep 17 00:00:00 2001 From: k-fish Date: Tue, 27 Jun 2023 17:33:29 -0400 Subject: [PATCH 5/5] Update tests, limit to chrome + FF, substitute empty state for version --- .../tracing/browsertracing/http-timings/test.ts | 15 +++++++++------ packages/tracing-internal/src/browser/request.ts | 2 +- 2 files changed, 10 insertions(+), 7 deletions(-) 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 index 1ef777b9f4fe..c4b5d3e92e62 100644 --- a/packages/browser-integration-tests/suites/tracing/browsertracing/http-timings/test.ts +++ b/packages/browser-integration-tests/suites/tracing/browsertracing/http-timings/test.ts @@ -4,11 +4,13 @@ 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('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('https://example.com/*', async route => { + await page.route('http://example.com/*', async route => { const request = route.request(); const postData = await request.postDataJSON(); @@ -28,6 +30,7 @@ sentryTest('should create fetch spans with http timing', async ({ getLocalTestPa expect(requestSpans).toHaveLength(3); + await page.pause(); requestSpans?.forEach((span, index) => expect(span).toMatchObject({ description: `GET http://example.com/${index}`, @@ -37,9 +40,9 @@ sentryTest('should create fetch spans with http timing', async ({ getLocalTestPa timestamp: expect.any(Number), trace_id: tracingEvent.contexts?.trace?.trace_id, data: expect.objectContaining({ - 'http.client.connect_start': expect.any(Number), - 'http.client.request_start': expect.any(Number), - 'http.client.response_start': expect.any(Number), + '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), }), }), diff --git a/packages/tracing-internal/src/browser/request.ts b/packages/tracing-internal/src/browser/request.ts index cce3791698b0..2c08918ed548 100644 --- a/packages/tracing-internal/src/browser/request.ts +++ b/packages/tracing-internal/src/browser/request.ts @@ -182,7 +182,7 @@ function addHTTPTimings(span: Span): void { } function resourceTimingEntryToSpanData(resourceTiming: PerformanceResourceTiming): [string, string | number][] { - const version = resourceTiming.nextHopProtocol.split('/')[1]; + const version = resourceTiming.nextHopProtocol.split('/')[1] || 'none'; const timingSpanData: [string, string | number][] = []; if (version) {