Skip to content

Commit

Permalink
fix(instrumentation): fix web instrumentation span clock drifts
Browse files Browse the repository at this point in the history
  • Loading branch information
@legendecas
legendecas committed Jan 3, 2023
1 parent eecb800 commit 7ad5c9d
Show file tree
Hide file tree
Showing 8 changed files with 299 additions and 71 deletions.
90 changes: 68 additions & 22 deletions experimental/packages/opentelemetry-instrumentation-fetch/src/fetch.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -27,7 +27,12 @@ import { AttributeNames } from './enums/AttributeNames';
import { SemanticAttributes } from '@opentelemetry/semantic-conventions';
import { FetchError, FetchResponse, SpanData } from './types';
import { VERSION } from './version';
import { _globalThis } from '@opentelemetry/core';
import {
hrTimeAdd,
hrTimeDuration,
numberToHrtime,
_globalThis,
} from '@opentelemetry/core';

// how long to wait for observer to collect information about resources
// this is needed as event "load" is called before observer
Expand Down Expand Up @@ -96,21 +101,37 @@ export class FetchInstrumentation extends InstrumentationBase<
*/
private _addChildSpan(
span: api.Span,
spanData: SpanData,
corsPreFlightRequest: PerformanceResourceTiming
): void {
const preflightStartTime = this._calcEpochHrTime(
spanData,
numberToHrtime(
corsPreFlightRequest[web.PerformanceTimingNames.FETCH_START]
)
);
const preflightEndTime = this._calcEpochHrTime(
spanData,
numberToHrtime(
corsPreFlightRequest[web.PerformanceTimingNames.RESPONSE_END]
)
);
const childSpan = this.tracer.startSpan(
'CORS Preflight',
{
startTime: corsPreFlightRequest[web.PerformanceTimingNames.FETCH_START],
startTime: preflightStartTime,
},
api.trace.setSpan(api.context.active(), span)
);
if (!this._getConfig().ignoreNetworkEvents) {
web.addSpanNetworkEvents(childSpan, corsPreFlightRequest);
web.addSpanNetworkEvents(
childSpan,
corsPreFlightRequest,
spanData.startTime,
spanData.startHrTime
);
}
childSpan.end(
corsPreFlightRequest[web.PerformanceTimingNames.RESPONSE_END]
);
childSpan.end(preflightEndTime);
}

/**
Expand Down Expand Up @@ -190,7 +211,8 @@ export class FetchInstrumentation extends InstrumentationBase<
*/
private _createSpan(
url: string,
options: Partial<Request | RequestInit> = {}
options: Partial<Request | RequestInit> = {},
startTime: api.HrTime
): api.Span | undefined {
if (core.isUrlIgnored(url, this._getConfig().ignoreUrls)) {
this._diag.debug('ignoring span as url matches ignored url');
Expand All @@ -205,21 +227,22 @@ export class FetchInstrumentation extends InstrumentationBase<
[SemanticAttributes.HTTP_METHOD]: method,
[SemanticAttributes.HTTP_URL]: url,
},
startTime,
});
}

/**
* Finds appropriate resource and add network events to the span
* @param span
* @param resourcesObserver
* @param spanData
* @param endTime
*/
private _findResourceAndAddNetworkEvents(
span: api.Span,
resourcesObserver: SpanData,
spanData: SpanData,
endTime: api.HrTime
): void {
let resources: PerformanceResourceTiming[] = resourcesObserver.entries;
let resources: PerformanceResourceTiming[] = spanData.entries;
if (!resources.length) {
if (!performance.getEntriesByType) {
return;
Expand All @@ -232,8 +255,8 @@ export class FetchInstrumentation extends InstrumentationBase<
) as PerformanceResourceTiming[];
}
const resource = web.getResource(
resourcesObserver.spanUrl,
resourcesObserver.startTime,
spanData.spanUrl,
spanData.startHrTime,
endTime,
resources,
this._usedResources,
Expand All @@ -246,11 +269,16 @@ export class FetchInstrumentation extends InstrumentationBase<

const corsPreFlightRequest = resource.corsPreFlightRequest;
if (corsPreFlightRequest) {
this._addChildSpan(span, corsPreFlightRequest);
this._addChildSpan(span, spanData, corsPreFlightRequest);
this._markResourceAsUsed(corsPreFlightRequest);
}
if (!this._getConfig().ignoreNetworkEvents) {
web.addSpanNetworkEvents(span, mainRequest);
web.addSpanNetworkEvents(
span,
mainRequest,
spanData.startTime,
spanData.startHrTime
);
}
}
}
Expand All @@ -276,18 +304,31 @@ export class FetchInstrumentation extends InstrumentationBase<
spanData: SpanData,
response: FetchResponse
) {
const endTime = core.hrTime();
const endHrTime = core.hrTime();
this._addFinalSpanAttributes(span, response);

setTimeout(() => {
spanData.observer?.disconnect();
this._findResourceAndAddNetworkEvents(span, spanData, endTime);
this._findResourceAndAddNetworkEvents(span, spanData, endHrTime);
this._tasksCount--;
this._clearResources();

const endTime = this._calcEpochHrTime(spanData, endHrTime);
span.end(endTime);
}, OBSERVER_WAIT_TIME_MS);
}

/**
* Calculate the epoch time from the given span data and the hrTime.
*/
private _calcEpochHrTime(spanData: SpanData, hrTime: api.HrTime): api.HrTime {
// Calculate the duration from the hrTimes.
const duration = hrTimeDuration(spanData.startHrTime, hrTime);
// Calculate the endTime from the epoch and the duration.
const endTime = hrTimeAdd(spanData.startTime, duration);
return endTime;
}

/**
* Patches the constructor of fetch
*/
Expand All @@ -300,15 +341,19 @@ export class FetchInstrumentation extends InstrumentationBase<
): Promise<Response> {
const self = this;
const url = web.parseUrl(
args[0] instanceof Request ? args[0].url : args[0]
args[0] instanceof Request ? args[0].url : String(args[0])
).href;

const options = args[0] instanceof Request ? args[0] : args[1] || {};
const createdSpan = plugin._createSpan(url, options);
const spanData = plugin._prepareSpanData(url);
const createdSpan = plugin._createSpan(
url,
options,
spanData.startTime
);
if (!createdSpan) {
return original.apply(this, args);
}
const spanData = plugin._prepareSpanData(url);

function endSpanOnError(span: api.Span, error: FetchError) {
plugin._applyAttributesAfterFetch(span, options, error);
Expand Down Expand Up @@ -431,10 +476,11 @@ export class FetchInstrumentation extends InstrumentationBase<
* @param spanUrl
*/
private _prepareSpanData(spanUrl: string): SpanData {
const startTime = core.hrTime();
const startTime = numberToHrtime(Date.now());
const startHrTime = core.hrTime();
const entries: PerformanceResourceTiming[] = [];
if (typeof PerformanceObserver !== 'function') {
return { entries, startTime, spanUrl };
return { entries, startHrTime, startTime, spanUrl };
}

const observer = new PerformanceObserver(list => {
Expand All @@ -448,7 +494,7 @@ export class FetchInstrumentation extends InstrumentationBase<
observer.observe({
entryTypes: ['resource'],
});
return { entries, observer, startTime, spanUrl };
return { entries, observer, startHrTime, startTime, spanUrl };
}

/**
Expand Down
3 changes: 3 additions & 0 deletions experimental/packages/opentelemetry-instrumentation-fetch/src/types.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -41,5 +41,8 @@ export interface SpanData {
entries: PerformanceResourceTiming[];
observer?: PerformanceObserver;
spanUrl: string;
// startTime of the span from the epoch.
startTime: api.HrTime;
// startTime of the span used to calculate durations.
startHrTime: api.HrTime;
}
8 changes: 6 additions & 2 deletions experimental/packages/opentelemetry-instrumentation-xml-http-request/src/types.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -55,8 +55,12 @@ export interface XhrMem {
span: api.Span;
// span url - not available on types.Span
spanUrl?: string;
// startTime of send function - used to filter cors preflight requests
sendStartTime?: api.HrTime;
// startTime of the span from the epoch.
startTime: api.HrTime;
// startTime of the span used to calculate durations.
startHrTime: api.HrTime;
// startTime of send function - used to filter cors preflight requests.
sendStartHrTime?: api.HrTime;
// resources created between send and end plus some additional timeout
createdResources?: {
observer: PerformanceObserver;
Expand Down
76 changes: 60 additions & 16 deletions experimental/packages/opentelemetry-instrumentation-xml-http-request/src/xhr.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -21,7 +21,14 @@ import {
InstrumentationConfig,
safeExecuteInTheMiddle,
} from '@opentelemetry/instrumentation';
import { hrTime, isUrlIgnored, otperformance } from '@opentelemetry/core';
import {
hrTimeAdd,
hrTime,
hrTimeDuration,
isUrlIgnored,
numberToHrtime,
otperformance,
} from '@opentelemetry/core';
import { SemanticAttributes } from '@opentelemetry/semantic-conventions';
import {
addSpanNetworkEvents,
Expand Down Expand Up @@ -134,14 +141,29 @@ export class XMLHttpRequestInstrumentation extends InstrumentationBase<XMLHttpRe
*/
private _addChildSpan(
span: api.Span,
xhrMem: XhrMem,
corsPreFlightRequest: PerformanceResourceTiming
): void {
api.context.with(api.trace.setSpan(api.context.active(), span), () => {
const startTime = this._calcEpochHrTime(
xhrMem,
numberToHrtime(corsPreFlightRequest[PTN.FETCH_START])
);
const endTime = this._calcEpochHrTime(
xhrMem,
numberToHrtime(corsPreFlightRequest[PTN.RESPONSE_END])
);

const childSpan = this.tracer.startSpan('CORS Preflight', {
startTime: corsPreFlightRequest[PTN.FETCH_START],
startTime,
});
addSpanNetworkEvents(childSpan, corsPreFlightRequest);
childSpan.end(corsPreFlightRequest[PTN.RESPONSE_END]);
addSpanNetworkEvents(
childSpan,
corsPreFlightRequest,
xhrMem.startTime,
xhrMem.startHrTime
);
childSpan.end(endTime);
});
}

Expand Down Expand Up @@ -255,10 +277,10 @@ export class XMLHttpRequestInstrumentation extends InstrumentationBase<XMLHttpRe
xhrMem: XhrMem,
span: api.Span,
spanUrl?: string,
startTime?: api.HrTime,
endTime?: api.HrTime
startHrTime?: api.HrTime,
endHrTime?: api.HrTime
): void {
if (!spanUrl || !startTime || !endTime || !xhrMem.createdResources) {
if (!spanUrl || !startHrTime || !endHrTime || !xhrMem.createdResources) {
return;
}

Expand All @@ -277,8 +299,8 @@ export class XMLHttpRequestInstrumentation extends InstrumentationBase<XMLHttpRe

const resource = getResource(
parseUrl(spanUrl).href,
startTime,
endTime,
startHrTime,
endHrTime,
resources,
this._usedResources
);
Expand All @@ -289,10 +311,15 @@ export class XMLHttpRequestInstrumentation extends InstrumentationBase<XMLHttpRe

const corsPreFlightRequest = resource.corsPreFlightRequest;
if (corsPreFlightRequest) {
this._addChildSpan(span, corsPreFlightRequest);
this._addChildSpan(span, xhrMem, corsPreFlightRequest);
this._markResourceAsUsed(corsPreFlightRequest);
}
addSpanNetworkEvents(span, mainRequest);
addSpanNetworkEvents(
span,
mainRequest,
xhrMem.startTime,
xhrMem.startHrTime
);
}
}

Expand Down Expand Up @@ -331,12 +358,15 @@ export class XMLHttpRequestInstrumentation extends InstrumentationBase<XMLHttpRe
}
const spanName = `HTTP ${method.toUpperCase()}`;

const startTime = Date.now();
const startHrTime = hrTime();
const currentSpan = this.tracer.startSpan(spanName, {
kind: api.SpanKind.CLIENT,
attributes: {
[SemanticAttributes.HTTP_METHOD]: method,
[SemanticAttributes.HTTP_URL]: parseUrl(url).toString(),
},
startTime,
});

currentSpan.addEvent(EventNames.METHOD_OPEN);
Expand All @@ -346,11 +376,24 @@ export class XMLHttpRequestInstrumentation extends InstrumentationBase<XMLHttpRe
this._xhrMem.set(xhr, {
span: currentSpan,
spanUrl: url,
startTime: numberToHrtime(startTime),
startHrTime,
});

return currentSpan;
}

/**
* Calculate the epoch time from the given span data and the hrTime.
*/
private _calcEpochHrTime(xhrMem: XhrMem, hrTime: api.HrTime): api.HrTime {
// Calculate the duration from the hrTimes.
const duration = hrTimeDuration(xhrMem.startHrTime, hrTime);
// Calculate the endTime from the epoch and the duration.
const endTime = hrTimeAdd(xhrMem.startTime, duration);
return endTime;
}

/**
* Marks certain [resource]{@link PerformanceResourceTiming} when information
* from this is used to add events to span.
Expand Down Expand Up @@ -389,23 +432,24 @@ export class XMLHttpRequestInstrumentation extends InstrumentationBase<XMLHttpRe
function endSpanTimeout(
eventName: string,
xhrMem: XhrMem,
endTime: api.HrTime
endHrTime: api.HrTime
) {
const callbackToRemoveEvents = xhrMem.callbackToRemoveEvents;

if (typeof callbackToRemoveEvents === 'function') {
callbackToRemoveEvents();
}

const { span, spanUrl, sendStartTime } = xhrMem;
const { span, spanUrl, sendStartHrTime } = xhrMem;
const endTime = plugin._calcEpochHrTime(xhrMem, endHrTime);

if (span) {
plugin._findResourceAndAddNetworkEvents(
xhrMem,
span,
spanUrl,
sendStartTime,
endTime
sendStartHrTime,
endHrTime
);
span.addEvent(eventName, endTime);
plugin._addFinalSpanAttributes(span, xhrMem, spanUrl);
Expand Down Expand Up @@ -482,7 +526,7 @@ export class XMLHttpRequestInstrumentation extends InstrumentationBase<XMLHttpRe
api.trace.setSpan(api.context.active(), currentSpan),
() => {
plugin._tasksCount++;
xhrMem.sendStartTime = hrTime();
xhrMem.sendStartHrTime = hrTime();
currentSpan.addEvent(EventNames.METHOD_SEND);

this.addEventListener('abort', onAbort);
Expand Down
Loading

0 comments on commit 7ad5c9d

Please sign in to comment.