feat(plugins): add pre, use and route handlers latencies to metrics p…

…lugin
restify · Feb 13, 2018 · 3dfdcbf · 3dfdcbf
1 parent b30396f
commit 3dfdcbf
Show file tree

Hide file tree

Showing 6 changed files with 149 additions and 4 deletions.
diff --git 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
@@ -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
@@ -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
@@ -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
@@ -842,8 +842,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 +908,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 +962,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 +1097,8 @@ Server.prototype._setupRequest = function _setupRequest(req, res) {
 
     // Response lifecycle events
     function onFinish() {
+        // Response may get flushed before last handler finishes
+        req._timeRouteEnd = req._timeRouteEnd || process.hrtime();
         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
@@ -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();
         });
     });
 });