From 3616028cf2c8735dcd84b50f5da3114c0c88dcf0 Mon Sep 17 00:00:00 2001 From: Peter Marton Date: Fri, 23 Feb 2018 08:26:15 -0800 Subject: [PATCH] feat(plugins): add totalLatency to metrics plugin --- docs/_api/plugins.md | 4 +++- lib/plugins/audit.js | 2 +- lib/plugins/fullResponse.js | 4 +++- lib/plugins/metrics.js | 27 +++++++++++++++++++++++++-- lib/server.js | 3 ++- test/plugins/metrics.test.js | 1 + 6 files changed, 35 insertions(+), 6 deletions(-) diff --git a/docs/_api/plugins.md b/docs/_api/plugins.md index adc4f63cf..211d829a7 100644 --- a/docs/_api/plugins.md +++ b/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 diff --git a/lib/plugins/audit.js b/lib/plugins/audit.js index f077521ab..fbc508bc6 100644 --- a/lib/plugins/audit.js +++ b/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 = { diff --git a/lib/plugins/fullResponse.js b/lib/plugins/fullResponse.js index 0edd1d1d5..21b8c5c3c 100644 --- a/lib/plugins/fullResponse.js +++ b/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()) ); } } diff --git a/lib/plugins/metrics.js b/lib/plugins/metrics.js index 194c4e3d8..da6f74d4c 100644 --- a/lib/plugins/metrics.js +++ b/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 diff --git a/lib/server.js b/lib/server.js index 9310e1c6f..eca0a5a3d 100644 --- a/lib/server.js +++ b/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); diff --git a/test/plugins/metrics.test.js b/test/plugins/metrics.test.js index a35f26c60..e99315817 100644 --- a/test/plugins/metrics.test.js +++ b/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');