From 891e7377dc2b20b685967d882b678e473c3b2d18 Mon Sep 17 00:00:00 2001 From: Peter Marton Date: Tue, 13 Feb 2018 11:10:50 -0500 Subject: [PATCH] feat(plugins): add pre, use and route handlers latencies to metrics plugin --- docs/_api/plugins.md | 3 + docs/guides/6to7guide.md | 11 +++ lib/plugins/metrics.js | 9 ++ lib/plugins/utils/hrTimeDurationInMs.js | 6 +- lib/server.js | 18 ++++ test/plugins/metrics.test.js | 113 +++++++++++++++++++++++- 6 files changed, 156 insertions(+), 4 deletions(-) diff --git a/docs/_api/plugins.md b/docs/_api/plugins.md index c28b1d942..31da1ad54 100644 --- a/docs/_api/plugins.md +++ b/docs/_api/plugins.md @@ -1145,6 +1145,9 @@ Type: [Function](https://developer.mozilla.org/docs/Web/JavaScript/Reference/Sta 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.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 - `metrics.path` **[String](https://developer.mozilla.org/docs/Web/JavaScript/Reference/Global_Objects/String)** `req.path()` value - `metrics.inflightRequests` **[Number](https://developer.mozilla.org/docs/Web/JavaScript/Reference/Global_Objects/Number)** Number of inflight requests pending in restify. diff --git a/docs/guides/6to7guide.md b/docs/guides/6to7guide.md index 63170da41..a7590e932 100644 --- a/docs/guides/6to7guide.md +++ b/docs/guides/6to7guide.md @@ -155,3 +155,14 @@ server.get('/hello/:name', restify.plugins.conditionalHandler([ // 'accept-version': '^1.1.0' => 1.5.x, 2.x' // 'accept-version': '3.x', accept: 'application/json' => '3.x, json' ``` + +### Metrics plugin latency + +In 7.x Metrics plugin's `latency` is calculated when the request is +fully flushed. Earlier it was calculated when the last handler finished. + +To address the previous use-cases, new timings were added to the metrics plugin: + + - `metrics.preLatency` pre handlers latency + - `metrics.useLatency` use handlers latency + - `metrics.routeLatency` route handlers latency diff --git a/lib/plugins/metrics.js b/lib/plugins/metrics.js index f5000e17e..a3d07cf18 100644 --- a/lib/plugins/metrics.js +++ b/lib/plugins/metrics.js @@ -40,6 +40,12 @@ function createMetrics(opts, callback) { method: req.method, // overall request latency latency: hrTimeDurationInMs(req._time, process.hrtime()), + preLatency: hrTimeDurationInMs(req._timePreStart, req._timePreEnd), + useLatency: hrTimeDurationInMs(req._timeUseStart, req._timeUseEnd), + routeLatency: hrTimeDurationInMs( + req._timeRouteStart, + req._timeRouteEnd + ), // the cleaned up url path // e.g., /foo?a=1 => /foo path: req.path(), @@ -72,6 +78,9 @@ function createMetrics(opts, callback) { * undefined in the case of an uncaughtException * @param {String} metrics.method http request verb * @param {Number} metrics.latency request latency + * @param {Number|null} metrics.preLatency pre handlers latency + * @param {Number|null} metrics.useLatency use handlers latency + * @param {Number|null} metrics.routeLatency route handlers latency * @param {String} metrics.path `req.path()` value * @param {Number} metrics.inflightRequests Number of inflight requests pending * in restify. diff --git a/lib/plugins/utils/hrTimeDurationInMs.js b/lib/plugins/utils/hrTimeDurationInMs.js index 87a472231..07321dc02 100644 --- a/lib/plugins/utils/hrTimeDurationInMs.js +++ b/lib/plugins/utils/hrTimeDurationInMs.js @@ -9,9 +9,13 @@ var MS_PER_NS = 1e6; * @function hrTimeDurationInMs * @param {Array} startTime - [seconds, nanoseconds] * @param {Array} endTime - [seconds, nanoseconds] -* @returns {Number} durationInMs +* @returns {Number|null} durationInMs */ function hrTimeDurationInMs(startTime, endTime) { + if (!Array.isArray(startTime) || !Array.isArray(endTime)) { + return null; + } + var secondDiff = endTime[0] - startTime[0]; var nanoSecondDiff = endTime[1] - startTime[1]; var diffInNanoSecond = secondDiff * NS_PER_SEC + nanoSecondDiff; diff --git a/lib/server.js b/lib/server.js index 844aa25b5..04338252d 100644 --- a/lib/server.js +++ b/lib/server.js @@ -770,6 +770,9 @@ Server.prototype.toString = function toString() { // triggers use) // 8. _finishReqResCycle (on response "finish" and "error" events) // +// Events: +// e.1 after (triggered when response is flushed) +// // Errors: // e.1 _onHandlerError (runs when next was called with an Error) // e.2 _routeErrorResponse @@ -842,8 +845,11 @@ Server.prototype._runPre = function _runPre(req, res) { // Run "pre" req._currentHandler = 'pre'; + req._timePreStart = process.hrtime(); self.preChain.run(req, res, function preChainDone(err) { + // Execution time of a handler with error can be significantly lower + req._timePreEnd = process.hrtime(); self._afterPre(err, req, res); }); }; @@ -905,7 +911,10 @@ Server.prototype._runRoute = function _runRoute(req, res) { self.emit('routed', req, res, req.route); self._runUse(req, res, function afterUse() { + req._timeRouteStart = process.hrtime(); routeHandler(req, res, function afterRouter(err) { + // Execution time of a handler with error can be significantly lower + req._timeRouteEnd = process.hrtime(); self._afterRoute(err, req, res); }); }); @@ -956,8 +965,11 @@ Server.prototype._runUse = function _runUse(req, res, next) { // Run "use" req._currentHandler = 'use'; + req._timeUseStart = process.hrtime(); self.useChain.run(req, res, function useChainDone(err) { + // Execution time of a handler with error can be significantly lower + req._timeUseEnd = process.hrtime(); self._afterUse(err, req, res, next); }); }; @@ -1088,6 +1100,12 @@ Server.prototype._setupRequest = function _setupRequest(req, res) { // Response lifecycle events function onFinish() { + // Response may get flushed before handler callback is triggered + var processHrTime = process.hrtime(); + req._timePreEnd = req._timePreEnd || processHrTime; + req._timeUseEnd = req._timeUseEnd || processHrTime; + req._timeRouteEnd = req._timeRouteEnd || processHrTime; + req.removeListener('close', onClose); res.removeListener('error', onError); self._finishReqResCycle(req, res, res.err); diff --git a/test/plugins/metrics.test.js b/test/plugins/metrics.test.js index f81f2db19..9bfa8d2ec 100644 --- a/test/plugins/metrics.test.js +++ b/test/plugins/metrics.test.js @@ -57,7 +57,10 @@ describe('request metrics plugin', function() { assert.isObject(metrics, 'metrics'); assert.equal(metrics.statusCode, 202); - assert.isAtLeast(metrics.latency, 100); + assert.isAtLeast(metrics.preLatency, 50); + assert.isAtLeast(metrics.useLatency, 50); + assert.isAtLeast(metrics.routeLatency, 50); + assert.isAtLeast(metrics.latency, 150); assert.equal(metrics.path, '/foo'); assert.equal(metrics.connectionState, undefined); assert.equal(metrics.method, 'GET'); @@ -70,11 +73,23 @@ describe('request metrics plugin', function() { ) ); + SERVER.pre(function(req, res, next) { + setTimeout(function() { + return next(); + }, 50); + }); + + SERVER.use(function(req, res, next) { + setTimeout(function() { + return next(); + }, 50); + }); + SERVER.get('/foo', function(req, res, next) { setTimeout(function() { res.send(202, 'hello world'); return next(); - }, 100); + }, 50); }); CLIENT.get('/foo?a=1', function(err, _, res) { @@ -84,6 +99,83 @@ describe('request metrics plugin', function() { }); }); + it('should return metrics with pre error', function(done) { + SERVER.on('uncaughtException', function(req, res, route, err) { + assert.ok(err); + }); + + SERVER.on( + 'after', + restify.plugins.metrics( + { + server: SERVER + }, + function(err, metrics, req, res, route) { + assert.ok(err); + + assert.isObject(metrics, 'metrics'); + assert.isAtLeast(metrics.preLatency, 50); + assert.equal(metrics.useLatency, null); + assert.equal(metrics.routeLatency, null); + assert.isAtLeast(metrics.latency, 50); + + return done(); + } + ) + ); + + SERVER.pre(function(req, res, next) { + setTimeout(function() { + return next(new Error('My Error')); + }, 50); + }); + + CLIENT.get('/foo?a=1', function(err, _, res) { + assert.ok(err); + }); + }); + + it('should return metrics with use error', function(done) { + SERVER.on('uncaughtException', function(req, res, route, err) { + assert.ok(err); + }); + + SERVER.on( + 'after', + restify.plugins.metrics( + { + server: SERVER + }, + function(err, metrics, req, res, route) { + assert.ok(err); + + assert.isObject(metrics, 'metrics'); + assert.isAtLeast(metrics.preLatency, 0); + assert.isAtLeast(metrics.useLatency, 50); + assert.equal(metrics.routeLatency, null); + assert.isAtLeast(metrics.latency, 50); + + return done(); + } + ) + ); + + SERVER.use(function(req, res, next) { + setTimeout(function() { + return next(new Error('My Error')); + }, 50); + }); + + SERVER.get('/foo', function(req, res, next) { + res.send(202, 'hello world'); + return next(); + }); + + CLIENT.get('/foo?a=1', function(err, _, res) { + assert.ok(err); + }); + }); + it("should return 'RequestCloseError' err", function(done) { // we test that the client times out and closes the request. server // flushes request responsibly but connectionState should indicate it @@ -108,6 +200,9 @@ describe('request metrics plugin', function() { // However the timeout value is 200, // it's calculated by the client, // but setTimeout is happening on the server, tolerate 10ms + assert.isAtLeast(metrics.preLatency, 50); + assert.isAtLeast(metrics.useLatency, 50); + assert.equal(metrics.routeLatency, null); assert.isAtLeast(metrics.latency, 200 - 10); assert.equal(metrics.path, '/foo'); assert.equal(metrics.method, 'GET'); @@ -118,6 +213,18 @@ describe('request metrics plugin', function() { ) ); + SERVER.pre(function(req, res, next) { + setTimeout(function() { + return next(); + }, 50); + }); + + SERVER.use(function(req, res, next) { + setTimeout(function() { + return next(); + }, 50); + }); + SERVER.get('/foo', function(req, res, next) { setTimeout(function() { assert.fail('Client has already closed request'); @@ -157,6 +264,7 @@ describe('request metrics plugin', function() { assert.equal(metrics.method, 'GET'); assert.equal(metrics.connectionState, undefined); assert.isNumber(metrics.inflightRequests); + return done(); } ) ); @@ -167,7 +275,6 @@ describe('request metrics plugin', function() { CLIENT.get('/foo?a=1', function(err, _, res) { assert.ok(err); - return done(); }); }); });