feat(plugins): add totalLatency to metrics plugin

docs/_api/plugins.md

@@ -1145,7 +1145,9 @@ Type: [Function](https://developer.mozilla.org/docs/Web/JavaScript/Reference/Sta
     -   `metrics.statusCode` **[Number](https://developer.mozilla.org/docs/Web/JavaScript/Reference/Global_Objects/Number)** status code of the response. can be
           undefined in the case of an uncaughtException
     -   `metrics.method` **[String](https://developer.mozilla.org/docs/Web/JavaScript/Reference/Global_Objects/String)** http request verb
-    -   `metrics.latency` **[Number](https://developer.mozilla.org/docs/Web/JavaScript/Reference/Global_Objects/Number)** request latency
+    -   `metrics.totalLatency` **[Number](https://developer.mozilla.org/docs/Web/JavaScript/Reference/Global_Objects/Number)** latency includes both request is flushed
+                                             and all handlers finished
+    -   `metrics.latency` **[Number](https://developer.mozilla.org/docs/Web/JavaScript/Reference/Global_Objects/Number)** latency when request is flushed
     -   `metrics.preLatency` **([Number](https://developer.mozilla.org/docs/Web/JavaScript/Reference/Global_Objects/Number) | null)** pre handlers latency
     -   `metrics.useLatency` **([Number](https://developer.mozilla.org/docs/Web/JavaScript/Reference/Global_Objects/Number) | null)** use handlers latency
     -   `metrics.routeLatency` **([Number](https://developer.mozilla.org/docs/Web/JavaScript/Reference/Global_Objects/Number) | null)** route handlers latency

lib/plugins/audit.js

@@ -265,7 +265,7 @@ function auditLogger(opts) {
         var latency = res.get('Response-Time');
 
         if (typeof latency !== 'number') {
-            latency = hrTimeDurationInMs(req._time, process.hrtime());
+            latency = hrTimeDurationInMs(req._timeStart, req._timeFlushed);
         }
 
         var obj = {

lib/plugins/fullResponse.js

@@ -43,9 +43,11 @@ function setHeaders(req, res) {
     }
 
     if (!res.getHeader('Response-Time')) {
+        // we cannot use req._timeFlushed here as
+        // the response is not flushed yet
         res.setHeader(
             'Response-Time',
-            hrTimeDurationInMs(req._time, process.hrtime())
+            hrTimeDurationInMs(req._timeStart, process.hrtime())
         );
     }
 }

lib/plugins/metrics.js

@@ -3,6 +3,26 @@
 var assert = require('assert-plus');
 var hrTimeDurationInMs = require('./utils/hrTimeDurationInMs');
 
+/**
+ * Timing internals
+ *
+ * Timings are also saved when there is no handler in the given category.
+ * Some handler categories are optional, for example there is no
+ * `use` and `route` for 404.
+ *
+ * @private
+ *
+ * req._timeStart      - request lifecycle started in restify
+ * req._timePreStart   - pre handlers started
+ * req._timePreEnd     - all pre handlers finished
+ * req._timeUseStart   - use handlers started
+ * req._timeUseEnd     - all use handlers finished
+ * req._timeRouteStart - route handlers started
+ * req._timeRouteEnd   - all route handlers finished
+ * req._timeFlushed    - request flushed, may happens before handlers finished
+ * req._timeFinished   - both all handlers finished and request flushed
+ */
+
 ///--- API
 
 /**
@@ -40,7 +60,8 @@ function createMetrics(opts, callback) {
             // REST verb
             method: req.method,
             // overall request latency
-            latency: hrTimeDurationInMs(req._time, req._timeFlushed),
+            totalLatency: hrTimeDurationInMs(req._timeStart, req._timeFinished),
+            latency: hrTimeDurationInMs(req._timeStart, req._timeFlushed),
             preLatency: hrTimeDurationInMs(req._timePreStart, req._timePreEnd),
             useLatency: hrTimeDurationInMs(req._timeUseStart, req._timeUseEnd),
             routeLatency: hrTimeDurationInMs(
@@ -80,7 +101,9 @@ function createMetrics(opts, callback) {
  * @param {Number} metrics.statusCode status code of the response. can be
  *   undefined in the case of an uncaughtException
  * @param {String} metrics.method http request verb
- * @param {Number} metrics.latency request latency
+ * @param {Number} metrics.totalLatency latency includes both request is flushed
+ *                                      and all handlers finished
+ * @param {Number} metrics.latency latency when request is flushed
  * @param {Number|null} metrics.preLatency pre handlers latency
  * @param {Number|null} metrics.useLatency use handlers latency
  * @param {Number|null} metrics.routeLatency route handlers latency

lib/server.js

@@ -1090,7 +1090,7 @@ Server.prototype._setupRequest = function _setupRequest(req, res) {
     req._dtraceId = dtrace.nextId();
     req.log = res.log = self.log;
     req._date = new Date();
-    req._time = process.hrtime();
+    req._timeStart = process.hrtime();
     req.serverName = self.name;
     req.params = {};
     req.timers = [];
@@ -1198,6 +1198,7 @@ Server.prototype._finishReqResCycle = function _finishReqResCycle(
         // decrement number of requests
         self._inflightRequests--;
         res._finished = true;
+        req._timeFinished = process.hrtime();
 
         // after event has signature of function(req, res, route, err) {...}
         self.emit('after', req, res, route, err || res.err);

test/plugins/metrics.test.js

@@ -61,6 +61,7 @@ describe('request metrics plugin', function() {
                     assert.isAtLeast(metrics.useLatency, 50);
                     assert.isAtLeast(metrics.routeLatency, 50);
                     assert.isAtLeast(metrics.latency, 150);
+                    assert.isAtLeast(metrics.totalLatency, 150);
                     assert.equal(metrics.path, '/foo');
                     assert.equal(metrics.connectionState, undefined);
                     assert.equal(metrics.method, 'GET');