fix(tracing): make spans resilient to performance clock drift #3384

dyladan · 2022-11-04T20:01:32Z

Relates to #3279 particularly #3279 (comment)

Fixes #3355

packages/opentelemetry-sdk-trace-base/src/Span.ts

Co-authored-by: Marc Pichler <[email protected]>

Co-authored-by: Gerhard Stöbich <[email protected]>

codecov · 2022-11-10T20:56:27Z

Codecov Report

Merging #3384 (eb4c2ae) into main (bd56547) will decrease coverage by 0.70%.
The diff coverage is 91.07%.

Additional details and impacted files

@@            Coverage Diff             @@
##             main    #3384      +/-   ##
==========================================
- Coverage   93.27%   92.57%   -0.71%     
==========================================
  Files         247      132     -115     
  Lines        7348     3152    -4196     
  Branches     1512      656     -856     
==========================================
- Hits         6854     2918    -3936     
+ Misses        494      234     -260

Impacted Files	Coverage Δ
packages/opentelemetry-core/src/common/time.ts	`95.45% <75.00%> (+0.06%)`	⬆️
packages/opentelemetry-sdk-trace-base/src/Span.ts	`97.87% <93.75%> (-2.13%)`	⬇️
api/src/platform/node/globalThis.ts	`0.00% <0.00%> (-100.00%)`	⬇️
...s/opentelemetry-core/src/platform/node/sdk-info.ts	`0.00% <0.00%> (-100.00%)`	⬇️
...opentelemetry-core/src/platform/node/globalThis.ts	`0.00% <0.00%> (-100.00%)`	⬇️
...pentelemetry-core/src/platform/node/performance.ts	`0.00% <0.00%> (-100.00%)`	⬇️
.../packages/api-logs/src/platform/node/globalThis.ts	`0.00% <0.00%> (-100.00%)`	⬇️
...lemetry-resources/src/detectors/ProcessDetector.ts	`31.81% <0.00%> (-68.19%)`	⬇️
...perimental/packages/otlp-exporter-base/src/util.ts	`78.94% <0.00%> (-15.79%)`	⬇️
...ckages/opentelemetry-exporter-zipkin/src/zipkin.ts	`84.48% <0.00%> (-15.52%)`	⬇️
... and 119 more

packages/opentelemetry-sdk-trace-base/src/Span.ts

t2t2 · 2022-11-14T16:28:15Z

Made a sandbox with this patch, most frequently used otel web instrumentations (document-load, user-interaction, xhr and fetch) and an artificial time drift simulator:

https://codesandbox.io/s/modest-fermat-4eu09e?file=/src/otel-fixes.ts

It doesn't improve this test case a lot (user interaction's in right time scale, as it's auto + auto), pretty much all cases of performance timestamps are still affected by drift

document load: performance time start + performance time end:

fetch: auto start + performance time end (duration becomes negative -> set to 0)

dyladan · 2022-11-14T19:45:01Z

It doesn't improve this test case a lot (user interaction's in right time scale, as it's auto + auto), pretty much all cases of performance timestamps are still affected by drift

These instrumentations all use auto start and manual end times.

duration becomes negative -> set to 0

If the duration is negative it should be getting the drift offset correction applied, not just set to 0. If you look at the diagram in the linked comment there is no situation where it should be set to 0, so there must be some bad code path.

t2t2 · 2022-11-15T09:17:00Z

Updated codesandbox with pr changes as of now

This was the root of the 0-duration spans in your example too

Yep fixed on auto start + perf end, however span events (input: perf timestamp) also need correcting (now they end up outside the span w/ drift)

These instrumentations all use auto start and manual end times.

document-load spans don't, as they use manual (performance API) times for both start and end, and these still get drifted:

packages/opentelemetry-core/src/common/time.ts

dyladan · 2022-11-15T12:57:37Z

document-load spans don't, as they use manual (performance API) times for both start and end, and these still get drifted

I'm not sure what we can do there. If the user provides manual start and end times we can't correct drift because they may be intentionally describing a span that happened in the past.

t2t2 · 2022-11-15T13:10:31Z

If the user provides manual start and end times we can't correct drift because they may be intentionally describing a span that happened in the past.

There is currently an assumption that any numeric value lower than timeOrigin is a performance timestamp:

opentelemetry-js/packages/opentelemetry-core/src/common/time.ts

Line 88 in 1b7246a

// Must be a performance.now() if it's smaller than process start time.

So it's actually impossible to create spans in the past (w/ accounting for drift) anyway:

Flarna · 2022-11-15T14:18:22Z

I'm not sure what we can do there. If the user provides manual start and end times we can't correct drift because they may be intentionally describing a span that happened in the past.

We can document how we create timestamps to allow users to keep in sync. Maybe provide some helper APIs.
And use this mechanism at least in the instrumentations hosted here.

dyladan · 2022-11-15T20:33:31Z

If the user provides manual start and end times we can't correct drift because they may be intentionally describing a span that happened in the past.

There is currently an assumption that any numeric value lower than timeOrigin is a performance timestamp:

opentelemetry-js/packages/opentelemetry-core/src/common/time.ts

Line 88 in 1b7246a

// Must be a performance.now() if it's smaller than process start time.

So it's actually impossible to create spans in the past (w/ accounting for drift) anyway:

Hmm so there is. That is disappointing and actually strikes me as a bug. The time code in core attempts to do way too much magic IMO and really limits us. That specific one can probably be fixed by changing it so that the heuristic is < performance.now() instead of < performance.timeOrigin. It would at least limit impossible times to epoch + time the page has been open.

I'm not sure what we can do there. If the user provides manual start and end times we can't correct drift because they may be intentionally describing a span that happened in the past.

We can document how we create timestamps to allow users to keep in sync. Maybe provide some helper APIs. And use this mechanism at least in the instrumentations hosted here.

I agree here documentation is a bare minimum and providing a helper API of some kind to correct drift would be a good idea

dyladan · 2022-11-16T13:17:48Z

packages/opentelemetry-sdk-trace-base/src/Span.ts

@@ -148,21 +170,19 @@ export class Span implements api.Span, ReadableSpan {
      api.diag.warn('Dropping extra events.');
      this.events.shift();
    }
-    if (isTimeInput(attributesOrStartTime)) {
-      if (typeof startTime === 'undefined') {


undefined was actually impossible here

…-js into fix-end-timestamps

dyladan · 2022-11-16T22:17:37Z

packages/opentelemetry-sdk-trace-base/src/Span.ts

+    const now = Date.now();
+    this._performanceStartTime = otperformance.now();
+    this._performanceOffset = now - (this._performanceStartTime + otperformance.timeOrigin);
+
+    // if startTime is a number smaller than the start of the process
+    // assume it is a performance API timestamp and apply correction as needed
+    if (typeof startTime === 'number' && startTime < otperformance.timeOrigin) {
+      startTime += this._performanceOffset;
+    }
+
+    this.startTime = timeInputToHrTime(startTime ?? now);


Updated codesandbox with these changes, looks like all are working properly now 👍

Oh it might be better to replace both references to otperformance.timeOrigin with getTimeOrigin from otel/core because it has additional backwards compat checks for older browsers (IE, safari <15)

opentelemetry-js/packages/opentelemetry-core/src/common/time.ts

Line 47 in e133f3f

function getTimeOrigin(): number {

done. also had to export that function

legendecas · 2022-11-18T08:48:00Z

packages/opentelemetry-sdk-trace-base/src/Span.ts

+
+    // if startTime is a number smaller than the start of the process
+    // assume it is a performance API timestamp and apply correction as needed
+    if (typeof startTime === 'number' && startTime < getTimeOrigin()) {


What if startTime is an HrTime? IIUC it should be compared to the time origin too.

There are only 2 ways I can think of for the user to provide a HrTime

They use our core.hrTime() function to get a time

They use process.hrTime() in node

I think we should discourage (1) and maybe even mark it deprecated. We know it is going to be shifted in the past in many cases. (2) seems extremely unlikely.

The reason I push back is because I'm actually currently reworking the startTime to check for < performance.now() instead of < getTimeOrigin(). We know all performance entries should be in the past, and it is a much more restrictive test. It would also allow creation of spans in the past if the user provides a timestamp from the past (as long as it isn't too close to jan 1 1970).

PTAL here #3279 (comment)

legendecas · 2022-11-18T08:53:46Z

packages/opentelemetry-sdk-trace-base/src/Span.ts

+    if (provided != null) {
+      const duration = hrTimeDuration(this.startTime, provided);
+      if (duration[0] < 0) {
+        return addHrTimes(provided, [0, this._performanceOffset * 1000000]);


Suggested change

return addHrTimes(provided, [0, this._performanceOffset * 1000000]);

return addHrTimes(provided, [0, this._performanceOffset * 1e6]);

or

Suggested change

return addHrTimes(provided, [0, this._performanceOffset * 1000000]);

return addHrTimes(provided, [0, this._performanceOffset * MILLISECOND_TO_NANOSECONDS]);

legendecas · 2022-11-18T08:53:53Z

packages/opentelemetry-sdk-trace-base/src/Span.ts

+    }
+
+    const msDuration = otperformance.now() - this._performanceStartTime;
+    return addHrTimes(this.startTime, [0, msDuration * 1000000]);


Suggested change

return addHrTimes(this.startTime, [0, msDuration * 1000000]);

return addHrTimes(this.startTime, [0, msDuration * 1e6]);

Or

Suggested change

return addHrTimes(this.startTime, [0, msDuration * 1000000]);

return addHrTimes(this.startTime, [0, msDuration * MILLISECOND_TO_NANOSECONDS]);

legendecas · 2022-11-18T08:58:16Z

packages/opentelemetry-sdk-trace-base/src/Span.ts

    this.name = spanName;
    this._spanContext = spanContext;
    this.parentSpanId = parentSpanId;
    this.kind = kind;
    this.links = links;
-    this.startTime = timeInputToHrTime(startTime ?? clock.now());
+
+    const now = Date.now();


I think AnchoredClock can still be applied here to get a high-resolution start time by default.

github-actions · 2023-01-23T06:35:42Z

This PR is stale because it has been open 60 days with no activity. Remove stale label or comment or this will be closed in 14 days.

legendecas · 2023-01-24T15:31:21Z

Superseded by #3434.

fix(tracing): make spans resilient to performance clock drift

b9cd99d

dyladan requested a review from a team November 4, 2022 20:01

Merge branch 'main' into fix-end-timestamps

ace1924

pichlermarc reviewed Nov 9, 2022

View reviewed changes

packages/opentelemetry-sdk-trace-base/src/Span.ts Outdated Show resolved Hide resolved

Flarna reviewed Nov 9, 2022

View reviewed changes

packages/opentelemetry-sdk-trace-base/src/Span.ts Outdated Show resolved Hide resolved

dyladan and others added 3 commits November 10, 2022 08:57

Fix build

f3b471b

Co-authored-by: Marc Pichler <[email protected]>

Remove duplicate performance now

2d29959

Co-authored-by: Gerhard Stöbich <[email protected]>

Merge branch 'main' into fix-end-timestamps

f818d2f

MSNev approved these changes Nov 10, 2022

View reviewed changes

Flarna mentioned this pull request Nov 14, 2022

Span start and end times in the distant past on chrome #3355

Closed

t2t2 reviewed Nov 14, 2022

View reviewed changes

packages/opentelemetry-sdk-trace-base/src/Span.ts Outdated Show resolved Hide resolved

dyladan added 4 commits November 14, 2022 14:50

Merge branch 'main' into fix-end-timestamps

dc7efce

Fix order of operations

09925fb

Don't treat ms as ns

6af1f7c

Fix test

1388dab

t2t2 reviewed Nov 15, 2022

View reviewed changes

packages/opentelemetry-core/src/common/time.ts Outdated Show resolved Hide resolved

Remove loop for drift calculation

e730c7d

dyladan added 5 commits November 15, 2022 15:36

Fix build

87afda1

Merge remote-tracking branch 'origin/main' into fix-end-timestamps

b057219

Lint

227bc5f

Changelog

e8f153e

Fix drift on event times

616b08b

dyladan commented Nov 16, 2022

View reviewed changes

dyladan added 4 commits November 16, 2022 08:21

Fix var name

d765b22

Apply correction to span start

0c5089c

Merge branch 'fix-end-timestamps' of github.com:dyladan/opentelemetry…

d513154

…-js into fix-end-timestamps

Remove duplicate API import

d09e980

dyladan commented Nov 16, 2022

View reviewed changes

t2t2 approved these changes Nov 17, 2022

View reviewed changes

Use getTimeOrigin

eb4c2ae

legendecas reviewed Nov 18, 2022

View reviewed changes

dyladan mentioned this pull request Nov 21, 2022

fix(tracing): make spans resilient to performance clock drift #3434

Merged

legendecas mentioned this pull request Jan 3, 2023

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

Closed

5 tasks

github-actions bot added the stale label Jan 23, 2023

legendecas closed this Jan 24, 2023

dyladan mentioned this pull request May 17, 2023

feat(api-logs): add ObservedTimestamp to LogRecord #3787

Merged

4 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

fix(tracing): make spans resilient to performance clock drift #3384

fix(tracing): make spans resilient to performance clock drift #3384

dyladan commented Nov 4, 2022 •

edited

Loading

codecov bot commented Nov 10, 2022 •

edited

Loading

t2t2 commented Nov 14, 2022

dyladan commented Nov 14, 2022

t2t2 commented Nov 15, 2022 •

edited

Loading

dyladan commented Nov 15, 2022

t2t2 commented Nov 15, 2022

Flarna commented Nov 15, 2022

dyladan commented Nov 15, 2022

dyladan Nov 16, 2022

dyladan Nov 16, 2022

t2t2 Nov 17, 2022

dyladan Nov 17, 2022

legendecas Nov 18, 2022

dyladan Nov 18, 2022 •

edited

Loading

dyladan Nov 18, 2022

legendecas Nov 18, 2022

legendecas Nov 18, 2022

legendecas Nov 18, 2022

github-actions bot commented Jan 23, 2023

legendecas commented Jan 24, 2023

	return addHrTimes(provided, [0, this._performanceOffset * 1000000]);
	return addHrTimes(provided, [0, this._performanceOffset * 1e6]);

	return addHrTimes(this.startTime, [0, msDuration * 1000000]);
	return addHrTimes(this.startTime, [0, msDuration * 1e6]);

fix(tracing): make spans resilient to performance clock drift #3384

fix(tracing): make spans resilient to performance clock drift #3384

Conversation

dyladan commented Nov 4, 2022 • edited Loading

codecov bot commented Nov 10, 2022 • edited Loading

Codecov Report

t2t2 commented Nov 14, 2022

dyladan commented Nov 14, 2022

t2t2 commented Nov 15, 2022 • edited Loading

dyladan commented Nov 15, 2022

t2t2 commented Nov 15, 2022

Flarna commented Nov 15, 2022

dyladan commented Nov 15, 2022

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dyladan Nov 18, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

github-actions bot commented Jan 23, 2023

legendecas commented Jan 24, 2023

dyladan commented Nov 4, 2022 •

edited

Loading

codecov bot commented Nov 10, 2022 •

edited

Loading

t2t2 commented Nov 15, 2022 •

edited

Loading

dyladan Nov 18, 2022 •

edited

Loading