refactor: use new microsecond timestamps (#616)

The start offset on spans have also been completely replaced by a
microsecond timestamp that isn't affected by clock drift relative to the
transaction timestamp.

Closes #592

BREAKING CHANGE: The previously undocumented method `span.offsetTime()`
have been removed.

Author: watson

lib/agent.js

@@ -242,7 +242,7 @@ Agent.prototype.captureError = function (err, opts, cb) {
 
   var agent = this
   var trans = this.currentTransaction
-  var timestamp = new Date().toISOString()
+  var timestamp = Date.now() * 1000
   var id = crypto.randomBytes(128 / 8).toString('hex')
   var req = opts && opts.request instanceof IncomingMessage
     ? opts.request

lib/instrumentation/http-shared.js

@@ -32,7 +32,7 @@ exports.instrumentRequest = function (agent, moduleName) {
             if (!err) return trans.end()
 
             if (agent._conf.errorOnAbortedRequests && !trans.ended) {
-              var duration = Date.now() - trans._timer.start
+              var duration = trans._timer.elapsed()
               if (duration > agent._conf.abortedErrorThreshold) {
                 agent.captureError('Socket closed with active HTTP request (>' + (agent._conf.abortedErrorThreshold / 1000) + ' sec)', {
                   request: req,

lib/instrumentation/span.js

@@ -20,6 +20,7 @@ function Span (transaction) {
   this.ended = false
   this.name = null
   this.type = null
+  this.timestamp = null
   this._db = null
   this._timer = null
   this._stackObj = null
@@ -42,7 +43,8 @@ Span.prototype.start = function (name, type) {
     this._recordStackTrace()
   }
 
-  this._timer = new Timer()
+  this._timer = new Timer(this.transaction._timer)
+  this.timestamp = this._timer.start
 
   this._agent.logger.debug('start span %o', { id: this.transaction.id, name: name, type: type })
 }
@@ -75,16 +77,7 @@ Span.prototype.duration = function () {
     return null
   }
 
-  return this._timer.duration()
-}
-
-Span.prototype.offsetTime = function () {
-  if (!this.started) {
-    this._agent.logger.debug('tried to call span.offsetTime() for un-started span %o', { id: this.transaction.id, name: this.name, type: this.type })
-    return null
-  }
-
-  return this._timer.offset(this.transaction._timer)
+  return this._timer.duration
 }
 
 Span.prototype.setDbContext = function (context) {
@@ -151,10 +144,9 @@ Span.prototype._encode = function (cb) {
       transaction_id: self.transaction.id,
       parent_id: self.transaction.id,
       trace_id: self.transaction.traceId,
-      timestamp: self.transaction.timestamp,
       name: self.name,
       type: self.type,
-      start: self.offsetTime(),
+      timestamp: self.timestamp,
       duration: self.duration()
     }
 

lib/instrumentation/timer.js

@@ -1,29 +1,21 @@
 'use strict'
 
+var microtime = require('relative-microtime')
+
 module.exports = Timer
 
-function Timer () {
-  this.ended = false
-  this.start = Date.now()
-  this._hrtime = process.hrtime()
-  this._diff = null
+function Timer (timer) {
+  this._timer = timer ? timer._timer : microtime()
+  this.start = this._timer()
+  this.duration = null
 }
 
 Timer.prototype.end = function () {
-  if (this.ended) return
-  this._diff = process.hrtime(this._hrtime)
-  this.ended = true
-}
-
-Timer.prototype.duration = function () {
-  if (!this.ended) return null
-  var ns = this._diff[0] * 1e9 + this._diff[1]
-  return ns / 1e6
+  if (this.duration !== null) return
+  this.duration = this.elapsed()
 }
 
-Timer.prototype.offset = function (timer) {
-  var a = timer._hrtime
-  var b = this._hrtime
-  var ns = (b[0] - a[0]) * 1e9 + (b[1] - a[1])
-  return ns / 1e6
+Timer.prototype.elapsed = function () {
+  // durations are in milliseconds ¯\_(ツ)_/¯
+  return (this._timer() - this.start) / 1000
 }

lib/instrumentation/transaction.js

@@ -50,15 +50,6 @@ function Transaction (agent, name, type) {
     }
   })
 
-  Object.defineProperty(this, 'timestamp', {
-    get () {
-      if (!this._timestamp) {
-        this._timestamp = new Date(this._timer.start).toISOString()
-      }
-      return this._timestamp
-    }
-  })
-
   this.id = crypto.randomBytes(64 / 8).toString('hex') // TODO: Replace with correct id once OT is ready
   this.traceId = crypto.randomBytes(128 / 8).toString('hex') // TODO: Replace with correct id once OT is ready
   this._defaultName = name || ''
@@ -75,14 +66,14 @@ function Transaction (agent, name, type) {
   this._abortTime = 0
   this._agent = agent
   this._agent._instrumentation.currentTransaction = this
-  this._timestamp = null
 
   // Random sampling
   this.sampled = Math.random() <= this._agent._conf.transactionSampleRate
 
   agent.logger.debug('start transaction %o', { id: this.id, name: name, type: type })
 
   this._timer = new Timer()
+  this.timestamp = this._timer.start
 }
 
 Transaction.prototype.setUserContext = function (context) {
@@ -195,7 +186,7 @@ Transaction.prototype.duration = function () {
     return null
   }
 
-  return this._timer.duration()
+  return this._timer.duration
 }
 
 Transaction.prototype.setDefaultName = function (name) {

package.json

@@ -82,6 +82,7 @@
     "original-url": "^1.2.1",
     "read-pkg-up": "^3.0.0",
     "redact-secrets": "^1.0.0",
+    "relative-microtime": "^2.0.0",
     "require-ancestors": "^1.0.0",
     "require-in-the-middle": "^3.1.0",
     "semver": "^5.5.0",

test/instrumentation/index.js

@@ -39,8 +39,8 @@ test('basic', function (t) {
         t.ok(span, 'should have span named ' + name)
         t.equal(span.transaction_id, trans.id, 'should belong to correct transaction')
         t.equal(span.type, 'type')
-        t.ok(span.start > 0, 'span start should be >0ms')
-        t.ok(span.start < 100, 'span start should be <100ms')
+        t.ok(span.timestamp > trans.timestamp, 'assert span timestamp > transaction timestamp')
+        t.ok(span.timestamp < trans.timestamp + 100000, 'assert span timestamp < transaction timestamp + 100000')
         t.ok(span.duration > 0, 'span duration should be >0ms')
         t.ok(span.duration < 100, 'span duration should be <100ms')
         t.ok(span.stacktrace.length > 0, 'should have stack trace')

test/instrumentation/modules/elasticsearch.js

@@ -107,8 +107,8 @@ function done (t, method, path, query) {
       t.notOk(span2.context)
     }
 
-    t.ok(span1.start > span2.start, 'http span should start after elasticsearch span')
-    t.ok(span1.start + span1.duration < span2.start + span2.duration, 'http span should end before elasticsearch span')
+    t.ok(span1.timestamp > span2.timestamp, 'http span should start after elasticsearch span')
+    t.ok(span1.timestamp + span1.duration * 1000 < span2.timestamp + span2.duration * 1000, 'http span should end before elasticsearch span')
 
     t.end()
   }

test/instrumentation/modules/express-graphql.js

@@ -169,7 +169,9 @@ function done (t, query) {
     t.equal(trans.type, 'request')
     t.equal(span.name, 'GraphQL: ' + query)
     t.equal(span.type, 'db.graphql.execute')
-    t.ok(span.start + span.duration < trans.duration)
+
+    var offset = span.timestamp - trans.timestamp
+    t.ok(offset + span.duration * 1000 < trans.duration * 1000)
 
     t.end()
   }

test/instrumentation/modules/express-queue.js

@@ -89,7 +89,9 @@ function done (t, query) {
       const span = findObjInArray(data.spans, 'transaction_id', trans.id)
       t.equal(span.name, 'foo', 'span name should be foo')
       t.equal(span.type, 'bar', 'span name should be bar')
-      t.ok(span.start + span.duration < trans.duration, 'span should have valid timings')
+
+      var offset = span.timestamp - trans.timestamp
+      t.ok(offset + span.duration * 1000 < trans.duration * 1000, 'span should have valid timings')
     })
 
     t.end()