Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

fix(instrumentation): fix web instrumentation span clock drifts #3518

Closed
wants to merge 1 commit into from
Closed

fix(instrumentation): fix web instrumentation span clock drifts #3518

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions experimental/CHANGELOG.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -23,6 +23,7 @@ All notable changes to experimental packages in this project will be documented
* fix(prometheus-sanitization): replace repeated `_` with a single `_` [3470](https://github.com/open-telemetry/opentelemetry-js/pull/3470) @samimusallam
* fix(prometheus-serializer): correct string used for NaN [#3477](https://github.com/open-telemetry/opentelemetry-js/pull/3477) @JacksonWeber
* fix(instrumentation-http): close server span when response finishes [#3407](https://github.com/open-telemetry/opentelemetry-js/pull/3407) @legendecas
* fix(instrumentation): fix web instrumentation span clock drifts [3518](https://github.com/open-telemetry/opentelemetry-js/pull/3518) @legendecas

### :books: (Refine Doc)

Expand Down
90 changes: 68 additions & 22 deletions experimental/packages/opentelemetry-instrumentation-fetch/src/fetch.ts
View file
Open in desktop
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
Open in desktop
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
Open in desktop
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
Loading