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.

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(tracing): make spans resilient to performance clock drift #3434

Merged
merged 31 commits into from
Jan 11, 2023
Merged
Show file tree
Hide file tree
Changes from 25 commits
Commits
Show all changes
31 commits
Select commit Hold shift + click to select a range
7083983
fix(tracing): make spans resilient to performance clock drift
dyladan Nov 21, 2022
5794fbc
Fix changelog
dyladan Nov 21, 2022
7890388
Do not export getTimeOrigin
dyladan Nov 21, 2022
a764b2b
Apply shift to shim spans
dyladan Nov 22, 2022
e991a6c
Lint
dyladan Nov 22, 2022
4405fc0
Lint
dyladan Nov 22, 2022
ee10895
Merge branch 'main' into simple-fix-timestamps
dyladan Nov 22, 2022
27d72df
Merge branch 'main' into simple-fix-timestamps
dyladan Nov 22, 2022
44d9dc5
Remove unused imports
dyladan Nov 22, 2022
2a5fc2f
Merge branch 'simple-fix-timestamps' of github.com:dyladan/openteleme…
dyladan Nov 22, 2022
0149f56
Fix drift calculation
dyladan Nov 30, 2022
7c540fe
Merge remote-tracking branch 'origin/main' into simple-fix-timestamps
dyladan Dec 14, 2022
7626ca2
Remove bad import
dyladan Dec 14, 2022
26a27f0
Merge remote-tracking branch 'origin/main' into simple-fix-timestamps
dyladan Dec 29, 2022
488b5da
Merge remote-tracking branch 'origin/main' into simple-fix-timestamps
dyladan Jan 3, 2023
9cc92bf
Use Date.now for fetch span end
dyladan Jan 3, 2023
8bddc96
Fetch changelog
dyladan Jan 3, 2023
91cfd37
Merge branch 'main' into simple-fix-timestamps
dyladan Jan 6, 2023
63f3b2c
Test addHrTimes
dyladan Jan 6, 2023
e66b75f
lint
dyladan Jan 6, 2023
b848140
lint
dyladan Jan 6, 2023
f4c1be0
lint
dyladan Jan 6, 2023
8c48a34
Fix flaky test
dyladan Jan 9, 2023
6790d17
lint
dyladan Jan 9, 2023
3b61190
Use perf timer for perf API
dyladan Jan 9, 2023
5614bcb
Apply date fix to xhr
dyladan Jan 9, 2023
f6d88aa
Changelog
dyladan Jan 9, 2023
e763118
lint
dyladan Jan 9, 2023
03c96c0
Revert to previous addHrTimes impl
dyladan Jan 10, 2023
fd2398d
Review comments
dyladan Jan 10, 2023
830c799
Fix flaky test
dyladan Jan 10, 2023
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 CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -22,6 +22,7 @@ For experimental package changes, see the [experimental CHANGELOG](experimental/
* `telemetry.sdk.name`
* `telemetry.sdk.language`
* `telemetry.sdk.version`
* fix(sdk-trace): make spans resilient to clock drift [#3434](https://github.com/open-telemetry/opentelemetry-js/pull/3434) @dyladan
* fix(selenium-tests): updated webpack version for selenium test issue [#3456](https://github.com/open-telemetry/opentelemetry-js/issues/3456) @SaumyaBhushan
* fix(sdk-metrics): fix duplicated registration of metrics for collectors [#3488](https://github.com/open-telemetry/opentelemetry-js/pull/3488) @legendecas
* fix(core): fix precision loss in numberToHrtime [#3480](https://github.com/open-telemetry/opentelemetry-js/pull/3480) @legendecas
Expand Down
1 change: 1 addition & 0 deletions experimental/CHANGELOG.md
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(fetch): make spans resilient to clock drift by using Date.now [#3434](https://github.com/open-telemetry/opentelemetry-js/pull/3434) @dyladan
* fix(sdk-node): fix exporter to be read only OTEL_TRACES_EXPORTER is set to a valid exporter [3492] @svetlanabrennan

### :books: (Refine Doc)
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -276,12 +276,13 @@ export class FetchInstrumentation extends InstrumentationBase<
spanData: SpanData,
response: FetchResponse
) {
const endTime = core.hrTime();
const endTime = core.epochMillisToHrTime(Date.now());
const performanceEndTime = core.hrTime();
this._addFinalSpanAttributes(span, response);

setTimeout(() => {
spanData.observer?.disconnect();
this._findResourceAndAddNetworkEvents(span, spanData, endTime);
this._findResourceAndAddNetworkEvents(span, spanData, performanceEndTime);
this._tasksCount--;
this._clearResources();
span.end(endTime);
Expand Down
34 changes: 18 additions & 16 deletions packages/opentelemetry-core/src/common/time.ts
Original file line number Diff line number Diff line change
Expand Up @@ -27,7 +27,7 @@ const SECOND_TO_NANOSECONDS = Math.pow(10, NANOSECOND_DIGITS);
* Converts a number of milliseconds from epoch to HrTime([seconds, remainder in nanoseconds]).
* @param epochMillis
*/
function numberToHrtime(epochMillis: number): api.HrTime {
export function epochMillisToHrTime(epochMillis: number): api.HrTime {
blumamir marked this conversation as resolved.
Show resolved Hide resolved
const epochSeconds = epochMillis / 1000;
// Decimals only.
const seconds = Math.trunc(epochSeconds);
Expand All @@ -36,7 +36,7 @@ function numberToHrtime(epochMillis: number): api.HrTime {
return [seconds, nanos];
}

function getTimeOrigin(): number {
export function getTimeOrigin(): number {
let timeOrigin = performance.timeOrigin;
if (typeof timeOrigin !== 'number') {
const perf: TimeOriginLegacy = performance as unknown as TimeOriginLegacy;
Expand All @@ -50,21 +50,12 @@ function getTimeOrigin(): number {
* @param performanceNow
*/
export function hrTime(performanceNow?: number): api.HrTime {
const timeOrigin = numberToHrtime(getTimeOrigin());
const now = numberToHrtime(
const timeOrigin = epochMillisToHrTime(getTimeOrigin());
const now = epochMillisToHrTime(
typeof performanceNow === 'number' ? performanceNow : performance.now()
);

let seconds = timeOrigin[0] + now[0];
let nanos = timeOrigin[1] + now[1];

// Nanoseconds
if (nanos > SECOND_TO_NANOSECONDS) {
nanos -= SECOND_TO_NANOSECONDS;
seconds += 1;
}

return [seconds, nanos];
return addHrTimes(timeOrigin, now);
}

/**
Expand All @@ -82,10 +73,10 @@ export function timeInputToHrTime(time: api.TimeInput): api.HrTime {
return hrTime(time);
} else {
// epoch milliseconds or performance.timeOrigin
return numberToHrtime(time);
return epochMillisToHrTime(time);
}
} else if (time instanceof Date) {
return numberToHrtime(time.getTime());
return epochMillisToHrTime(time.getTime());
} else {
throw TypeError('Invalid input type');
}
Expand Down Expand Up @@ -175,3 +166,14 @@ export function isTimeInput(
value instanceof Date
);
}

export function addHrTimes(time1: api.HrTime, time2: api.HrTime): api.HrTime {
const out: api.HrTime = [time1[0] + time2[0], time1[1] + time2[1]];

if (out[1] > SECOND_TO_NANOSECONDS) {
blumamir marked this conversation as resolved.
Show resolved Hide resolved
out[0] = out[0] + Math.floor(out[1] / SECOND_TO_NANOSECONDS);
out[1] = out[1] % SECOND_TO_NANOSECONDS;
}
blumamir marked this conversation as resolved.
Show resolved Hide resolved

return out;
}
31 changes: 31 additions & 0 deletions packages/opentelemetry-core/test/common/time.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -27,6 +27,7 @@ import {
hrTimeToMicroseconds,
hrTimeToTimeStamp,
isTimeInput,
addHrTimes,
} from '../../src/common/time';

describe('time', () => {
Expand Down Expand Up @@ -224,4 +225,34 @@ describe('time', () => {
assert.strictEqual(isTimeInput(undefined), false);
});
});

describe('#addHrTimes', () => {
const NANOSECOND_DIGITS = 9;
const SECOND_TO_NANOSECONDS = Math.pow(10, NANOSECOND_DIGITS);

it('should add two positive times', () => {
const output = addHrTimes([10, 20], [30, 40]);
assert.deepStrictEqual(output, [40, 60]);
});
it('should add two negative times', () => {
const output = addHrTimes([-10, 20], [-30, 40]);
assert.deepStrictEqual(output, [-40, 60]);
});
it('should add a positive and negative time (result positive)', () => {
const output = addHrTimes([-10, 20], [30, 40]);
assert.deepStrictEqual(output, [20, 60]);
});
it('should add a positive and negative time (result negative)', () => {
const output = addHrTimes([10, 20], [-30, 40]);
assert.deepStrictEqual(output, [-20, 60]);
});
it('should overflow nanoseconds to seconds', () => {
const output = addHrTimes([10, SECOND_TO_NANOSECONDS - 10], [10, 20]);
assert.deepStrictEqual(output, [21, 10]);
});
it('should overflow nanoseconds to seconds (negative)', () => {
const output = addHrTimes([-10, SECOND_TO_NANOSECONDS - 10], [-10, 20]);
assert.deepStrictEqual(output, [-19, 10]);
});
});
});
Loading