fix(plugins): use process.hrtime() for duration calculation (#1507)

lib/plugins/audit.js

@@ -6,6 +6,7 @@ var assert = require('assert-plus');
 var bunyan = require('bunyan');
 var HttpError = require('restify-errors').HttpError;
 var VError = require('verror');
+var hrTimeDurationInMs = require('./utils/hrTimeDurationInMs');
 
 /**
  * Utility to get response headers from a given response.
@@ -133,7 +134,7 @@ function auditLogger(opts) {
         var latency = res.get('Response-Time');
 
         if (typeof (latency) !== 'number') {
-            latency = Date.now() - req._time;
+            latency = hrTimeDurationInMs(req._time, process.hrtime());
         }
 
         var obj = {

lib/plugins/fullResponse.js

@@ -4,6 +4,7 @@
 
 var crypto = require('crypto');
 var httpDate = require('./utils/httpDate');
+var hrTimeDurationInMs = require('./utils/hrTimeDurationInMs');
 
 
 ///--- API
@@ -44,7 +45,8 @@ function setHeaders(req, res) {
     }
 
     if (!res.getHeader('Response-Time')) {
-        res.setHeader('Response-Time', now.getTime() - req._time);
+        res.setHeader('Response-Time',
+            hrTimeDurationInMs(req._time, process.hrtime()));
     }
 
 }

lib/plugins/metrics.js

@@ -1,6 +1,7 @@
 'use strict';
 
 var assert = require('assert-plus');
+var hrTimeDurationInMs = require('./utils/hrTimeDurationInMs');
 
 
 ///--- API
@@ -37,7 +38,7 @@ function createMetrics(opts, callback) {
             // REST verb
             method: req.method,
             // overall request latency
-            latency: Date.now() - req._time,
+            latency: hrTimeDurationInMs(req._time, process.hrtime()),
             // the cleaned up url path
             // e.g., /foo?a=1 => /foo
             path: req.path(),

lib/plugins/utils/hrTimeDurationInMs.js

@@ -0,0 +1,21 @@
+'use strict';
+
+var NS_PER_SEC = 1e9;
+var MS_PER_NS = 1e6;
+
+/**
+* Get duration in milliseconds from two process.hrtime()
+* @function hrTimeDurationInMs
+* @param {Array} startTime - [seconds, nanoseconds]
+* @param {Array} endTime - [seconds, nanoseconds]
+* @returns {Number} durationInMs
+*/
+function hrTimeDurationInMs (startTime, endTime) {
+    var secondDiff = endTime[0] - startTime[0];
+    var nanoSecondDiff = endTime[1] - startTime[1];
+    var diffInNanoSecond = secondDiff * NS_PER_SEC + nanoSecondDiff;
+
+    return Math.round(diffInNanoSecond / MS_PER_NS);
+}
+
+module.exports = hrTimeDurationInMs;

lib/server.js

@@ -1076,7 +1076,7 @@ Server.prototype._setupRequest = function _setupRequest(req, res) {
 
     var self = this;
     req.log = res.log = self.log;
-    req._time = res._time = Date.now();
+    req._time = process.hrtime();
     req.serverName = self.name;
 
     res.acceptable = self.acceptable;

test/plugins/utilsHrTimeDurationInMs.test.js

@@ -0,0 +1,18 @@
+'use strict';
+
+var assert = require('chai').assert;
+var hrTimeDurationInMs =
+    require('../../lib/plugins/utils/hrTimeDurationInMs');
+
+describe('utils #hrTimeDurationInMs', function () {
+
+    it('should return with duration', function () {
+        var startTime = [0, 0];
+        var endTime = [1, 1e6];
+
+        var duration = hrTimeDurationInMs(startTime, endTime);
+
+        assert.equal(duration, 1001);
+    });
+
+});