Supports microsecond precision by employing process.hrtime

This uses the same approach as Brave does, except using process.hrtime
instead of Java's `System.nanoTime`. Here's the approach in summary:

When creating a tracer or a span, save off the relative time and make
timestamps based on an high-precision offset from there.

In browsers, microsecond precision requires installing a shim like this:
```
// use higher-precision time than milliseconds
process.hrtime = require('browser-process-hrtime');
```

See https://nodejs.org/api/process.html#process_process_hrtime_time
See https://github.com/kumavis/browser-process-hrtime

Fixes #29
Fixes #3

README.md

@@ -41,6 +41,17 @@ Currently, the following transports are available:
 
 Every package has its own README.md which describes how to use it.
 
+## Clock precision
+
+Zipkin timestamps are microsecond, not millisecond granularity. When running in node.js,
+[process.hrtime](https://nodejs.org/api/process.html#process_process_hrtime_time) is used to
+achieve this.
+
+In browsers, microsecond precision requires installing a shim like [browser-process-hrtime](https://github.com/kumavis/browser-process-hrtime):
+```javascript
+// use higher-precision time than milliseconds
+process.hrtime = require('browser-process-hrtime');
+```
 
 ## Developing
 

lerna.json

@@ -1,4 +1,4 @@
 {
-  "lerna": "2.0.0-beta.9",
+  "lerna": "2.0.0-beta.30",
   "version": "0.3.0"
 }

package.json

@@ -3,7 +3,7 @@
   "private": true,
   "license": "Apache-2.0",
   "dependencies": {
-    "lerna": "2.0.0-beta.9"
+    "lerna": "2.0.0-beta.30"
   },
   "scripts": {
     "lint": "node node_modules/eslint/bin/eslint.js packages",
@@ -22,6 +22,7 @@
     "eslint-plugin-react": "^5.0.1",
     "lerna": "^2.0.0-beta.6",
     "mocha": "^2.4.5",
-    "sinon": "^1.17.4"
+    "lolex": "^1.5.1",
+    "sinon": "^1.17.6"
   }
 }

packages/zipkin/src/batch-recorder.js

@@ -45,15 +45,15 @@ class BatchRecorder {
       span = new MutableSpan(id);
     }
     updater(span);
-    if (span.complete) {
+    if (span.endTimestamp) {
       this._writeSpan(id);
     } else {
       this.partialSpans.set(id, span);
     }
   }
 
   _timedOut(span) {
-    return span.started + this.timeout < now();
+    return span.startTimestamp + this.timeout < now();
   }
 
 

packages/zipkin/src/internalRepresentations.js

@@ -85,8 +85,8 @@ BinaryAnnotation.prototype.toJSON = function toJSON() {
 
 function MutableSpan(traceId) {
   this.traceId = traceId;
-  this.complete = false;
-  this.started = now();
+  this.startTimestamp = now();
+  this.startTick = process && process.hrtime ? process.hrtime() : undefined;
   this.name = None;
   this.service = None;
   this.endpoint = new Endpoint({});
@@ -100,11 +100,11 @@ MutableSpan.prototype.setServiceName = function setServiceName(name) {
   this.service = new Some(name);
 };
 MutableSpan.prototype.addAnnotation = function addAnnotation(ann) {
-  if (!this.complete && (
+  if (!this.endTimestamp && (
         ann.value === thriftTypes.CLIENT_RECV ||
         ann.value === thriftTypes.SERVER_SEND
         )) {
-    this.complete = true;
+    this.endTimestamp = now(this.startTimestamp, this.startTick);
   }
   this.annotations.push(ann);
 };
@@ -157,17 +157,25 @@ MutableSpan.prototype.toThrift = function toThrift() {
   return span;
 };
 MutableSpan.prototype.toJSON = function toJSON() {
+  let startedSpan = true;
   const trace = this.traceId;
   const spanJson = {
     traceId: trace.traceId,
     name: this.name.getOrElse('Unknown'),
-    id: trace.spanId,
-    timestamp: this.started
+    id: trace.spanId
   };
   trace._parentId.ifPresent(id => {
     spanJson.parentId = id;
   });
   spanJson.annotations = this.annotations.map(ann => {
+    // In the RPC span model, the client owns the timestamp and duration of the
+    // span. If we were propagated an id, we can assume that we shouldn't report
+    // timestamp or duration, rather let the client do that. Worst case we were
+    // propagated an unreported ID and Zipkin backfills timestamp and duration.
+    if (ann.value === thriftTypes.SERVER_RECV) {
+      // TODO: only set this to false when we know we in an existing trace
+      startedSpan = false;
+    }
     const annotationJson = ann.toJSON();
     this.overrideEndpointJSON(annotationJson);
     annotationJson.endpoint.serviceName = this.service.getOrElse('Unknown');
@@ -179,6 +187,12 @@ MutableSpan.prototype.toJSON = function toJSON() {
     annotationJson.endpoint.serviceName = this.service.getOrElse('Unknown');
     return annotationJson;
   });
+
+  // Log timestamp and duration if this tracer started and completed this span.
+  if (startedSpan && this.endTimestamp) {
+    spanJson.timestamp = this.startTimestamp;
+    spanJson.duration = Math.max(this.endTimestamp - this.startTimestamp, 1);
+  }
   return spanJson;
 };
 MutableSpan.prototype.toString = function toString() {

packages/zipkin/src/time.js

@@ -1,4 +1,12 @@
 // Returns the current time in epoch microseconds
-module.exports.now = function now() {
-  return new Date().getTime() * 1000;
+// if startTimestamp and startTick are present, process.hrtime is used
+// See https://nodejs.org/api/process.html#process_process_hrtime_time
+module.exports.now = function now(startTimestamp, startTick) {
+  if (startTimestamp && startTick && process && process.hrtime) {
+    const hrtime = process.hrtime(startTick);
+    const elapsedMicros = Math.floor(hrtime[0] * 1000000 + hrtime[1] / 1000);
+    return startTimestamp + elapsedMicros;
+  } else {
+    return new Date().getTime() * 1000;
+  }
 };

packages/zipkin/src/tracer/index.js

@@ -21,6 +21,8 @@ class Tracer {
     this.sampler = sampler;
     this._ctxImpl = ctxImpl;
     this._defaultTraceId = this.createRootId();
+    this._startTimestamp = now();
+    this._startTick = process && process.hrtime ? process.hrtime() : undefined;
   }
 
   scoped(callback) {
@@ -76,7 +78,7 @@ class Tracer {
   recordAnnotation(annotation) {
     this.recorder.record(new Record({
       traceId: this.id,
-      timestamp: now(),
+      timestamp: now(this._startTimestamp, this._startTick),
       annotation
     }));
   }

packages/zipkin/test/batch-recorder.test.js

@@ -44,7 +44,6 @@ describe('Batch Recorder', () => {
       expect(loggedSpan.traceId.traceId).to.equal('a');
       expect(loggedSpan.traceId.parentId).to.equal('a');
       expect(loggedSpan.traceId.spanId).to.equal('c');
-      expect(loggedSpan.complete).to.equal(true);
       expect(loggedSpan.name).to.eql(new Some('buySmoothie'));
       expect(loggedSpan.service).to.eql(new Some('SmoothieStore'));
       expect(loggedSpan.endpoint.host).to.equal(2130706433);
@@ -56,7 +55,8 @@ describe('Batch Recorder', () => {
     });
   });
 
-  it('should set MutableSpan.started to first record', () => {
+  it('should set MutableSpan.startTimestamp to first record', () => {
+    const clock = lolex.install(12345678);
     const logSpan = sinon.spy();
 
     const ctxImpl = new ExplicitContext();
@@ -71,18 +71,15 @@ describe('Batch Recorder', () => {
         spanId: 'c',
         sampled: new Some(true)
       }));
-      const clock = lolex.install(12345678);
       trace.recordServiceName('SmoothieStore');
-
-      clock.tick(1); // everything else is beyond this
       trace.recordRpc('buySmoothie');
       trace.recordBinary('taste', 'banana');
       trace.recordAnnotation(new Annotation.ServerRecv());
       trace.recordAnnotation(new Annotation.ServerSend());
 
       const loggedSpan = logSpan.getCall(0).args[0];
 
-      expect(loggedSpan.started).to.equal(12345678000);
+      expect(loggedSpan.startTimestamp).to.equal(12345678000);
 
       clock.uninstall();
     });

packages/zipkin/test/explicit-context.test.js

@@ -1,3 +1,4 @@
+const lolex = require('lolex');
 const ExplicitContext = require('../src/explicit-context.js');
 
 describe('ExplicitContext', () => {
@@ -43,6 +44,8 @@ describe('ExplicitContext', () => {
   });
 
   it('does not support async context', done => {
+    const clock = lolex.install();
+
     const ctx = new ExplicitContext();
     function callback() {
       expect(ctx.getContext()).to.equal(null);
@@ -51,5 +54,8 @@ describe('ExplicitContext', () => {
     ctx.letContext('foo', () => {
       setTimeout(callback, 10);
     });
+
+    clock.tick(10);
+    clock.uninstall();
   });
 });

packages/zipkin/test/internalRepresentations.test.js

@@ -1,3 +1,4 @@
+const lolex = require('lolex');
 const TraceId = require('../src/tracer/TraceId');
 const {
   MutableSpan,
@@ -6,36 +7,37 @@ const {
   BinaryAnnotation
 } = require('../src/internalRepresentations');
 const {Some, None} = require('../src/option');
+const {now} = require('../src/time');
 
 describe('JSON Formatting', () => {
-  const ms = new MutableSpan(new TraceId({
+  const serverSpan = new MutableSpan(new TraceId({
     traceId: new Some('a'),
     parentId: new Some('b'),
     spanId: 'c',
     sampled: None
   }));
-  ms.setName('GET');
-  ms.setServiceName('PortalService');
+  serverSpan.setName('GET');
+  serverSpan.setServiceName('PortalService');
 
   const here = new Endpoint({host: 171520595, port: 8080});
 
-  ms.setEndpoint(here);
-  ms.addBinaryAnnotation(new BinaryAnnotation({
+  serverSpan.setEndpoint(here);
+  serverSpan.addBinaryAnnotation(new BinaryAnnotation({
     key: 'warning',
     value: 'The cake is a lie',
     endpoint: here
   }));
-  ms.addAnnotation(new ZipkinAnnotation({
+  serverSpan.addAnnotation(new ZipkinAnnotation({
     timestamp: 1,
     endpoint: here,
     value: 'sr'
   }));
-  ms.addAnnotation(new ZipkinAnnotation({
+  serverSpan.addAnnotation(new ZipkinAnnotation({
     timestamp: 2,
     endpoint: here,
     value: 'ss'
   }));
-  ms.started = 1468441525803803;
+  serverSpan.started = 1468441525803803;
 
   const expected = {
     traceId: 'a',
@@ -77,12 +79,72 @@ describe('JSON Formatting', () => {
   };
 
   it('should transform correctly from MutableSpan to JSON representation', () => {
-    const spanJson = ms.toJSON();
+    const spanJson = serverSpan.toJSON();
     expect(spanJson.traceId).to.equal(expected.traceId);
     expect(spanJson.name).to.equal(expected.name);
     expect(spanJson.id).to.equal(expected.id);
     expect(spanJson.parentId).to.equal(expected.parentId);
     expect(spanJson.annotations).to.deep.equal(expected.annotations);
     expect(spanJson.binaryAnnotations).to.deep.equal(expected.binaryAnnotations);
   });
+
+  it('should not set timestamp or duration on server span', () => {
+    const spanJson = serverSpan.toJSON();
+    expect(spanJson.timestamp).to.equal(undefined);
+    expect(spanJson.duration).to.equal(undefined);
+  });
+
+  it('should set timestamp and duration on client span', () => {
+    const clock = lolex.install(12345678);
+
+    const clientSpan = new MutableSpan(new TraceId({
+      traceId: new Some('a'),
+      parentId: new Some('b'),
+      spanId: 'c',
+      sampled: None
+    }));
+    clientSpan.setName('GET');
+    clientSpan.addAnnotation(new ZipkinAnnotation({
+      timestamp: now(),
+      value: 'cs'
+    }));
+    clock.tick(1.732123);
+    clientSpan.addAnnotation(new ZipkinAnnotation({
+      timestamp: now(),
+      value: 'cr'
+    }));
+
+    const spanJson = clientSpan.toJSON();
+    expect(spanJson.timestamp).to.equal(12345678000);
+    expect(spanJson.duration).to.equal(1732); // truncates nanos!
+
+    clock.uninstall();
+  });
+
+  it('should have minimum duration of 1 microsecond', () => {
+    const clock = lolex.install(12345678);
+
+    const clientSpan = new MutableSpan(new TraceId({
+      traceId: new Some('a'),
+      parentId: new Some('b'),
+      spanId: 'c',
+      sampled: None
+    }));
+    clientSpan.setName('GET');
+    clientSpan.addAnnotation(new ZipkinAnnotation({
+      timestamp: now(),
+      value: 'cs'
+    }));
+    clock.tick(0.000123);
+    clientSpan.addAnnotation(new ZipkinAnnotation({
+      timestamp: now(),
+      value: 'cr'
+    }));
+
+    const spanJson = clientSpan.toJSON();
+    expect(spanJson.timestamp).to.equal(12345678000);
+    expect(spanJson.duration).to.equal(1); // rounds up!
+
+    clock.uninstall();
+  });
 });

packages/zipkin/test/trace.test.js

@@ -65,21 +65,21 @@ describe('Tracer', () => {
   });
 
   it('should log timestamps in microseconds', () => {
+    const clock = lolex.install(12345678);
+
     const record = sinon.spy();
     const recorder = {record};
     const ctxImpl = new ExplicitContext();
     const trace = new Tracer({ctxImpl, recorder});
 
     ctxImpl.scoped(() => {
-      const clock = lolex.install(12345678);
       trace.recordAnnotation(new Annotation.ServerSend());
       clock.tick(1); // everything else is beyond this
       trace.recordMessage('error');
 
       expect(record.getCall(0).args[0].timestamp).to.equal(12345678000);
       expect(record.getCall(1).args[0].timestamp).to.equal(12345679000);
-
-      clock.uninstall();
     });
+    clock.uninstall();
   });
 });