Add option to time request/response cycle (including rollup of redirects)

README.md

@@ -615,7 +615,7 @@ The first argument can be either a `url` or an `options` object. The only requir
 * `hawk` - Options for [Hawk signing](https://github.com/hueniverse/hawk). The `credentials` key must contain the necessary signing info, [see hawk docs for details](https://github.com/hueniverse/hawk#usage-example).
 * `strictSSL` - If `true`, requires SSL certificates be valid. **Note:** to use your own certificate authority, you need to specify an agent that was created with that CA as an option.
 * `agentOptions` - Object containing user agent options. See documentation above. **Note:** [see tls API doc for TLS/SSL options](http://nodejs.org/api/tls.html#tls_tls_connect_options_callback).
-
+* `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.
 * `jar` - If `true` and `tough-cookie` is installed, remember cookies for future use (or define your custom cookie jar; see examples section)
 * `aws` - `object` containing AWS signing information. Should have the properties `key`, `secret`. Also requires the property `bucket`, unless you’re specifying your `bucket` as part of the path, or the request doesn’t use a bucket (i.e. GET Services)
 * `httpSignature` - Options for the [HTTP Signature Scheme](https://github.com/joyent/node-http-signature/blob/master/http_signing.md) using [Joyent's library](https://github.com/joyent/node-http-signature). The `keyId` and `key` properties must be specified. See the docs for other options.

request.js

@@ -282,7 +282,7 @@ Request.prototype.setupTunnel = function () {
   if (typeof self.proxy === 'string') {
     self.proxy = url.parse(self.proxy)
   }
-  
+
   if (!self.proxy || !self.tunnel) {
     return false
   }
@@ -298,7 +298,7 @@ Request.prototype.setupTunnel = function () {
   self.proxyHeaders = constructProxyHeaderWhiteList(self.headers, proxyHeaderWhiteList)
   self.proxyHeaders.host = constructProxyHost(self.uri)
   proxyHeaderExclusiveList.forEach(self.removeHeader, self)
- 
+
   // Set Agent from Tunnel Data
   var tunnelFn = getTunnelFn(self)
   var tunnelOptions = constructTunnelOptions(self)
@@ -548,6 +548,11 @@ Request.prototype.init = function (options) {
     self.multipart(options.multipart)
   }
 
+  if (options.time) {
+    self.timing = true
+    self.elapsedTime = self.elapsedTime || 0
+  }
+
   if (self.body) {
     var length = 0
     if (!Buffer.isBuffer(self.body)) {
@@ -869,6 +874,7 @@ Request.prototype.start = function () {
   // start() is called once we are ready to send the outgoing HTTP request.
   // this is usually called on the first write(), end() or on nextTick()
   var self = this
+    , startTime
 
   if (self._aborted) {
     return
@@ -891,8 +897,14 @@ Request.prototype.start = function () {
   delete reqOptions.auth
 
   debug('make request', self.uri.href)
+
+  startTime = new Date().getTime()
   self.req = self.httpModule.request(reqOptions)
 
+  if (self.timing) {
+    self.startTime = startTime
+  }
+
   if (self.timeout && !self.timeoutTimer) {
     self.timeoutTimer = setTimeout(function () {
       self.abort()
@@ -955,6 +967,11 @@ Request.prototype.onRequestResponse = function (response) {
   var self = this
   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)
+      response.elapsedTime = self.elapsedTime
+    }
     debug('response end', self.uri.href, response.statusCode, response.headers)
   })
 

tests/test-timing.js

@@ -0,0 +1,62 @@
+'use strict'
+
+var http = require('http')
+  , server = require('./server')
+  , request = require('../index')
+  , tape = require('tape')
+
+var plain_server = server.createServer()
+  , redirect_mock_time = 10
+
+tape('setup', function(t) {
+  plain_server.listen(plain_server.port, function() {
+    plain_server.on('/', function (req, res) {
+      res.writeHead(200)
+      res.end('plain')
+    })
+    plain_server.on('/redir', function (req, res) {
+      // fake redirect delay to ensure strong signal for rollup check
+      setTimeout(function() {
+        res.writeHead(301, { 'location': 'http://localhost:' + plain_server.port + '/' })
+        res.end()
+      }, redirect_mock_time)
+    })
+
+    request('http://localhost:' + plain_server.port + '/', {}, function(err, res, body) {
+      t.equal(err, null)
+    })
+
+    t.end()
+  })
+})
+
+tape('no-op', function(t) {
+  t.end()
+})
+
+tape('non-redirected request is timed', function(t) {
+  var options = {time: true}
+  request('http://localhost:' + plain_server.port + '/', options, function(err, res, body) {
+    t.equal(err, null)
+    t.equal(typeof res.elapsedTime, 'number')
+    t.equal((res.elapsedTime > 0), true)
+    t.end()
+  })
+})
+
+tape('redirected request is timed with rollup', function(t) {
+  var options = {time: true}
+  request('http://localhost:' + plain_server.port + '/redir', options, function(err, res, body) {
+    t.equal(err, null)
+    t.equal(typeof res.elapsedTime, 'number')
+    t.equal((res.elapsedTime > 0), true)
+    t.equal((res.elapsedTime > redirect_mock_time), true)
+    t.end()
+  })
+})
+
+tape('cleanup', function(t) {
+  plain_server.close(function() {
+    t.end()
+  })
+})