Timings: Tracks 'lookup', adds 'wait' time, fixes connection re-use #2566

nicjansma · 2017-02-28T04:51:26Z

PR Checklist:

I have run npm test locally and all tests are passing.
I have added/updated tests for any new behavior.
If this is a significant change, an issue has already been created where the problem / solution was discussed: Addresses some feedback from Adds .timings array with DNC, TCP, request and response times #2452

PR Description

Feedback from @mcorb in #2452 found a few items with the new .timings object.

Changes:

The net 'lookup' event is now tracked, which is the correct event to track DNS lookup time.
There is a new .timingStart property that is based on Date.now().
The .timings.* timestamps are relative to .timingStart (using now()).
The .timings object now only contains socket, lookup, connect, response and end (moving the durations to .timingPhases)
.timings.start is no longer needed, since it will always in effect be 0.
The other durations such as wait, dns, tcp, etc were moved to .timingPhases.
A new .timingPhases.wait delta is added, which tracks the time from start->socket
The .timingPhases.dns calculation is changed from start->socket to socket->lookup.
Documentation was updated to be clearer about the handling of HTTP redirects and for all of the new properties above.
For cases of connection re-use, the timings would have resulted in NaNs or negative numbers. This is resolved by assuming any events (such as lookup) that did not happen (due to re-use) are "filled in" using the timestamp of the previous phase (such as socket), resulting in a 0 ms delta.
Fixes EventEmitter leak in 2.80 #2575 by not re-adding event listeners to Keep-Alive sockets (resulting in EventEmitter leak)

Here is an example of the current properties:

{ 
  elapsedTime: 143,                 // deprecated
  responseStartTime: 1488424737161, // deprecated
  timingStart: 1488424737018,       // Unix Epoch ms
  timings: {                        // relative to timingStart
     socket: 6.410719000000002,
     lookup: 7.299280000000001,
     connect: 46.287758000000004,
     response: 105.45501300000001,
     end: 142.975414 
  },
  timingPhases: {                   // durations
     wait: 6.410719000000002,
     dns: 0.8885609999999993,
     tcp: 38.988478,
     firstByte: 59.167255000000004,
     download: 37.52040099999999,
     total: 142.975414
  } 
}

Tests have been added.

nicjansma · 2017-03-02T03:28:28Z

@Huachao and @FredKSchott would appreciate you taking a look!

Huachao · 2017-03-02T12:30:00Z

request.js

+      if (!self.timings.connect) {
+        self.timings.connect = self.timings.lookup
+      }
+      if (!self.timings.response) {


Q: in which case self.timings.response is blank, or response event is not triggered?

I'm not sure it's even possible, but I added it here for consistency and to protect against edge cases.

Huachao · 2017-03-02T12:34:09Z

README.md

-  - `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`)
+- `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 start time of the request (in Unix Epoch milliseconds via `Date`) is saved as `timingStart`. The `responseStartTime` property is also available to indicate the timestamp when the response begins. In addition, there is a `timings` object available with timestamps in millisecond resolution relative to `timingStart`. If there were redirects, the properties reflect the timings of the final request in the redirect chain:


I think it's important to emphasize the elapsedTime and responseStartTime is deprecated in README

Good idea, I've reorganized the description here a bit to be a list of all properties added.

Huachao · 2017-03-02T12:41:37Z

tests/test-timing.js

-    t.equal((res.timings.start > 0), true)
-    t.equal((res.timings.socket >= res.timings.start), true)
+    t.equal((res.timings.socket >= 0), true)
+    t.equal((res.timings.lookup >= res.timings.socket), true)
    t.equal((res.timings.connect >= res.timings.socket), true)


res.timing.lookup

Great catch.

FredKSchott · 2017-03-02T18:11:09Z

Thanks for the work @nicjansma, I'll be mostly offline until Monday but would love to take a look at this once back

Huachao · 2017-03-03T01:50:15Z

README.md

+  - `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 [`http`](https://nodejs.org/api/http.html#http_event_connect) module's `connect` event fires. This happens when the server acknowledges the TCP connection.


the connect event is not the one in http module, it's the one in net of Socket class, the doc url should be https://nodejs.org/api/net.html#net_event_connect

Great catch, fixed

…anup on error

nicjansma · 2017-03-04T21:42:46Z

@mikeal Some fixes in here for #2575

mikeal · 2017-03-04T21:44:35Z

Once CI passes I would like to get this in because it fixes a leak introduced in the last release. Is anyone still in the middle of reviews that would object?

mikeal · 2017-03-04T23:43:04Z

Wow, there's a big falloff in code coverage.

nicjansma · 2017-03-04T23:49:51Z

-0.35% overall. It seems like it's just due to 4 lines in the new patch that aren't run (which cover error conditions):

https://codecov.io/gh/request/request/compare/667e923d8d51a0f0fb4c66c91d94a40f3d3e575a...32232d91f86f16b20d76f21363d7ae4a22a0af45/diff

If you're worried about it, I can see if I can create test cases for those scenarios in a followup PR (though tomorrow at the earliest).

mikeal · 2017-03-04T23:53:11Z

Oh i see, was reading that wrong. Merging this to fix the bug. Would love a followup with more tests :)

nicjansma · 2017-03-09T14:33:08Z

@mikeal KeepAlive test here: #2590

mikeal

+1

nicjansma mentioned this pull request Feb 28, 2017

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

Merged

Huachao suggested changes Mar 2, 2017

View reviewed changes

Timings: Tracks 'lookup', adds 'wait' time, fixes connection re-use

3bc8346

Huachao approved these changes Mar 2, 2017

View reviewed changes

Huachao suggested changes Mar 3, 2017

View reviewed changes

nicjansma mentioned this pull request Mar 4, 2017

EventEmitter leak in 2.80 #2575

Closed

nicjansma added 2 commits March 4, 2017 16:40

Don’t re-add event listeners on Keep-Alive, run only .once(), and cle…

6c891da

…anup on error

Fixed documentation

32232d9

Huachao approved these changes Mar 4, 2017

View reviewed changes

mikeal merged commit 2e70b74 into request:master Mar 4, 2017

nicjansma mentioned this pull request Mar 9, 2017

Adds test-timing keepAlive test #2590

Merged

3 tasks

mikeal reviewed Mar 10, 2017

View reviewed changes

nicjansma mentioned this pull request Mar 26, 2017

Inconsistency in 'time' documentation #2587

Closed

This was referenced Mar 16, 2021

Bump request from 2.34.0 to 2.88.2 helenkulka/spotify-taste-tester#38

Open

Bump request from 2.49.0 to 2.88.2 baconjs/baconjs.github.io#51

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Timings: Tracks 'lookup', adds 'wait' time, fixes connection re-use #2566

Timings: Tracks 'lookup', adds 'wait' time, fixes connection re-use #2566

nicjansma commented Feb 28, 2017 •

edited

nicjansma commented Mar 2, 2017

Huachao Mar 2, 2017

nicjansma Mar 2, 2017

Huachao Mar 2, 2017

nicjansma Mar 2, 2017

Huachao Mar 2, 2017

nicjansma Mar 2, 2017

FredKSchott commented Mar 2, 2017

Huachao Mar 3, 2017

nicjansma Mar 4, 2017

nicjansma commented Mar 4, 2017

mikeal commented Mar 4, 2017

mikeal commented Mar 4, 2017

nicjansma commented Mar 4, 2017

mikeal commented Mar 4, 2017

nicjansma commented Mar 9, 2017

mikeal left a comment

Timings: Tracks 'lookup', adds 'wait' time, fixes connection re-use #2566

Timings: Tracks 'lookup', adds 'wait' time, fixes connection re-use #2566

Conversation

nicjansma commented Feb 28, 2017 • edited

PR Checklist:

PR Description

nicjansma commented Mar 2, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

FredKSchott commented Mar 2, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

nicjansma commented Mar 4, 2017

mikeal commented Mar 4, 2017

mikeal commented Mar 4, 2017

nicjansma commented Mar 4, 2017

mikeal commented Mar 4, 2017

nicjansma commented Mar 9, 2017

mikeal left a comment

Choose a reason for hiding this comment

nicjansma commented Feb 28, 2017 •

edited