Timings: Tracks 'lookup', adds 'wait' time, fixes connection re-use (#…

…2566)

* Timings: Tracks 'lookup', adds 'wait' time, fixes connection re-use

* Don’t re-add event listeners on Keep-Alive, run only .once(), and cleanup on error

* Fixed documentation

README.md

@@ -812,17 +812,23 @@ 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. 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`)
-  - `firstByte`: Duration of HTTP server response (`timings.response` - `timings.connect`)
-  - `download`: Duration of HTTP download (`timings.end` - `timings.response`)
-  - `total`: Duration entire HTTP round-trip (`timings.end` - `timings.start`)
+- `time` - If `true`, the request-response cycle (including all redirects) is timed at millisecond resolution. When set, the following properties are added to the response object:
+  - `elapsedTime` Duration of the entire request/response in milliseconds (*deprecated*).
+  - `responseStartTime` Timestamp when the response began (in Unix Epoch milliseconds) (*deprecated*).
+  - `timingStart` Timestamp of the start of the request (in Unix Epoch milliseconds).
+  - `timings` Contains event timestamps in millisecond resolution relative to `timingStart`. If there were redirects, the properties reflect the timings of the final request in the redirect chain:
+    - `socket` Relative 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.
+    - `lookup` Relative timestamp when the [`net`](https://nodejs.org/api/net.html#net_event_lookup) module's `lookup` event fires. This happens when the DNS has been resolved.
+    - `connect`: Relative timestamp when the [`net`](https://nodejs.org/api/net.html#net_event_connect) module's `connect` event fires. This happens when the server acknowledges the TCP connection.
+    - `response`: Relative 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`: Relative timestamp when the last bytes of the response are received.
+  - `timingPhases` Contains the durations of each request phase. If there were redirects, the properties reflect the timings of the final request in the redirect chain:
+    - `wait`: Duration of socket initialization (`timings.socket`)
+    - `dns`: Duration of DNS lookup (`timings.lookup` - `timings.socket`)
+    - `tcp`: Duration of TCP connection (`timings.connect` - `timings.socket`)
+    - `firstByte`: Duration of HTTP server response (`timings.response` - `timings.connect`)
+    - `download`: Duration of HTTP download (`timings.end` - `timings.response`)
+    - `total`: Duration entire HTTP round-trip (`timings.end`)
 
 - `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

request.js

@@ -715,7 +715,13 @@ Request.prototype.start = function () {
   var self = this
 
   if (self.timing) {
-    var startTime = now()
+    // All timings will be relative to this request's startTime.  In order to do this,
+    // we need to capture the wall-clock start time (via Date), immediately followed
+    // by the high-resolution timer (via now()).  While these two won't be set
+    // at the _exact_ same time, they should be close enough to be able to calculate
+    // high-resolution, monotonically non-decreasing timestamps relative to startTime.
+    var startTime = new Date().getTime()
+    var startTimeNow = now()
   }
 
   if (self._aborted) {
@@ -753,10 +759,12 @@ Request.prototype.start = function () {
   }
 
   if (self.timing) {
-    self.startTime = new Date().getTime()
-    self.timings = {
-      start: startTime
-    }
+    self.startTime = startTime
+    self.startTimeNow = startTimeNow
+
+    // Timing values will all be relative to startTime (by comparing to startTimeNow
+    // so we have an accurate clock)
+    self.timings = {}
   }
 
   var timeout
@@ -774,11 +782,29 @@ Request.prototype.start = function () {
     self.emit('drain')
   })
   self.req.on('socket', function(socket) {
+    // `._connecting` was the old property which was made public in node v6.1.0
+    var isConnecting = socket._connecting || socket.connecting
     if (self.timing) {
-      self.timings.socket = now()
-      socket.on('connect', function() {
-        self.timings.connect = now()
-      })
+      self.timings.socket = now() - self.startTimeNow
+
+      if (isConnecting) {
+        var onLookupTiming = function() {
+          self.timings.lookup = now() - self.startTimeNow
+        }
+
+        var onConnectTiming = function() {
+          self.timings.connect = now() - self.startTimeNow
+        }
+
+        socket.once('lookup', onLookupTiming)
+        socket.once('connect', onConnectTiming)
+
+        // clean up timing event listeners if needed on error
+        self.req.once('error', function() {
+          socket.removeListener('lookup', onLookupTiming)
+          socket.removeListener('connect', onConnectTiming)
+        })
+      }
     }
 
     var setReqTimeout = function() {
@@ -797,8 +823,6 @@ Request.prototype.start = function () {
         }
       })
     }
-    // `._connecting` was the old property which was made public in node v6.1.0
-    var isConnecting = socket._connecting || socket.connecting
     if (timeout !== undefined) {
       // Only start the connection timer if we're actually connecting a new
       // socket, otherwise if we're already connected (because this is a
@@ -864,30 +888,50 @@ Request.prototype.onRequestResponse = function (response) {
   var self = this
 
   if (self.timing) {
-    self.timings.response = now()
+    self.timings.response = now() - self.startTimeNow
   }
 
   debug('onRequestResponse', self.uri.href, response.statusCode, response.headers)
   response.on('end', function() {
     if (self.timing) {
-      self.timings.end = now()
+      self.timings.end = now() - self.startTimeNow
+      response.timingStart = self.startTime
 
-      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
+      // fill in the blanks for any periods that didn't trigger, such as
+      // no lookup or connect due to keep alive
+      if (!self.timings.socket) {
+        self.timings.socket = 0
+      }
+      if (!self.timings.lookup) {
+        self.timings.lookup = self.timings.socket
+      }
+      if (!self.timings.connect) {
+        self.timings.connect = self.timings.lookup
+      }
+      if (!self.timings.response) {
+        self.timings.response = self.timings.connect
+      }
 
-      debug('elapsed time', self.timings.total)
+      debug('elapsed time', self.timings.end)
 
       // elapsedTime includes all redirects
-      self.elapsedTime += Math.round(self.timings.total)
+      self.elapsedTime += Math.round(self.timings.end)
 
       // NOTE: elapsedTime is deprecated in favor of .timings
       response.elapsedTime = self.elapsedTime
 
       // timings is just for the final fetch
       response.timings = self.timings
+
+      // pre-calculate phase timings as well
+      response.timingPhases = {
+        wait: self.timings.socket,
+        dns: self.timings.lookup - self.timings.socket,
+        tcp: self.timings.connect - self.timings.lookup,
+        firstByte: self.timings.response - self.timings.connect,
+        download: self.timings.end - self.timings.response,
+        total: self.timings.end
+      }
     }
     debug('response end', self.uri.href, response.statusCode, response.headers)
   })

tests/test-timing.js

@@ -27,23 +27,31 @@ tape('setup', function(t) {
 
 tape('non-redirected request is timed', function(t) {
   var options = {time: true}
+  var start = new Date().getTime()
   var r = request('http://localhost:' + plain_server.port + '/', options, function(err, res, body) {
+    var end = new Date().getTime()
     t.equal(err, null)
     t.equal(typeof res.elapsedTime, 'number')
     t.equal(typeof res.responseStartTime, 'number')
+    t.equal(typeof res.timingStart, 'number')
+    t.equal((res.timingStart >= start), true)
     t.equal(typeof res.timings, 'object')
     t.equal((res.elapsedTime > 0), true)
+    t.equal((res.elapsedTime <= (end - start)), 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.socket >= 0), true)
+    t.equal((res.timings.lookup >= res.timings.socket), true)
+    t.equal((res.timings.connect >= res.timings.lookup), 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.equal(typeof res.timingPhases, 'object')
+    t.equal((res.timingPhases.wait >= 0), true)
+    t.equal((res.timingPhases.dns >= 0), true)
+    t.equal((res.timingPhases.tcp >= 0), true)
+    t.equal((res.timingPhases.firstByte > 0), true)
+    t.equal((res.timingPhases.download > 0), true)
+    t.equal((res.timingPhases.total > 0), true)
+    t.equal((res.timingPhases.total <= (end - start)), true)
 
     // validate there are no unexpected properties
     var propNames = []
@@ -52,8 +60,15 @@ tape('non-redirected request is timed', function(t) {
         propNames.push(propName)
       }
     }
-    t.deepEqual(propNames, ['start', 'socket', 'connect', 'response', 'end', 'dns',
-      'tcp', 'firstByte', 'download', 'total'])
+    t.deepEqual(propNames, ['socket', 'lookup', 'connect', 'response', 'end'])
+
+    propNames = []
+    for (var propName in res.timingPhases) {
+      if (res.timingPhases.hasOwnProperty(propName)) {
+        propNames.push(propName)
+      }
+    }
+    t.deepEqual(propNames, ['wait', 'dns', 'tcp', 'firstByte', 'download', 'total'])
 
     t.end()
   })