diff --git a/README.md b/README.md index a716c2337..231739114 100644 --- a/README.md +++ b/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 diff --git a/request.js b/request.js index a683a590b..de9d1e584 100644 --- a/request.js +++ b/request.js @@ -717,7 +717,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) { @@ -755,10 +761,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 @@ -776,11 +784,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() { @@ -799,8 +825,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 @@ -866,30 +890,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) }) diff --git a/tests/test-timing.js b/tests/test-timing.js index 0623195f6..bc68774a6 100644 --- a/tests/test-timing.js +++ b/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() })