From e8efd6cdcb73e674583e2a7081d2a9b923c72809 Mon Sep 17 00:00:00 2001
From: Peter Marton <email@martonpeter.com>
Date: Mon, 9 Oct 2017 17:45:10 +0200
Subject: [PATCH] fix(plugins): use process.hrtime() for duration calculation
 (#1507)

---
 lib/plugins/audit.js                         |  3 ++-
 lib/plugins/fullResponse.js                  |  4 +++-
 lib/plugins/metrics.js                       |  3 ++-
 lib/plugins/utils/hrTimeDurationInMs.js      | 21 ++++++++++++++++++++
 lib/server.js                                |  2 +-
 test/plugins/utilsHrTimeDurationInMs.test.js | 18 +++++++++++++++++
 6 files changed, 47 insertions(+), 4 deletions(-)
 create mode 100644 lib/plugins/utils/hrTimeDurationInMs.js
 create mode 100644 test/plugins/utilsHrTimeDurationInMs.test.js

diff --git a/lib/plugins/audit.js b/lib/plugins/audit.js
index c861e155c..2276122ef 100644
--- a/lib/plugins/audit.js
+++ b/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 = {
diff --git a/lib/plugins/fullResponse.js b/lib/plugins/fullResponse.js
index 541a052f7..b2b6e9de7 100644
--- a/lib/plugins/fullResponse.js
+++ b/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()));
     }
 
 }
diff --git a/lib/plugins/metrics.js b/lib/plugins/metrics.js
index d3789b3f9..a1296b1f5 100644
--- a/lib/plugins/metrics.js
+++ b/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(),
diff --git a/lib/plugins/utils/hrTimeDurationInMs.js b/lib/plugins/utils/hrTimeDurationInMs.js
new file mode 100644
index 000000000..665334b17
--- /dev/null
+++ b/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;
diff --git a/lib/server.js b/lib/server.js
index 13b484aa2..6e41c4c41 100644
--- a/lib/server.js
+++ b/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;
diff --git a/test/plugins/utilsHrTimeDurationInMs.test.js b/test/plugins/utilsHrTimeDurationInMs.test.js
new file mode 100644
index 000000000..d56e05b90
--- /dev/null
+++ b/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);
+    });
+
+});