New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Adds .timings array with DNC, TCP, request and response times #2452
Changes from 2 commits
c5243d0
c7c9431
47523a2
21e315d
d9e8c3d
a9ad38a
3f57975
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
Original file line number | Diff line number | Diff line change |
---|---|---|
|
@@ -812,7 +812,18 @@ 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). | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. remove extra space before There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Fixed -- there were 15 other occurrences of double-spaces, so if you're going for consistency I've fixed those as well. |
||
- `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`) | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. also add firstByte description? |
||
|
||
- `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 | ||
|
||
|
Original file line number | Diff line number | Diff line change |
---|---|---|
|
@@ -36,6 +36,7 @@ var safeStringify = helpers.safeStringify | |
, copy = helpers.copy | ||
, version = helpers.version | ||
, globalCookieJar = cookies.jar() | ||
, hrTimeStart | ||
|
||
|
||
var globalPool = {} | ||
|
@@ -91,6 +92,28 @@ function responseToJSON() { | |
} | ||
} | ||
|
||
function getHrTime() { | ||
if (typeof process === 'undefined' || !process.hrtime) { | ||
return 0 | ||
} | ||
|
||
var hr = process.hrtime() | ||
// convert to nanoseconds | ||
return hr[0] * 1e9 + hr[1] | ||
} | ||
|
||
hrTimeStart = getHrTime() | ||
|
||
function getTimeFromStart() { | ||
// in the browser, use performance.now() | ||
if (typeof performance !== 'undefined' && performance.now) { | ||
return performance.now() | ||
} | ||
|
||
// in nodejs, use process.hrtime() (converting back to milliseconds) | ||
return (getHrTime() - hrTimeStart) / 1e6 | ||
} | ||
|
||
function Request (options) { | ||
// if given the method property in options, set property explicitMethod to true | ||
|
||
|
@@ -713,6 +736,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 = getTimeFromStart() | ||
} | ||
|
||
if (self._aborted) { | ||
return | ||
} | ||
|
@@ -749,6 +776,9 @@ Request.prototype.start = function () { | |
|
||
if (self.timing) { | ||
self.startTime = new Date().getTime() | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Would recommend move to |
||
self.timings = { | ||
start: startTime | ||
} | ||
} | ||
|
||
var timeout | ||
|
@@ -766,6 +796,13 @@ Request.prototype.start = function () { | |
self.emit('drain') | ||
}) | ||
self.req.on('socket', function(socket) { | ||
if (self.timing) { | ||
self.timings.socket = getTimeFromStart() | ||
socket.on('connect', function() { | ||
self.timings.connect = getTimeFromStart() | ||
}) | ||
} | ||
|
||
var setReqTimeout = function() { | ||
// This timeout sets the amount of time to wait *between* bytes sent | ||
// from the server once connected. | ||
|
@@ -847,12 +884,30 @@ Request.prototype.onRequestError = function (error) { | |
|
||
Request.prototype.onRequestResponse = function (response) { | ||
var self = this | ||
|
||
if (self.timing) { | ||
self.timings.response = getTimeFromStart() | ||
} | ||
|
||
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 = getTimeFromStart() | ||
|
||
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) | ||
}) | ||
|
Original file line number | Diff line number | Diff line change |
---|---|---|
|
@@ -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) | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more.
Can you think of a way to check for unexpected properties as well? There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Yeah, that's why I hadn't used There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Awesome 👍 |
||
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() | ||
}) | ||
}) | ||
|
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Is the timestamp like
start
,end
which is got from process.hrtime a useful time for user, since the result from process.hrtime is relative to an arbitrary time in the past, and not related to the time of day. So thestart
andend
time seem not useful and user also can't utilize themThere was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
It's useful to have
start
andend
if you want to make any duration calculations other than the built indns
,tcp
, etc. For example, you may want a duration from the start to the first byte (timings.response
-timings.start
) instead offirstByte
(connect
toresponse
).You may also just want to log or keep timestamps (relative to module startup) to be able to sort requests by start time, etc.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
@nicjansma if I want to know the
start
time of the request in Unix format, how can we achieve this?There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
That's available today as
request.startTime
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
sorry, I mean the start time of response, can we use responseStartTime, it is still available?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Yup! I didn't break any of the additional timestamps, so
responseStartTime
is still available.There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
+1 glad you thought about the deprecated behavior.
Can you add a comment near wherever
elapsedTime
andresponseStartTime
are set in the code to indicate that they are now deprecated in favor of the.timings
property? Once this has had some time to bake we can remove any README references to the old properties and think about how we deprecate them.