From 0bc7a4dd9f697a3fceb26c9b1d9ab0891332b9de Mon Sep 17 00:00:00 2001 From: Daniel Griesser Date: Mon, 9 Mar 2020 11:45:47 +0100 Subject: [PATCH] feat[apm]: Use Performance API (#2474) * feat: Use performance api * feat: Update ops & descriptions * feat: Handle navigation changes correctly * chore: Code comments * Apply suggestions from code review Co-Authored-By: Rodolfo Carvalho * chore: CodeReview * ref: Check for performance API Co-authored-by: Rodolfo Carvalho --- CHANGELOG.md | 1 + packages/apm/src/integrations/tracing.ts | 201 ++++++++++++++++++++++- packages/apm/src/span.ts | 2 +- 3 files changed, 201 insertions(+), 3 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index d073802a2bed..59ab09df33b7 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,7 @@ - "You miss 100 percent of the chances you don't take. — Wayne Gretzky" — Michael Scott +- [apm] feat: Make use of the `performance` browser API to provide better instrumentation (#2474) - [browser] ref: Move global error handler + unhandled promise rejection to instrument ## 5.13.2 diff --git a/packages/apm/src/integrations/tracing.ts b/packages/apm/src/integrations/tracing.ts index ca3cc3fc58d6..d074a1975e50 100644 --- a/packages/apm/src/integrations/tracing.ts +++ b/packages/apm/src/integrations/tracing.ts @@ -132,12 +132,17 @@ export class Tracing implements Integration { private readonly _emitOptionsWarning: boolean = false; + private static _performanceCursor: number = 0; + /** * Constructor for Tracing * * @param _options TracingOptions */ public constructor(_options?: Partial) { + if (global.performance) { + global.performance.mark('sentry-tracing-init'); + } const defaults = { discardBackgroundSpans: true, idleTimeout: 500, @@ -257,6 +262,7 @@ export class Tracing implements Integration { event.timestamp - event.start_timestamp < 0); if (Tracing.options.maxTransactionDuration !== 0 && event.type === 'transaction' && isOutdatedTransaction) { + logger.log('[Tracing] Discarded transaction since it maxed out maxTransactionDuration'); return null; } } @@ -316,6 +322,7 @@ export class Tracing implements Integration { ); Tracing._activeTransaction = span; + Tracing._addOffsetToSpan(`idleTransactionStarted-${Tracing._currentIndex}`, span as SpanClass); // We need to do this workaround here and not use configureScope // Reason being at the time we start the inital transaction we do not have a client bound on the hub yet @@ -357,11 +364,168 @@ export class Tracing implements Integration { const active = Tracing._activeTransaction as SpanClass; if (active) { logger.log('[Tracing] finishIdleTransaction', active.transaction); + Tracing._addPerformanceEntries(active); // true = use timestamp of last span active.finish(true); } } + /** + * This uses `performance.getEntries()` to add additional spans to the active transaction. + * Also, we update our timings since we consider the timings in this API to be more correct than our manual + * measurements. + * + * @param transactionSpan The transaction span + */ + private static _addPerformanceEntries(transactionSpan: SpanClass): void { + if (!global.performance) { + // Gatekeeper if performance API not available + return; + } + logger.log('[Tracing] Adding & adjusting spans using Performance API'); + let navigationOffset = 0; + if ( + transactionSpan.op === 'navigation' && + transactionSpan.data && + typeof transactionSpan.data.offset === 'number' + ) { + navigationOffset = transactionSpan.data.offset; + } + // tslint:disable-next-line: completed-docs + function addSpan(span: SpanClass): void { + if (transactionSpan.spanRecorder) { + transactionSpan.spanRecorder.finishSpan(span); + } + } + + // tslint:disable-next-line: completed-docs + function addPerformanceNavigationTiming(parent: SpanClass, entry: { [key: string]: number }, event: string): void { + const span = parent.child({ + description: event, + op: 'browser', + }); + span.startTimestamp = parent.startTimestamp + Tracing._msToSec(entry[`${event}Start`]); + span.timestamp = parent.startTimestamp + Tracing._msToSec(entry[`${event}End`]); + addSpan(span); + } + + // tslint:disable-next-line: completed-docs + function addRequest(parent: SpanClass, entry: { [key: string]: number }): void { + const request = parent.child({ + description: 'request', + op: 'browser', + }); + request.startTimestamp = parent.startTimestamp + Tracing._msToSec(entry.requestStart); + request.timestamp = parent.startTimestamp + Tracing._msToSec(entry.responseEnd); + addSpan(request); + const response = parent.child({ + description: 'response', + op: 'browser', + }); + response.startTimestamp = parent.startTimestamp + Tracing._msToSec(entry.responseStart); + response.timestamp = parent.startTimestamp + Tracing._msToSec(entry.responseEnd); + addSpan(response); + } + + let entryScriptSrc: string | undefined; + + if (global.document) { + // tslint:disable-next-line: prefer-for-of + for (let i = 0; i < document.scripts.length; i++) { + // We go through all scripts on the page and look for 'data-entry' + // We remember the name and measure the time between this script finished loading and + // our mark 'sentry-tracing-init' + if (document.scripts[i].dataset.entry === 'true') { + entryScriptSrc = document.scripts[i].src; + break; + } + } + } + + let entryScriptStartEndTime: number | undefined; + let tracingInitMarkStartTime: number | undefined; + + // tslint:disable: no-unsafe-any + performance + .getEntries() + .slice(Tracing._performanceCursor) + .forEach((entry: any) => { + const startTime = Tracing._msToSec(entry.startTime as number); + const duration = Tracing._msToSec(entry.duration as number); + + switch (entry.entryType) { + case 'navigation': + addPerformanceNavigationTiming(transactionSpan, entry, 'unloadEvent'); + addPerformanceNavigationTiming(transactionSpan, entry, 'domContentLoadedEvent'); + addPerformanceNavigationTiming(transactionSpan, entry, 'loadEvent'); + addPerformanceNavigationTiming(transactionSpan, entry, 'connect'); + addPerformanceNavigationTiming(transactionSpan, entry, 'domainLookup'); + addRequest(transactionSpan, entry); + break; + case 'mark': + case 'paint': + case 'measure': + const mark = transactionSpan.child({ + description: `${entry.entryType} ${entry.name}`, + op: 'mark', + }); + mark.startTimestamp = transactionSpan.startTimestamp + startTime - navigationOffset; + mark.timestamp = mark.startTimestamp + duration; + if (tracingInitMarkStartTime === undefined && entry.name === 'sentry-tracing-init') { + tracingInitMarkStartTime = mark.startTimestamp; + } + addSpan(mark); + break; + case 'resource': + const resourceName = entry.name.replace(window.location.origin, ''); + if (entry.initiatorType === 'xmlhttprequest' || entry.initiatorType === 'fetch') { + // We need to update existing spans with new timing info + if (transactionSpan.spanRecorder) { + transactionSpan.spanRecorder.finishedSpans.map((finishedSpan: SpanClass) => { + if (finishedSpan.description && finishedSpan.description.indexOf(resourceName) !== -1) { + finishedSpan.startTimestamp = transactionSpan.startTimestamp + startTime - navigationOffset; + finishedSpan.timestamp = finishedSpan.startTimestamp + duration; + } + }); + } + } else { + const resource = transactionSpan.child({ + description: `${entry.initiatorType} ${resourceName}`, + op: `resource`, + }); + resource.startTimestamp = transactionSpan.startTimestamp + startTime - navigationOffset; + resource.timestamp = resource.startTimestamp + duration; + // We remember the entry script end time to calculate the difference to the first init mark + if (entryScriptStartEndTime === undefined && (entryScriptSrc || '').includes(resourceName)) { + entryScriptStartEndTime = resource.timestamp; + } + addSpan(resource); + } + break; + default: + // Ignore other entry types. + } + }); + + if (entryScriptStartEndTime !== undefined && tracingInitMarkStartTime !== undefined) { + const evaluation = transactionSpan.child({ + description: 'evaluation', + op: `script`, + }); + evaluation.startTimestamp = entryScriptStartEndTime; + evaluation.timestamp = tracingInitMarkStartTime; + addSpan(evaluation); + } + + logger.log('[Tracing] Clearing most performance marks'); + performance.clearMarks(); + performance.clearMeasures(); + performance.clearResourceTimings(); + Tracing._performanceCursor = Math.max(performance.getEntries().length - 1, 0); + + // tslint:enable: no-unsafe-any + } + /** * Sets the status of the current active transaction (if there is one) */ @@ -373,6 +537,32 @@ export class Tracing implements Integration { } } + /** + * Adds offset to the span + * + * @param measureName name of the performance measure + * @param span Span to add data.offset to + */ + private static _addOffsetToSpan(measureName: string, span: SpanClass): void { + if (global.performance) { + const name = `#sentry-${measureName}`; + performance.measure(name); + const measure = performance.getEntriesByName(name).pop(); + if (measure) { + span.setData('offset', Tracing._msToSec(measure.duration)); + } + performance.clearMeasures(name); + } + } + + /** + * Converts from milliseconds to seconds + * @param time time in ms + */ + private static _msToSec(time: number): number { + return time / 1000; + } + /** * Starts tracking for a specifc activity * @@ -403,9 +593,11 @@ export class Tracing implements Integration { if (spanContext && _getCurrentHub) { const hub = _getCurrentHub(); if (hub) { + const span = hub.startSpan(spanContext); + Tracing._addOffsetToSpan(`${name}${Tracing._currentIndex}`, span as SpanClass); Tracing._activities[Tracing._currentIndex] = { name, - span: hub.startSpan(spanContext), + span, }; } } else { @@ -445,7 +637,7 @@ export class Tracing implements Integration { if (activity) { logger.log(`[Tracing] popActivity ${activity.name}#${id}`); - const span = activity.span; + const span = activity.span as SpanClass; if (span) { if (spanData) { Object.keys(spanData).forEach((key: string) => { @@ -459,6 +651,11 @@ export class Tracing implements Integration { }); } span.finish(); + // If there is an offset in data, we need to shift timestamps towards it + if (span.data && typeof span.data.offset === 'number' && typeof span.timestamp === 'number') { + span.startTimestamp += span.data.offset; + span.timestamp += span.data.offset; + } } // tslint:disable-next-line: no-dynamic-delete delete Tracing._activities[id]; diff --git a/packages/apm/src/span.ts b/packages/apm/src/span.ts index f86b340161ff..f5ae63c2ed0c 100644 --- a/packages/apm/src/span.ts +++ b/packages/apm/src/span.ts @@ -108,7 +108,7 @@ export class Span implements SpanInterface, SpanContext { /** * Timestamp when the span was created. */ - public readonly startTimestamp: number = timestampWithMs(); + public startTimestamp: number = timestampWithMs(); /** * Internal start time tracked with a monotonic clock.