diff --git a/README.md b/README.md index cf3c17f5..1323fe3d 100644 --- a/README.md +++ b/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 diff --git a/lerna.json b/lerna.json index 3292956b..d8db0954 100644 --- a/lerna.json +++ b/lerna.json @@ -1,4 +1,4 @@ { - "lerna": "2.0.0-beta.9", + "lerna": "2.0.0-beta.30", "version": "0.3.0" } diff --git a/package.json b/package.json index 1faf8489..1b0e3967 100644 --- a/package.json +++ b/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" } } diff --git a/packages/zipkin/src/batch-recorder.js b/packages/zipkin/src/batch-recorder.js index 772cfbcf..19eacb38 100644 --- a/packages/zipkin/src/batch-recorder.js +++ b/packages/zipkin/src/batch-recorder.js @@ -45,7 +45,7 @@ class BatchRecorder { span = new MutableSpan(id); } updater(span); - if (span.complete) { + if (span.endTimestamp) { this._writeSpan(id); } else { this.partialSpans.set(id, span); @@ -53,7 +53,7 @@ class BatchRecorder { } _timedOut(span) { - return span.started + this.timeout < now(); + return span.startTimestamp + this.timeout < now(); } diff --git a/packages/zipkin/src/internalRepresentations.js b/packages/zipkin/src/internalRepresentations.js index dc17a86b..5d1cdcd6 100644 --- a/packages/zipkin/src/internalRepresentations.js +++ b/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() { diff --git a/packages/zipkin/src/time.js b/packages/zipkin/src/time.js index 2d0030b1..c8216c6c 100644 --- a/packages/zipkin/src/time.js +++ b/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; + } }; diff --git a/packages/zipkin/src/tracer/index.js b/packages/zipkin/src/tracer/index.js index 9ac6e527..35b4af1d 100644 --- a/packages/zipkin/src/tracer/index.js +++ b/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 })); } diff --git a/packages/zipkin/test/batch-recorder.test.js b/packages/zipkin/test/batch-recorder.test.js index 48cdcfa8..04cd757e 100644 --- a/packages/zipkin/test/batch-recorder.test.js +++ b/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,10 +71,7 @@ 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()); @@ -82,7 +79,7 @@ describe('Batch Recorder', () => { const loggedSpan = logSpan.getCall(0).args[0]; - expect(loggedSpan.started).to.equal(12345678000); + expect(loggedSpan.startTimestamp).to.equal(12345678000); clock.uninstall(); }); diff --git a/packages/zipkin/test/explicit-context.test.js b/packages/zipkin/test/explicit-context.test.js index 1773357e..0793ce41 100644 --- a/packages/zipkin/test/explicit-context.test.js +++ b/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(); }); }); diff --git a/packages/zipkin/test/internalRepresentations.test.js b/packages/zipkin/test/internalRepresentations.test.js index cbe0e5d9..cfccb27f 100644 --- a/packages/zipkin/test/internalRepresentations.test.js +++ b/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,7 +79,7 @@ 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); @@ -85,4 +87,64 @@ describe('JSON Formatting', () => { 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(); + }); }); diff --git a/packages/zipkin/test/trace.test.js b/packages/zipkin/test/trace.test.js index 7f07515b..88e54713 100644 --- a/packages/zipkin/test/trace.test.js +++ b/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(); }); });