Adds .timings array with DNC, TCP, request and response times

README.md

@@ -812,7 +812,17 @@ default in Linux can be anywhere from 20-120 seconds][linux-timeout]).
 
 ---
 
-- `time` - If `true`, the request-response cycle (including all redirects) is timed at millisecond resolution, and the result provided on the response's `elapsedTime` property. The `responseStartTime` property is also available to indicate the timestamp when the response begins.
+- `time` - If `true`, the request-response cycle (including all redirects) is timed at millisecond resolution, and the result provided on the response's `elapsedTime` property. The `responseStartTime` property is also available to indicate the timestamp when the response begins.  In addition, there is a `.timings` object available with the following properties:
+  - `start`: Timestamp when `request()` was initialized
+  - `socket` Timestamp when the [`http`](https://nodejs.org/api/http.html#http_event_socket) module's `socket` event fires.  This happens when the socket is assigned to the request (after DNS has been resolved).
+  -  `connect`: Timestamp when the [`http`](https://nodejs.org/api/http.html#http_event_connect) module's `connect` event fires.  This happens when the server acknowledges the TCP connection.
+  - `response`: Timestamp when the [`http`](https://nodejs.org/api/http.html#http_event_response) module's `response` event fires.  This happens when the first bytes are received from the server.
+  - `end`: Timestamp when the last bytes of the response are received.
+  - `dns`: Duration of DNS lookup (`timings.socket` - `timings.start`)
+  - `tcp`: Duration of TCP connection (`timings.connect` - `timings.socket`)
+  - `download`: Duration HTTP fetch (`timings.end` - `timings.response`)
+  - `total`: Duration entire HTTP round-trip (`timings.end` - `timings.start`)
+
 - `har` - A [HAR 1.2 Request Object](http://www.softwareishard.com/blog/har-12-spec/#request), will be processed from HAR format into options overwriting matching values *(see the [HAR 1.2 section](#support-for-har-1.2) for details)*
 - `callback` - alternatively pass the request's callback in the options object
 

package.json

@@ -38,6 +38,7 @@
     "mime-types": "~2.1.7",
     "node-uuid": "~1.4.7",
     "oauth-sign": "~0.8.1",
+    "performance-now": "^0.2.0",
     "qs": "~6.3.0",
     "stringstream": "~0.0.4",
     "tough-cookie": "~2.3.0",

request.js

@@ -28,6 +28,7 @@ var http = require('http')
   , Multipart = require('./lib/multipart').Multipart
   , Redirect = require('./lib/redirect').Redirect
   , Tunnel = require('./lib/tunnel').Tunnel
+  , now = require('performance-now')
 
 var safeStringify = helpers.safeStringify
   , isReadStream = helpers.isReadStream
@@ -713,6 +714,10 @@ Request.prototype.start = function () {
   // this is usually called on the first write(), end() or on nextTick()
   var self = this
 
+  if (self.timing) {
+    var startTime = now()
+  }
+
   if (self._aborted) {
     return
   }
@@ -749,6 +754,9 @@ Request.prototype.start = function () {
 
   if (self.timing) {
     self.startTime = new Date().getTime()
+    self.timings = {
+      start: startTime
+    }
   }
 
   var timeout
@@ -766,6 +774,13 @@ Request.prototype.start = function () {
     self.emit('drain')
   })
   self.req.on('socket', function(socket) {
+    if (self.timing) {
+      self.timings.socket = now()
+      socket.on('connect', function() {
+        self.timings.connect = now()
+      })
+    }
+
     var setReqTimeout = function() {
       // This timeout sets the amount of time to wait *between* bytes sent
       // from the server once connected.
@@ -847,12 +862,30 @@ Request.prototype.onRequestError = function (error) {
 
 Request.prototype.onRequestResponse = function (response) {
   var self = this
+
+  if (self.timing) {
+    self.timings.response = now()
+  }
+
   debug('onRequestResponse', self.uri.href, response.statusCode, response.headers)
   response.on('end', function() {
     if (self.timing) {
-      self.elapsedTime += (new Date().getTime() - self.startTime)
-      debug('elapsed time', self.elapsedTime)
+      self.timings.end = now()
+
+      self.timings.dns = self.timings.socket - self.timings.start
+      self.timings.tcp = self.timings.connect - self.timings.socket
+      self.timings.firstByte = self.timings.response - self.timings.connect
+      self.timings.download = self.timings.end - self.timings.response
+      self.timings.total = self.timings.end - self.timings.start
+
+      debug('elapsed time', self.timings.total)
+
+      // elapsedTime includes all redirects
+      self.elapsedTime += Math.round(self.timings.total)
       response.elapsedTime = self.elapsedTime
+
+      // timings is just for the final fetch
+      response.timings = self.timings
     }
     debug('response end', self.uri.href, response.statusCode, response.headers)
   })

tests/test-timing.js

@@ -31,8 +31,19 @@ tape('non-redirected request is timed', function(t) {
     t.equal(err, null)
     t.equal(typeof res.elapsedTime, 'number')
     t.equal(typeof res.responseStartTime, 'number')
+    t.equal(typeof res.timings, 'object')
     t.equal((res.elapsedTime > 0), true)
     t.equal((res.responseStartTime > r.startTime), true)
+    t.equal((res.timings.start > 0), true)
+    t.equal((res.timings.socket >= res.timings.start), true)
+    t.equal((res.timings.connect >= res.timings.socket), true)
+    t.equal((res.timings.response >= res.timings.connect), true)
+    t.equal((res.timings.end >= res.timings.response), true)
+    t.equal((res.timings.dns >= 0), true)
+    t.equal((res.timings.tcp > 0), true)
+    t.equal((res.timings.firstByte > 0), true)
+    t.equal((res.timings.download > 0), true)
+    t.equal((res.timings.total > 0), true)
     t.end()
   })
 })