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
Conversation
First of all, this is great. The only problem I see is the additional dependency. We've actually been combing through our deps and removing deps that are this small in order to improve the load time of request which is currently bogged down in loading a lot of relatively small deps that could be inlined. |
README.md
Outdated
- `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`) |
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.
change to Duration of HTTP
?
README.md
Outdated
@@ -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: |
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.
remove extra space before In addition
README.md
Outdated
- `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`) |
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.
also add firstByte description?
tests/test-timing.js
Outdated
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) |
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.
or >= ?
@@ -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') |
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.
do we must use the high resolution watch?
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.
I was looking at cURL results for quite a few API endpoints and I see it takes a few ms
(10 - 50ms) on an average for most events. Although, a high-resolution watch would be nicer; as @mikeal suggested - we can possibly skip in interest of keeping the dependencies low.
@nicjansma any updates, I think this feature is very important and necessary for request package |
+1 for this feature |
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.
Overall, I suggest not using performance-now
and moving to using Date.now()
as the next best lightweight option.
@nicjansma Thanks for the PR and the implementation. Looking forward to the changes and it being merged in any of the upcoming releases.
@@ -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') |
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.
I was looking at cURL results for quite a few API endpoints and I see it takes a few ms
(10 - 50ms) on an average for most events. Although, a high-resolution watch would be nicer; as @mikeal suggested - we can possibly skip in interest of keeping the dependencies low.
@@ -749,6 +754,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 comment
The reason will be displayed to describe this comment to others. Learn more.
Would recommend move to Date.now()
instead of 'new Date().getTime()` as the former is twice as fast. Performance test: https://jsperf.com/date-now-vs-new-date
Awesome, I'll work on all suggested changes shortly. |
Current coverage is 92.55% (diff: 96.42%)@@ master #2452 diff @@
==========================================
Files 12 12
Lines 1491 1517 +26
Methods 154 157 +3
Messages 0 0
Branches 452 457 +5
==========================================
+ Hits 1379 1404 +25
- Misses 112 113 +1
Partials 0 0
|
Thanks everyone for their feedback, I've pushed a new change. I've removed the Note that I'm still using
Using I've also fixed the documentation and other minor things. Hope this helps! |
README.md
Outdated
- `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 comment
The reason will be displayed to describe this comment to others. Learn more.
remove extra space before 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.
Fixed -- there were 15 other occurrences of double-spaces, so if you're going for consistency I've fixed those as well.
@@ -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 |
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 the start
and end
time seem not useful and user also can't utilize them
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.
It's useful to have start
and end
if you want to make any duration calculations other than the built in dns
, tcp
, etc. For example, you may want a duration from the start to the first byte (timings.response
- timings.start
) instead of firstByte
(connect
to response
).
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
and responseStartTime
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.
README.md
Outdated
- `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. |
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 there an extra space before connect
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.
Good catch, fixed
Any more concerns here? |
@nicjansma I think the code is quite well, and @mikeal do you have any suggestions, I expect to see this feature very much 😃 |
@simov Any concerns with this PR? |
@FredKSchott please help to review this, thanks in advance. |
I've only been going through the small, low-hanging PRs. But I appreciate the time and effort you and @nicjansma have given to writing this and continuing to ping/bump it. I'll try to give it a look tonight/tomorrow. |
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, a few comments but I'm excited to help merge this in
@@ -287,13 +287,13 @@ The method form takes parameters | |||
`auth(username, password, sendImmediately, bearer)`. | |||
|
|||
`sendImmediately` defaults to `true`, which causes a basic or bearer | |||
authentication header to be sent. If `sendImmediately` is `false`, then |
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.
In the future, address these unrelated changes in a separate PR. It makes the review smaller/easier.
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.
No problem -- it was requested that my new documentation remove double-spaces for consistency, so I wanted to fix other occurrences.
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.
Thanks for the context, hard to get caught up when Github minimizes everything that was previously said.
@@ -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 |
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
and responseStartTime
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.
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 comment
The reason will be displayed to describe this comment to others. Learn more.
Do a Just realized this will mean we can't compare the properties equally because we don't know their exact values. Hmm...t.deepEqual(res.timings, ...)
here instead, so that we check that only the properties we expect are present.
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 comment
The reason will be displayed to describe this comment to others. Learn more.
Yeah, that's why I hadn't used .deepEqual
initially. I've added a check to get all property names and compare.
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.
Awesome 👍
re: Not sure if @mikeal would still disagree, and I know that you already removed it. But if you still think it's the right call I'd say add it back (in a separate commit that can be easily reverted) and I'll give everyone a chance to weigh in before making the final call to merge. |
@FredKSchott Deprecation notes added in d9e8c3d and tests updated in a9ad38a. I'd certainly prefer to use Thanks for the feedback! Let me know if there's anything else. |
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.
Looks great to me, thanks again for taking the time to add this.
I'll merge in 48 hours unless anyone else has any comments/feedback.
LGTM, merging now |
Thanks! |
@nicjansma This is great. I have a quality-of-impementation issue after trying to consume the new request timing API yesterday. Please consider: We found it challenging to separate timeline entries (start, socket, connect, response, end) from time duration entries (dns, tcp, firstByte, download, total). Because deltas and times are currently mixed together in the 'timings' object, users of the request library have to separate them manually before use. This means each user currently has to hard-code the key names into their code in order to present the data to the user, chart it or do whatever they want. A cleaner way to implement this API would be to only provide the absolute values (start, socket, connect, response, end) in your 'timeline' object. You could then provide a convenience accessor containing 'timings' or deltas (dns, tcp, firstByte, download, total) computed from the absolute times in 'timeline'. That way users will be able to just pass response.timeline or response.timings into their database, charting library, UI or whatever without processing, based on the one they need. And it future-proofs your interface so you can add new measurements (e.g. 'ssl') to request in future without breaking apps. |
Another QoI issue we had is that the timestamps leak the process start time. This is just an implementing detail of performance-now that shouldn't be leaked into the request API. It'll be best to present either zero-based or session-based timings that can be piped straight into a metrics tool or processed more easily by developers. I'm going to prepare two PRs to address both points today or tomorrow - @FredKSchott if you can hold any release until we've had a chance to look at this that'd be great. |
We found a lot of issues and decided to hook the core http agent module for our need. This means I won't have the time to submit changesets but I'll try to help if you have any questions. Some notes from a run against our in-hous http timing test suite:
To get this right I recommend running against an HTTP timing test suite. |
Hi Mike! Lots of great feedback. Let me try to unpack some of it.
|
Neat Nic, that was quick. I haven't had a chance to look at your patch but here are some quick replies to your points: Start of Navigation is meaningful for a browser page load because all the timed loads are initiated by the navigation and immediately follow it. In contrast, node's process start time isn't related to the use of the request() API. Node processes run for weeks or months and outbound http queries are triggered by timers, user interaction or all kinds of other actions any time. It's best not to bake that assumption into request() I see two ways to go:
All http libraries I know do one of the above, with my mild preference being (2). These are both universal and well-known formats, while process-relative time isn't. Process-relative time is mostly used for performance instrumentation of a single process (compiler debugging, code optimisation) so it doesn't feel right here. Maybe that's the intended audience for Overall As for the flaw in |
By the way Nic, I totally respect your point of view and your work in this space. Some of this boils down to differences in developer expectations coming from client-side timing vs server-side/node conventions. As long as the deltas are stored separately to absolute timings the API is future-proof and can be worked on incrementally. (For completeness, there are other options too - like emitting an event or calling a user-supplied callback for each phase change so that they can decide how they measure, and also allowing for a real-time GUI like the Chrome network inspector instead of waiting till the end of the request. You might want to move your collections into a private Did you test that your patch supplies timings for failed requests? DNS and connection timings are equally, if not more important for failures too. I didn't check if your revision addresses this - it was in my notes from my previous review that I forgot to mention. Sorry to come at you with all this review. I'm not a direct consumer of this API any more so please pick what you find helpful and go with your best judgement. |
Again great feedback Mike, appreciate your thoughts. Unfortunately there are several reasons to avoid But if we only use I like your idea for (2). I've made some changes in the other PR #2566 for how the data is presented based on your recommendations:
I guess I still don't understand your concern about For the DNS and TCP failure cases you mention, no If you have any further feedback, want to move it to #2566? Thanks! |
This improves upon #1459 by adding a timings breakdown for the following phases:
First, instead of relying on
new Date().getTime()
we can useprocess.hrtime()
to get a higher-resolution monotonically non-decreasing timestamp. This is utilized via theperformance-now
package.The previous PR tracked
startTime
(not exposed) andelapsedTime
(exposed on the request). This PR adds a new.timings
object that adds new timestamps and elapsed times.Note the "timestamps" in this object are not Unix-epoch based like
new Date.getTime()
-- they aremilliseconds.microsecond
resolution relative to when theperformance-now
module got loaded.If there is a redirect when fetching the resource, the timestamps are only for the final resource fetched.
Timestamps:
start
: Timestamp whenrequest()
was initializedsocket
Timestamp when thehttp
module'ssocket
event fires. This happens when the socket is assigned to the request (after DNS has been resolved).connect
: Timestamp when thehttp
module'sconnect
event fires. This happens when the server acknowledges the TCP connection.response
: Timestamp when thehttp
module'sresponse
event fires. This happens when the first bytes are received from the server.end
: Timestamp when the last bytes of the response are received.Durations:
dns
: Duration of DNS lookup (timings.socket
-timings.start
)tcp
: Duration of TCP connection (timings.connect
-timings.socket
)firstByte
: Duration of HTTP server first byte (timings.response
-timings.connect
)download
: Duration HTTP fetch (timings.end
-timings.response
)total
: Duration entire HTTP round-trip (timings.end
-timings.start
)Example: