fix(basic-tracer): performance.now() is relative from start time (jae…

…gertracing#206)

* fix(basic-tracer): performance.now() is relative from start time

* refactor(time): tuples

* refactor(span): change name of toHrTime

* fix(span): duration default

* fix(hrtime): conver to tuple

* fix(basic-tracer): nanosecond accuracy

* feat(core): move time utils to core

* feat(core): add millis and nanos converter

* test(basic-tracer): fix span time tests

packages/opentelemetry-basic-tracer/package.json

@@ -6,7 +6,7 @@
   "types": "build/src/index.d.ts",
   "repository": "open-telemetry/opentelemetry-js",
   "scripts": {
-    "test": "nyc ts-mocha -p tsconfig.json 'test/**/*.ts'",
+    "test": "nyc ts-mocha -p tsconfig.json test/**/**/*.ts",
     "tdd": "yarn test -- --watch-extensions ts --watch",
     "codecov": "nyc report --reporter=json && codecov -f coverage/*.json -p ../../",
     "clean": "rimraf build/*",

packages/opentelemetry-basic-tracer/src/Span.ts

@@ -15,7 +15,7 @@
  */
 
 import * as types from '@opentelemetry/types';
-import { performance } from 'perf_hooks';
+import { hrTime, hrTimeDuration, timeInputToHrTime } from '@opentelemetry/core';
 import { ReadableSpan } from './export/ReadableSpan';
 import { BasicTracer } from './BasicTracer';
 import { SpanProcessor } from './SpanProcessor';
@@ -33,13 +33,14 @@ export class Span implements types.Span, ReadableSpan {
   readonly attributes: types.Attributes = {};
   readonly links: types.Link[] = [];
   readonly events: types.TimedEvent[] = [];
-  readonly startTime: number;
+  readonly startTime: types.HrTime;
   name: string;
   status: types.Status = {
     code: types.CanonicalCode.OK,
   };
-  endTime = 0;
+  endTime: types.HrTime = [0, 0];
   private _ended = false;
+  private _duration: types.HrTime = [-1, -1];
   private readonly _logger: types.Logger;
   private readonly _spanProcessor: SpanProcessor;
 
@@ -50,14 +51,14 @@ export class Span implements types.Span, ReadableSpan {
     spanContext: types.SpanContext,
     kind: types.SpanKind,
     parentSpanId?: string,
-    startTime?: number
+    startTime: types.TimeInput = hrTime()
   ) {
     this._tracer = parentTracer;
     this.name = spanName;
     this.spanContext = spanContext;
     this.parentSpanId = parentSpanId;
     this.kind = kind;
-    this.startTime = startTime || performance.now();
+    this.startTime = timeInputToHrTime(startTime);
     this._logger = parentTracer.logger;
     this._spanProcessor = parentTracer.activeSpanProcessor;
     this._spanProcessor.onStart(this);
@@ -86,7 +87,11 @@ export class Span implements types.Span, ReadableSpan {
 
   addEvent(name: string, attributes?: types.Attributes): this {
     if (this._isSpanEnded()) return this;
-    this.events.push({ name, attributes, time: performance.now() });
+    this.events.push({
+      name,
+      attributes,
+      time: hrTime(),
+    });
     return this;
   }
 
@@ -108,13 +113,13 @@ export class Span implements types.Span, ReadableSpan {
     return this;
   }
 
-  end(endTime?: number): void {
+  end(endTime: types.TimeInput = hrTime()): void {
     if (this._isSpanEnded()) {
       this._logger.error('You can only call end() on a span once.');
       return;
     }
     this._ended = true;
-    this.endTime = endTime || performance.now();
+    this.endTime = timeInputToHrTime(endTime);
     this._spanProcessor.onEnd(this);
   }
 
@@ -126,6 +131,24 @@ export class Span implements types.Span, ReadableSpan {
     return this;
   }
 
+  get duration(): types.HrTime {
+    if (this._duration[0] !== -1) {
+      return this._duration;
+    }
+
+    this._duration = hrTimeDuration(this.startTime, this.endTime);
+
+    if (this._duration[0] < 0) {
+      this._logger.warn(
+        'Inconsistent start and end time, startTime > endTime',
+        this.startTime,
+        this.endTime
+      );
+    }
+
+    return this._duration;
+  }
+
   private _isSpanEnded(): boolean {
     if (this._ended) {
       this._logger.warn(

packages/opentelemetry-basic-tracer/src/export/ReadableSpan.ts

@@ -18,6 +18,7 @@ import {
   SpanKind,
   Status,
   Attributes,
+  HrTime,
   Link,
   SpanContext,
   TimedEvent,
@@ -28,10 +29,11 @@ export interface ReadableSpan {
   readonly kind: SpanKind;
   readonly spanContext: SpanContext;
   readonly parentSpanId?: string;
-  readonly startTime: number;
-  readonly endTime: number;
+  readonly startTime: HrTime;
+  readonly endTime: HrTime;
   readonly status: Status;
   readonly attributes: Attributes;
   readonly links: Link[];
   readonly events: TimedEvent[];
+  readonly duration: HrTime;
 }

packages/opentelemetry-basic-tracer/test/Span.test.ts

@@ -15,6 +15,7 @@
  */
 
 import * as assert from 'assert';
+import { performance } from 'perf_hooks';
 import { Span } from '../src/Span';
 import {
   SpanKind,
@@ -23,7 +24,11 @@ import {
   SpanContext,
 } from '@opentelemetry/types';
 import { BasicTracer } from '../src';
-import { NoopLogger } from '@opentelemetry/core';
+import {
+  hrTimeToNanoseconds,
+  hrTimeToMilliseconds,
+  NoopLogger,
+} from '@opentelemetry/core';
 
 describe('Span', () => {
   const tracer = new BasicTracer({
@@ -43,6 +48,39 @@ describe('Span', () => {
     span.end();
   });
 
+  it('should have valid startTime', () => {
+    const span = new Span(tracer, name, spanContext, SpanKind.SERVER);
+    assert.ok(hrTimeToMilliseconds(span.startTime) > performance.timeOrigin);
+  });
+
+  it('should have valid endTime', () => {
+    const span = new Span(tracer, name, spanContext, SpanKind.SERVER);
+    span.end();
+    assert.ok(
+      hrTimeToNanoseconds(span.endTime) > hrTimeToNanoseconds(span.startTime),
+      'end time must be bigger than start time'
+    );
+
+    assert.ok(
+      hrTimeToMilliseconds(span.endTime) > performance.timeOrigin,
+      'end time must be bigger than time origin'
+    );
+  });
+
+  it('should have a duration', () => {
+    const span = new Span(tracer, name, spanContext, SpanKind.SERVER);
+    span.end();
+    assert.ok(hrTimeToNanoseconds(span.duration) >= 0);
+  });
+
+  it('should have valid event.time', () => {
+    const span = new Span(tracer, name, spanContext, SpanKind.SERVER);
+    span.addEvent('my-event');
+    assert.ok(
+      hrTimeToMilliseconds(span.events[0].time) > performance.timeOrigin
+    );
+  });
+
   it('should get the span context of span', () => {
     const span = new Span(tracer, name, spanContext, SpanKind.CLIENT);
     const context = span.context();
@@ -189,22 +227,22 @@ describe('Span', () => {
     const [event] = readableSpan.events;
     assert.deepStrictEqual(event.name, 'sent');
     assert.ok(!event.attributes);
-    assert.ok(event.time > 0);
+    assert.ok(event.time[0] > 0);
 
     span.addEvent('rev', { attr1: 'value', attr2: 123, attr3: true });
     readableSpan = span.toReadableSpan();
     assert.strictEqual(readableSpan.events.length, 2);
     const [event1, event2] = readableSpan.events;
     assert.deepStrictEqual(event1.name, 'sent');
     assert.ok(!event1.attributes);
-    assert.ok(event1.time > 0);
+    assert.ok(event1.time[0] > 0);
     assert.deepStrictEqual(event2.name, 'rev');
     assert.deepStrictEqual(event2.attributes, {
       attr1: 'value',
       attr2: 123,
       attr3: true,
     });
-    assert.ok(event2.time > 0);
+    assert.ok(event2.time[0] > 0);
 
     span.end();
     // shouldn't add new event
@@ -238,9 +276,10 @@ describe('Span', () => {
 
   it('should only end a span once', () => {
     const span = new Span(tracer, name, spanContext, SpanKind.SERVER);
-    span.end(1234);
-    span.end(4567);
-    assert.strictEqual(span.endTime, 1234);
+    const endTime = Date.now();
+    span.end(endTime);
+    span.end(endTime + 10);
+    assert.deepStrictEqual(span.endTime, [endTime, 0]);
   });
 
   it('should update name', () => {

packages/opentelemetry-core/package.json

@@ -46,6 +46,7 @@
   "devDependencies": {
     "@types/mocha": "^5.2.5",
     "@types/node": "^12.6.8",
+    "@types/sinon": "^7.0.13",
     "@types/webpack-env": "1.13.9",
     "codecov": "^3.1.0",
     "gts": "^1.0.0",
@@ -56,6 +57,7 @@
     "karma-webpack": "^4.0.2",
     "mocha": "^6.1.0",
     "nyc": "^14.1.1",
+    "sinon": "^7.3.2",
     "tslint-microsoft-contrib": "^6.2.0",
     "tslint-consistent-codestyle":"^1.15.1",
     "ts-loader": "^6.0.4",

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

@@ -0,0 +1,99 @@
+/**
+ * Copyright 2019, OpenTelemetry Authors
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      https://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+import * as types from '@opentelemetry/types';
+import { performance } from 'perf_hooks';
+
+const NANOSECOND_DIGITS = 9;
+const SECOND_TO_NANOSECONDS = Math.pow(10, NANOSECOND_DIGITS);
+
+// Converts a number to HrTime
+function numberToHrtime(time: number): types.HrTime {
+  // Decimals only.
+  const seconds = Math.trunc(time);
+  // Round sub-nanosecond accuracy to nanosecond.
+  const nanos =
+    Number((time - seconds).toFixed(NANOSECOND_DIGITS)) * SECOND_TO_NANOSECONDS;
+  return [seconds, nanos];
+}
+
+// Returns an hrtime calculated via performance component.
+export function hrTime(performanceNow?: number): types.HrTime {
+  const timeOrigin = numberToHrtime(performance.timeOrigin);
+  const now = numberToHrtime(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];
+}
+
+// Converts a TimeInput to an HrTime, defaults to _hrtime().
+export function timeInputToHrTime(time: types.TimeInput): types.HrTime {
+  // process.hrtime
+  if (Array.isArray(time)) {
+    return time;
+  } else if (typeof time === 'number') {
+    // Must be a performance.now() if it's smaller than process start time.
+    if (time < performance.timeOrigin) {
+      return hrTime(time);
+    }
+    // epoch milliseconds or performance.timeOrigin
+    else {
+      return numberToHrtime(time);
+    }
+  } else if (time instanceof Date) {
+    return [time.getTime(), 0];
+  } else {
+    throw TypeError('Invalid input type');
+  }
+}
+
+// Returns a duration of two hrTime.
+export function hrTimeDuration(
+  startTime: types.HrTime,
+  endTime: types.HrTime
+): types.HrTime {
+  let seconds = endTime[0] - startTime[0];
+  let nanos = endTime[1] - startTime[1];
+
+  // overflow
+  if (nanos < 0) {
+    seconds -= 1;
+    // negate
+    nanos += SECOND_TO_NANOSECONDS;
+  }
+
+  return [seconds, nanos];
+}
+
+// Convert hrTime to nanoseconds.
+export function hrTimeToNanoseconds(hrTime: types.HrTime): number {
+  const nanos = hrTime[0] * SECOND_TO_NANOSECONDS + hrTime[1];
+  return nanos;
+}
+
+// Convert hrTime to milliseconds.
+export function hrTimeToMilliseconds(hrTime: types.HrTime): number {
+  const nanos = Math.round(hrTime[0] * 1000 + hrTime[1] / 1e6);
+  return nanos;
+}

packages/opentelemetry-core/src/index.ts

@@ -16,6 +16,7 @@
 
 export * from './common/ConsoleLogger';
 export * from './common/NoopLogger';
+export * from './common/time';
 export * from './common/types';
 export * from './context/propagation/B3Format';
 export * from './context/propagation/BinaryTraceContext';

packages/opentelemetry-core/src/trace/NoopSpan.ts

@@ -64,7 +64,7 @@ export class NoopSpan implements types.Span {
   }
 
   // By default does nothing
-  end(endTime?: number): void {}
+  end(endTime?: types.TimeInput): void {}
 
   // isRecordingEvents always returns false for noopSpan.
   isRecordingEvents(): boolean {