Span._getTime() doesn't handle results from otperformance.now() that are non-monotonically increasing. #5111

vtanakas-nv · 2024-11-05T04:12:17Z

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

Line 283 in ce5bbfb

if (typeof inp === 'number' && inp < otperformance.now()) {

The browser implementation of performance.now() can return identical values if two calls to performance.now() occur in close enough succession. When a call performance.now() is made to assign a value to a span's start or end time prior to the approprate startSpan or span.end() call, Span._getTime() can incorrectly assume that the time a real number containing the quantity of milliseconds since the epoch.

As a result, an error about an inconsistent timespan is returned:

Inconsistent start and end time, startTime > endTime. Setting span duration to 0ms. (2) [1730741930, 287940097] (2) [17, 220185000]

it has also been observed that when this check fails at startSpan (or startActiveSpan) the resulting span can have a duration much longer than actual.

Instead of this check:

        if (typeof inp === 'number' && inp < otperformance.now()) {
            // must be a performance timestamp
            // apply correction and convert to hrtime
            return hrTime(inp + this._performanceOffset);
        }
        if (typeof inp === 'number') {
            return millisToHrTime(inp);
        }

       // omitted for clarity
}

the check should be:

 if (typeof inp === 'number' && inp <= otperformance.now())

This will allow situations where two calls to otperformance.now() happen in quick succession in the browser to correctly process the time.

(tested in Google Chrome Version 130.0.6723.91 (Official Build) (64-bit) on ubuntu 22.04)

<!DOCTYPE html>
<html lang="en">
<head>
  <meta charset="UTF-8">
  <meta name="viewport" content="width=device-width, initial-scale=1.0">
  <title>Performance Test</title>
</head>
<body>
  <h1>Performance.now() Test</h1>
  <button id="testButton">Run Test</button>
  <p id="result"></p>

  <script>
    document.getElementById('testButton').addEventListener('click', function() {
      let sameValueCount = 0;
      let previousTime = performance.now();

      for (let i = 0; i < 100000; i++) {
        const currentTime = performance.now();
        if (currentTime === previousTime) {
          sameValueCount++;
        }
        previousTime = currentTime;
      }

      document.getElementById('result').textContent = `Number of times two successive calls to performance.now() had the same value: ${sameValueCount}`;
    });
  </script>
</body>
</html>

A similar node script behaves as expected with performance.now() returning monotonically increasing values.
(tested with node: v18.17.1)

const { performance } = require('perf_hooks');

let sameValueCount = 0;
let previousTime = performance.now();

for (let i = 0; i < 100000; i++) {
  const currentTime = performance.now();
  if (currentTime === previousTime) {
    sameValueCount++;
  }
  previousTime = currentTime;
}

console.log(`Number of times two successive calls to performance.now() had the same value: ${sameValueCount}`);

The text was updated successfully, but these errors were encountered:

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Span._getTime() doesn't handle results from otperformance.now() that are non-monotonically increasing. #5111

Span._getTime() doesn't handle results from otperformance.now() that are non-monotonically increasing. #5111

vtanakas-nv commented Nov 5, 2024 •

edited

Loading

Span._getTime() doesn't handle results from otperformance.now() that are non-monotonically increasing. #5111

Span._getTime() doesn't handle results from otperformance.now() that are non-monotonically increasing. #5111

Comments

vtanakas-nv commented Nov 5, 2024 • edited Loading

vtanakas-nv commented Nov 5, 2024 •

edited

Loading