feat(HttpClient): add timings to res

README.md

@@ -131,7 +131,7 @@ var client = restify.createJsonClient({
   url: 'https://api.us-east-1.joyent.com',
   version: '*'
 });
-```    
+```
 
 ### API Options:
 
@@ -469,6 +469,23 @@ client.get(options, function(err, res, socket, head) {
 });
 ```
 
+#### Timings
+
+Request timings are available under the `req.getTimings()` in milliseconds:
+
+```javascript
+{
+  dnsLookup: 34,
+  tcpConnection: 52,
+  tlsHandshake: 112,
+  firstByte: 66,
+  contentTransfer: 2,
+  total: 266
+}
+```
+
+All timings except `total` can be `null` under various circumstances like
+keep-alive connection, missing https etc.
 
 ## Contributing
 

lib/HttpClient.js

@@ -22,6 +22,7 @@ var bunyanHelper = require('./helpers/bunyan');
 var dtrace = require('./helpers/dtrace');
 var auditor = require('./helpers/auditor');
 var errors = require('restify-errors');
+var getTimingsFromEventTimes = require('./helpers/timings').getTimings;
 
 // Use native KeepAlive in Node as of 0.11.6
 var semver = require('semver');
@@ -123,6 +124,15 @@ function rawRequest(opts, cb) {
     var id = dtrace.nextId();
     var log = opts.log;
     var proto = opts.protocol === 'https:' ? https : http;
+    var eventTimes = {
+        // use process.hrtime() as it's not a subject of clock drift
+        startAt: process.hrtime(),
+        dnsLookupAt: null,
+        tcpConnectionAt: null,
+        tlsHandshakeAt: null,
+        firstByteAt: null,
+        endAt: null
+    };
     var connectionTimer;
     var requestTimer;
     var req;
@@ -219,6 +229,19 @@ function rawRequest(opts, cb) {
 
         req.removeAllListeners('socket');
 
+        res.once('readable', function onReadable () {
+            eventTimes.firstByteAt = process.hrtime();
+        });
+
+        // End event is not emitted when stream is not consumed fully
+        // in our case we consume it see: res.on('data')
+        res.once('end', function onEnd () {
+            eventTimes.endAt = process.hrtime();
+            req.getTimings = function getTimings () {
+                return getTimingsFromEventTimes(eventTimes);
+            };
+        });
+
         emitResult((err || null), req, res);
     });
     req.log = log;
@@ -278,9 +301,19 @@ function rawRequest(opts, cb) {
             return;
         }
 
+        _socket.once('lookup', function onLookup () {
+            eventTimes.dnsLookupAt = process.hrtime();
+        });
+
+        _socket.once('secureConnect', function () {
+            eventTimes.tlsHandshakeAt = process.hrtime();
+        });
+
         _socket.once('connect', function onConnect() {
             clearTimeout(connectionTimer);
 
+            eventTimes.tcpConnectionAt = process.hrtime();
+
             if (opts._keep_alive) {
                 _socket.setKeepAlive(true);
                 socket.setKeepAlive(true);

lib/helpers/timings.js

@@ -0,0 +1,71 @@
+'use strict';
+
+var NS_PER_SEC = 1e9;
+var MS_PER_NS = 1e6;
+
+/**
+* Get duration in milliseconds from two process.hrtime()
+* @function getHrTimeDurationInMs
+* @param {Array} startTime - [seconds, nanoseconds]
+* @param {Array} endTime - [seconds, nanoseconds]
+* @returns {Number|null} durationInMs
+*/
+function getHrTimeDurationInMs (startTime, endTime) {
+    if (startTime === null || endTime === null) {
+        return null;
+    }
+
+    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);
+}
+
+/**
+* Calculates HTTP timings
+* @function getTimings
+* @param {Object} eventTimes - Timings
+* @param {Number} eventTimes.startAt - Request started
+* @param {Number|undefined} eventTimes.dnsLookupAt - DNS resolved
+* @param {Number} eventTimes.tcpConnectionAt - TCP connection estabilished
+* @param {Number|undefined} eventTimes.tlsHandshakeAt - TLS handshake finished
+* @param {Number} eventTimes.firstByteAt - First byte arrived
+* @param {Number} eventTimes.endAt - Request ended
+* @returns {Object} timings - { dnsLookup, tcpConnection, tlsHandshake,
+*                               firstByte, contentTransfer, total }
+*/
+function getTimings (eventTimes) {
+    return {
+        // There is no DNS lookup with IP address, can be null
+        dnsLookup: getHrTimeDurationInMs(
+            eventTimes.startAt,
+            eventTimes.dnsLookupAt
+        ),
+        tcpConnection: getHrTimeDurationInMs(
+            eventTimes.dnsLookupAt || eventTimes.startAt,
+            eventTimes.tcpConnectionAt
+        ),
+        // There is no TLS handshake without https, can be null
+        tlsHandshake: getHrTimeDurationInMs(
+            eventTimes.tcpConnectionAt,
+            eventTimes.tlsHandshakeAt
+        ),
+        firstByte: getHrTimeDurationInMs((
+            // There is no TLS/TCP Connection with keep-alive connection
+            eventTimes.tlsHandshakeAt || eventTimes.tcpConnectionAt ||
+                eventTimes.startAt),
+            eventTimes.firstByteAt
+        ),
+        contentTransfer: getHrTimeDurationInMs(
+            eventTimes.firstByteAt,
+            eventTimes.endAt
+        ),
+        total: getHrTimeDurationInMs(eventTimes.startAt, eventTimes.endAt)
+    };
+}
+
+module.exports = {
+    getHrTimeDurationInMs: getHrTimeDurationInMs,
+    getTimings: getTimings
+};

test/e2e.js

@@ -0,0 +1,31 @@
+'use strict';
+
+var assert = require('chai').assert;
+var clients = require('../lib');
+
+
+// --- Tests
+
+describe('restify-client tests against real web server', function () {
+    it('have timings', function (done) {
+        var client = clients.createJsonClient({
+            url: 'https://netflix.com'
+        });
+
+        client.get('/', function (err, req, res) {
+            assert.ifError(err);
+
+            var timings = req.getTimings();
+
+            assert.isObject(timings);
+            assert.isNumber(timings.dnsLookup);
+            assert.isNumber(timings.tlsHandshake);
+            assert.isNumber(timings.tcpConnection);
+            assert.isNumber(timings.firstByte);
+            assert.isNumber(timings.contentTransfer);
+            assert.isNumber(timings.total);
+            done();
+        });
+    });
+});
+

test/index.js

@@ -283,6 +283,56 @@ describe('restify-client tests', function () {
         }
     });
 
+    describe('req.getTimings()', function () {
+        var TIMINGS_CLIENT_IP;
+        var TIMINGS_CLIENT_HOST;
+
+        beforeEach(function () {
+            TIMINGS_CLIENT_IP = clients.createJsonClient({
+                url: 'http://127.0.0.1:' + PORT,
+                retry: false
+            });
+            TIMINGS_CLIENT_HOST = clients.createJsonClient({
+                url: 'http://localhost:' + PORT,
+                retry: false
+            });
+        });
+
+        afterEach(function () {
+            TIMINGS_CLIENT_IP.close();
+            TIMINGS_CLIENT_HOST.close();
+        });
+
+        it('returns timings with IP', function (done) {
+            TIMINGS_CLIENT_IP.get('/json/mcavage', function (err, req, res) {
+                assert.ifError(err);
+                var timings = req.getTimings();
+                assert.isObject(timings);
+                assert.isNull(timings.dnsLookup);
+                assert.isNull(timings.tlsHandshake);
+                assert.isNumber(timings.tcpConnection);
+                assert.isNumber(timings.firstByte);
+                assert.isNumber(timings.contentTransfer);
+                assert.isNumber(timings.total);
+                done();
+            });
+        });
+
+        it('returns timings with Host', function (done) {
+            TIMINGS_CLIENT_HOST.get('/json/mcavage', function (err, req, res) {
+                assert.ifError(err);
+                var timings = req.getTimings();
+                assert.isObject(timings);
+                assert.isNumber(timings.dnsLookup);
+                assert.isNull(timings.tlsHandshake);
+                assert.isNumber(timings.tcpConnection);
+                assert.isNumber(timings.firstByte);
+                assert.isNumber(timings.contentTransfer);
+                assert.isNumber(timings.total);
+                done();
+            });
+        });
+    });
 
     it('GET json', function (done) {
         JSON_CLIENT.get('/json/mcavage', function (err, req, res, obj) {