Skip to content
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

Merged
merged 7 commits into from Feb 21, 2017
Merged

Adds .timings array with DNC, TCP, request and response times #2452

merged 7 commits into from Feb 21, 2017

Conversation

nicjansma
Copy link
Contributor

@nicjansma nicjansma commented Nov 6, 2016

This improves upon #1459 by adding a timings breakdown for the following phases:

  • DNS
  • TCP
  • Request
  • Download

First, instead of relying on new Date().getTime() we can use process.hrtime() to get a higher-resolution monotonically non-decreasing timestamp. This is utilized via the performance-now package.

The previous PR tracked startTime (not exposed) and elapsedTime (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 are milliseconds.microsecond resolution relative to when the performance-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 when request() was initialized
  • socket Timestamp when the http 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 module's connect event fires. This happens when the server acknowledges the TCP connection.
  • response: Timestamp when the http 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.

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:

var req = request({ url: "http://foo.com", time: true }, function(err, response, body) {
  console.log("elapsedTime", response.elapsedTime);
  console.log(response.timings);
});

/*
elapsedTime 271
{ start: 8.496343,
  socket: 11.571675,
  connect: 61.353872,
  response: 102.523232,
  end: 279.228004,
  dns: 3.0753320000000013,
  tcp: 49.782197000000004,
  firstByte: 41.16935999999999,
  download: 176.704772,
  total: 270.731661 }
*/

@mikeal
Copy link
Member

mikeal commented Nov 8, 2016

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`)
Copy link
Contributor

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:
Copy link
Contributor

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`)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

also add firstByte description?

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)
Copy link
Contributor

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')
Copy link
Contributor

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?

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.

@Huachao
Copy link
Contributor

Huachao commented Nov 21, 2016

@nicjansma any updates, I think this feature is very important and necessary for request package

@whiteboardmonk
Copy link

+1 for this feature

Copy link

@whiteboardmonk whiteboardmonk left a 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')

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()

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

@nicjansma
Copy link
Contributor Author

Awesome, I'll work on all suggested changes shortly.

@codecov-io
Copy link

codecov-io commented Dec 4, 2016

Current coverage is 92.55% (diff: 96.42%)

Merging #2452 into master will increase coverage by 0.06%

@@             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          

Powered by Codecov. Last update b628cab...c7c9431

@nicjansma
Copy link
Contributor Author

nicjansma commented Dec 4, 2016

Thanks everyone for their feedback, I've pushed a new change.

I've removed the performance-now package (which was just a lightweight wrapper over window.performance.now() in the browser and process.hrtime() in Node).

Note that I'm still using process.hrtime() / performance.now() under the hood (and added two small functions to facilitate this) instead of Date.now(). Date.now() really shouldn't be used for anything that involves measuring timestamp deltas, as it is not monotonically non-decreasing. In other words, if your system clock changes, Date.now() reflects that, and you could see negative deltas between two consecutive timestamps.

process.hrtime() and window.performance.now() were built to address this by guaranteeing that they're not sync'd to the system clock, so will give you the "actual" relative time regardless of how the system clock changes. They also have the small benefit of giving you higher resolution (microseconds instead of milliseconds, though we're not exposing microsecond times).

Using process.hrtime() or performance.now() is relatively simple so if we don't want to include the performance-now package we just need one state variable and two functions to do the same thing.

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).
Copy link
Contributor

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

Copy link
Contributor Author

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
Copy link
Contributor

@Huachao Huachao Dec 5, 2016

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

Copy link
Contributor Author

@nicjansma nicjansma Dec 6, 2016

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.

Copy link
Contributor

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?

Copy link
Contributor Author

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

Copy link
Contributor

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?

Copy link
Contributor Author

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.

Copy link
Contributor

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.
Copy link
Contributor

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

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good catch, fixed

@nicjansma
Copy link
Contributor Author

Any more concerns here?

@Huachao
Copy link
Contributor

Huachao commented Dec 15, 2016

@nicjansma I think the code is quite well, and @mikeal do you have any suggestions, I expect to see this feature very much 😃

@Huachao
Copy link
Contributor

Huachao commented Jan 15, 2017

@mikeal @simov , any concerns about the PR, when will this be merged, it's a long waiting feature

@nicjansma
Copy link
Contributor Author

@mikeal @simov Would love to see this merged in :)

@nicjansma
Copy link
Contributor Author

@simov Any concerns with this PR?

@Huachao
Copy link
Contributor

Huachao commented Feb 14, 2017

@FredKSchott please help to review this, thanks in advance.

@FredKSchott
Copy link
Contributor

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.

Copy link
Contributor

@FredKSchott FredKSchott left a 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
Copy link
Contributor

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.

Copy link
Contributor Author

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.

Copy link
Contributor

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
Copy link
Contributor

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)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do a t.deepEqual(res.timings, ...) here instead, so that we check that only the properties we expect are present. Just realized this will mean we can't compare the properties equally because we don't know their exact values. Hmm...

Can you think of a way to check for unexpected properties as well?

Copy link
Contributor Author

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.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Awesome 👍

@FredKSchott
Copy link
Contributor

re: performance-now: I checked the library and it seems well tested, well supported, and has zero dependencies. I know that we're trying to remove dependencies and not add them, but by using performance-now we get to remove our custom implementation that is less tested, has never been used in production, and that leaves us responsible for all bugs. To me that sounds like a no brainer, as long as it continues to have a small footprint.

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.

@nicjansma
Copy link
Contributor Author

@FredKSchott Deprecation notes added in d9e8c3d and tests updated in a9ad38a.

I'd certainly prefer to use performance-now for all of the reasons you suggested. I've re-added it in 3f57975, if everyone agrees.

Thanks for the feedback! Let me know if there's anything else.

Copy link
Contributor

@FredKSchott FredKSchott left a 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.

@FredKSchott
Copy link
Contributor

LGTM, merging now

@FredKSchott FredKSchott merged commit 60f6a00 into request:master Feb 21, 2017
@nicjansma
Copy link
Contributor Author

Thanks!

@mcorb
Copy link

mcorb commented Feb 25, 2017

@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.

@mcorb
Copy link

mcorb commented Feb 25, 2017

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.

@mcorb
Copy link

mcorb commented Feb 25, 2017

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:

  1. We found performance-now to be broken. They introduce two rounding errors by going through nanoseconds and back, and also by not using the documented base time feature correctly. You might want to investigate using process.hrtime() directly.
  2. You're not timing DNS correctly. Need to hook the socket 'lookup' event.
  3. The results are incorrect for common use modes like HTTP keep-alive, connection reuse and connection pools.
  4. More clarity needed on http redirect handling.

To get this right I recommend running against an HTTP timing test suite.

@nicjansma
Copy link
Contributor Author

Hi Mike!

Lots of great feedback. Let me try to unpack some of it.

  • RE: separating the timestamps (start, socket, connect, response, end) from the deltas (dns, tcp, firstByte, download, total). I don't have strong feelings about this, but I can see how it would be helpful to have them separated. I might suggest keeping .timing for the timestamps and .timingDeltas for the deltas.

    Does anyone else have a preference here?

  • RE: timestamps leak the process start time. I'm not sure I fully follow your concern. It's true that all of the timestamps such as .start, .socket, etc are using the process' start time as the epoch (0-base). This allows you to, for example, lay out all of the requests within your app in a timeline of requests, and each .timings timestamp can be directly placed on that timeline.

    Are you suggesting, instead, that .start process start epoch, while the other timestamps are using "time-since-.start" as epoch? If so, I think that would be more confusing to have timestamps with different epochs.

    FWIW, ResourceTiming keeps everything in a DOMHighResTimeStamp, whose epoch is the start of the navigation. .startTime, .domainLookupStart, etc are all using the same 0-base of navigation start (i.e. process start).

    Anyone that needs timestamps in a different epoch (e.g. .socket is the time since .start), could easily do the math, right?

  • RE: 1. performance-now concerns. I'm not seeing the rounding error, can you share details? (My personal feeling is that most people won't look much beyond milliseconds at best -- I personally wouldn't be concerned about nanoseconds being rounded).

    As far as using the process.hrtime() third parameter to automatically calculate the delta, I couldn't see how using it would give additional accuracy benefits vs. doing the same math?

    Anyways, I would suggest opening these Issues against performance-now if you think it could be improved.

  • RE: 2. DNS. Thanks for finding that! I hadn't found the lookup event. Fixes in: Timings: Tracks 'lookup', adds 'wait' time, fixes connection re-use #2566

  • RE: 3. Incorrect results for HTTP keep-alive, connection re-use and connection pools.

    Great catch. I've tested a bit more with forever (for Keep Alive), agent (connection reuse) and pool (connection pool), and I believe have fixed the timestamps and deltas. Fixes in Timings: Tracks 'lookup', adds 'wait' time, fixes connection re-use #2566

  • RE: 4. HTTP redirect handling. The timings will report the data for the final hop in a redirect chain. I've improved the documentation to address this: Timings: Tracks 'lookup', adds 'wait' time, fixes connection re-use #2566

    If someone wants extra credit, they could expose a log of the timings for all redirects. :)

@mcorb
Copy link

mcorb commented Mar 1, 2017

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:

  1. Just keep it dead simple and provide all absolute times as Date.now()
  2. Include a start date in the parent object with Date.now() and make all the sub-timings relative to that.

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 performance-now?

Overall Date.now() is perfectly fine for this use case. You're measuring events based on the node event loop which already have a lower resolution, so process.hrtime() and process-now are just measuring noise using an API that was designed to measure CPU performance in nanoseconds in a single tick.

As for the flaw in performance-now: the code is currently converting process.hrtime() to JS before doing its calculation so the nanoseconds are truncated, defeating the point of using high-resolution timers. I'll send them a patch but honestly Date.now() seems more appropriate for this use case.

@mcorb
Copy link

mcorb commented Mar 2, 2017

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 markTime() function for clarity.)

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.

@nicjansma
Copy link
Contributor Author

Again great feedback Mike, appreciate your thoughts.

Unfortunately there are several reasons to avoid Date.now() if possible when doing performance measurements (please see my previous comment for details).

But if we only use Date.now() once per request -- to log the start "epoch" wall time -- and use process.hrtime() for all other timestamps, we gain the advantage of a higher-resolution, monotonically non-decreasing clock to measure all of the phases.

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:

  1. There is a new timingStart property that is based on Date.now()
  2. The timings timestamps are relative to timingStart, using process.hrtime(). This object now only contains socket, lookup, connect, response and end (moving the durations out). start is no longer needed, since it will always in effect be 0.
  3. The other durations were moved to timingPhases.

I guess I still don't understand your concern about performance-now -- looking forward to your patch :) (Remeber that Date.now() is limited to millisecond resolution, so truncating nanoseconds is still better accuracy than Date.now()).

For the DNS and TCP failure cases you mention, no response object is created, so there's (currently) no way to get timings out of failures.

If you have any further feedback, want to move it to #2566?

Thanks!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

7 participants