core: refactor NetworkRequest time properties #14311

connorjclark · 2022-08-22T19:20:40Z

Broken up into multiple PRs:

Implementing refactor as described here: #14227 (comment)

new time properties / renames

Renamed:

startTime            -> networkRequestTime
endTime              -> networkEndTime
responseReceivedTime -> responseHeadersEndTime

Added:

rendererStartTime
rendererEndTime

rendererEndTime is not actually something we have yet (only exists in trace), so at the moment it's always equal to networkEndTime. It is included to fill out our model of the network, and in some places the former is used instead of the latter even though it doesn't make a difference yet. At the very least, it better documents intent.

excerpt from network request constructor:

/** When the renderer process initially discovers a network request, in milliseconds. */
this.rendererStartTime = -1;
/**
 * When the network service is about to handle a request, ie. just before going to the
 * HTTP cache or going to the network for DNS/connection setup, in milliseconds.
 */
this.networkRequestTime = -1;
/** When the last byte of the response headers is received, in milliseconds. */
this.responseHeadersEndTime = -1;
/** When the last byte of the response body is received, in milliseconds. */
this.networkEndTime = -1;
/**
 * Network response is done, this marks the time when the main thread is first available
 * to actually utilize the network resource, in milliseconds.
 *
 * TODO: we don't have this on the CDP, but it exists in trace as ResourceFinish.ts
 * So currently this is equivalent to networkEndTime.
 */
this.rendererEndTime = -1;

Tons of subtle changes to determine which time property should be used, thanks to @paulirish for going through all of them one-by-one with me.

I had to do an annoying refactor of critical request chain, in an attempt to avoid making a breaking change to its audit values. It's a weird gatherer that saves the network request on it, then walks it in the audit...but needs to walk both the "gatherer chain" and the "audit detail chain"... which now has drifted in shape. The simple fix was to copy the chain traversal code and treat the two separately.

s -> ms

This PR also changes our network record time values to be in ms instead of seconds. This should not impact any audit values - network-requests was already converted to ms.

However critical-request-chain timings and startTime/endTime in lantern nodes remain as seconds. They'll be adjusted in a followup.

(Same deal in #14567)

…ing-overhaul

connorjclark · 2022-08-22T19:24:11Z

core/test/audits/critical-request-chains-test.js

-    const artifacts = mockArtifacts(PASSING_CHAIN_RECORDS_2);
+    const artifacts = mockArtifacts(PASSING_CHAIN_RECORDS_2, {
+      // Precision issues from converting between ms and s create slight differences during roundtrip.
+      skipVerification: true,


This was unfortunate.

we should probably put an epsilon on those comparisons, but for a quick fix, could also just pick a different timestamp :)

+1 to changing the timestamp. We don't want to skip verification if possible, especially on an already neglected audit.

brendankenny

I'll wait for any changes the tests need to settle before digging in too closely, but overall looks great and I love the additional precision we'll have to describe network requests.

Can we pick a different name than internalNetworkRequestTime? It's a key timestamp for request timing, so it's weird to put internal on the front of that. Makes it seem like you shouldn't be looking at it.
Relatedly: for the network-requests hidden audit, that time is really important for post-analysis. e.g. a low-priority image could have a very quick mainThreadStartTime but a much later internalNetworkRequestTime due to being queued after a bunch of other requests. I guess we just need to include both in the output?

Also, doesn't it seem suspicious that yarn test-lantern is all 0% changes? If the network timings have all changed I would expect at least some movement.

connorjclark · 2022-08-22T20:59:30Z

Tests should be good now.

Also, doesn't it seem suspicious that yarn test-lantern is all 0% changes? If the network timings have all changed I would expect at least some movement.

I forgot to mention - this PR should have zero impact on lantern. I figured it'd be good to split that out entirely.

The behavior remains exactly the same because network-node just uses internalNetworkRequestTime, which is the same as the previous startTime. There possibly might have been a change due to precision differences (like seen in that one test...) but I guess we don't deal with any input that would trigger that.

brendankenny

Really excited about the improved precision these extra timestamps bring. I disagree with my earlier comment that we should try to preserve the network-requests hidden audit properties; I think the new properties and names make it so much clearer it outweighs any breakages for the few of us looking at the audit.

In retrospect it would have been easier to review if we'd broken this up into

rename startTime/endTime and add mainThreadStartTime/mainThreadEndTime with no other changes

and then some order of:

switch to milliseconds in network-request
switch audits to using mainThreadStart/End where appropriate
CRC changes (though those are mostly self contained)

it's hard to track all of those simultaneously and feel confident we're getting it right in every file, and our network-timing-related test coverage isn't always the best since we also need to avoid smoke flakes, but hopefully the power of combined reviewership will win out here.

core/audits/network-requests.js

core/audits/redirects.js

core/lib/dependency-graph/network-node.js

brendankenny · 2022-10-26T17:42:26Z

core/test/network-records-to-devtools-log.js

+      timestamp:
+        networkRecord.redirectResponseTimestamp || networkRecord.mainThreadStartTime / 1000 || 0,


the different timestamps seem like they should default to each other if one is set, otherwise you can get subtly broken things like networkRequestTime of 0, before a set mainThreadStartTime

Sorry, I'm not following this / sure how to address this. Where would the values be set in this function?

basically if either rendererStartTime or networkRequestTime is set (but not both), the one not set should probably default to value of the other, not 0.

brendankenny · 2022-10-26T17:45:03Z

core/test/lib/network-recorder-test.js

@@ -218,7 +218,7 @@ describe('network recorder', function() {

    const [mainDocument, loaderPrefetch, _ /* favicon */, loaderScript, implScript] = records;
    expect(mainDocument.initiatorRequest).toBe(undefined);
-    expect(loaderPrefetch.startTime < loaderScript.startTime).toBe(true);
+    expect(loaderPrefetch.mainThreadStartTime < loaderScript.mainThreadStartTime).toBe(true);


this is a different assertion than before, though. Maybe assert both since the fetch time of prefetch is important?

brendankenny · 2022-10-26T18:05:08Z

core/lib/network-request.js

+     */
+    this.networkRequestTime = -1;
+    /** ms. When the first byte of the response headers is received. */
+    this.responseHeadersReceivedTime = -1;


bikeshed: I think I prefer the old responseReceivedTime name (with clarification of how it's defined in a comment).

I can see the benefits of being clearer internally, but when using an instance externally, this property name makes me have to think a lot to parse it, and it kind of implies there are other response-received times, even though there's just the one :)

(i'd prefer headersReceivedTime to be more terse)

do you think we'd ever want to introduce more granular network timings? if so, we should be specific here

maybe we can drop "headers" if we sneak "start" into the name somewhere.

responseStartTime i like. i guess we could just call out the 'headers received' technicality in a comment as the distinction isn't really important.

responseHeadersReceivedTime does feel a bit wordy and overkill at this point.

headersReceivedTime well... less wordy but it gets me thinking about "but what about request headers??" so the thinking overhead is still there.

responseReceivedTime (the old one) i dont like cuz it can easily be interpreted as 'end of response received'

responseHeadersEndTime is another option if we want to be both specific, consistent with start/end, and precise, though it's unfortunate that usually what we want is responseBodyStartTime.

responseStartTime does seem like it would trip up a lot on the fact that the server has already responded :/

core/lib/network-request.js

brendankenny · 2022-10-26T18:23:53Z

core/lib/network-request.js

-    if (!this.responseReceivedTime || this.responseReceivedTime < 0) {
-      this.responseReceivedTime = headersReceivedTime;
+    this.networkRequestTime = timing.requestTime * 1000;
+    const headersReceivedTime = this.networkRequestTime + timing.receiveHeadersEnd;


wait, is it actually when the last header byte is received?

⚠️ ‼️ ⚠️ ‼️ ⚠️ ‼️ ⚠️ ‼️

there's no "start" equivalent on the timing object... It seems in practice it wouldn't make a difference, surely all sites flush out all the headers upfront

does the lack of receiveHeadersStart imply that blink doesn't "stream" headers? if a preload header comes on the main document...then the server blocks before doing more headers then the body....would Chrome delay that preload?

wait, is it actually when the last header byte is received?

yes

I've poked at this with the netlog, but i've never had a testcase where the response headers get split over two packets.
But.. if i remember right even the //net stack doesnt really call out headersStart as a thing.

brendankenny · 2022-10-26T18:30:02Z

core/test/lib/network-request-test.js

@@ -111,10 +111,10 @@ describe('NetworkRequest', () => {
  describe('update fetch stats for Lightrider', () => {


Add tests for the new timestamps?

The test for _updateTimingsForLightrider or something else? There aren't really any tests here for (old) startTime, endTime, etc. and I'm not sure what it'd be other than check _onX() multiplies timestamp by 1000 or whatever.

oh, doh, I guess I should just add the other fields here in getRequest()

Added - but I had to make a change to getResponseReceivedEvent to fix roundtrip record->log errors. Don't understand why creating a timings was behind a flag, but now it isn't and it fixed the roundtripping problem... seem ok?

core/audits/network-requests.js

…g-overhaul

paulirish · 2022-11-04T20:33:55Z

core/lib/network-recorder.js

@@ -248,7 +248,8 @@ class NetworkRecorder extends RequestEventEmitter {

    let candidates = recordsByURL.get(initiatorURL) || [];
    // The initiator must come before the initiated request.
-    candidates = candidates.filter(cand => cand.responseReceivedTime <= record.startTime);
+    candidates = candidates
+      .filter(cand => cand.responseHeadersEndTime <= record.networkRequestTime);


i think this could be rendererStartTime instead of networkRequestTime.
as we have to go back to renderer to make new requests.
redirect would be the only case where that wouldnt happen but 1) thats cuz we artificially separate them into reqs and 2) i don't think we'll hit this situation with redirects.

paulirish · 2022-11-04T20:48:18Z

core/test/lib/dependency-graph/simulator/simulator-test.js

-      const nodeB = new NetworkNode(request({startTime: 2, endTime: 3}));
-      const nodeC = new NetworkNode(request({startTime: 2, endTime: 5}));
-      const nodeD = new NetworkNode(request({startTime: 2, endTime: 7}));
+      const nodeA = new NetworkNode(request({networkRequestTime: 0, networkEndTime: 1}));


i noticed there's a bunch of other startTime and endTime's in this file.. and while some belong to simulator nodes.. i think many should get renamed too..

hold up how the hell are these other tests passing?!

like should simulate cached network graphs, the start/end time on nodeA/B just don't seem to matter (delete them, still passes), even the timing assert still passes 😕

it's b/c for that test the timing data comes from an estimate based on disk cache, real timing data is ignored.

other tests, start/end time given also doesn't seem to matter for different reasons

I didn't like how simulator naming got more complicated because of network timing internals, so I kept the start/end time naming in these test files and just modified the request() helper function to translate back to the network timings domain

We can return to this in #14500 if needed

paulirish · 2022-11-04T21:51:16Z

I was thinking about the rename aspect of this PR separate from the behavior changes.. So I went through the changes and applied just the renames....

That diff: https://github.com/GoogleChrome/lighthouse/compare/renamenetwork

And then diffing this PR here against my rename-only branch: https://github.com/GoogleChrome/lighthouse/compare/renamenetwork..network-request-timing-overhaul

Maybe this diff is informative... I gotta run but i was also thinking.. maybe it'd be good for this branch to call things ambiguousStartTime so that it doesn't start to decide who uses what.

…g-overhaul

connorjclark added 13 commits July 20, 2022 16:19

misc: document where network timings come from

0b2e77b

update

7b912a5

update

057d1da

update

0a33be4

update

02aae47

pr

6f7bee2

update

9bf0683

Merge remote-tracking branch 'origin/master' into request-notes-cdp

0227595

typo

3077f90

this ck is fn raw!!

d83d201

wip

ab2885a

wip

39016e1

Merge remote-tracking branch 'origin/master' into network-request-tim…

237dec1

…ing-overhaul

connorjclark requested a review from a team as a code owner August 22, 2022 19:20

connorjclark requested review from adamraine and removed request for a team August 22, 2022 19:20

devtools-bot assigned adamraine Aug 22, 2022

devtools-bot added the waiting4reviewer label Aug 22, 2022

connorjclark commented Aug 22, 2022

View reviewed changes

rename

71705e4

vercel bot deployed to Preview August 22, 2022 19:25 View deployment

jsons

f80540b

vercel bot deployed to Preview August 22, 2022 19:32 View deployment

brendankenny reviewed Aug 22, 2022

View reviewed changes

connorjclark added 2 commits August 22, 2022 13:16

fix some tests

83313ed

fix all audit tests

ee62cf3

vercel bot deployed to Preview August 22, 2022 20:27 View deployment

fix computed tests

cf84651

vercel bot deployed to Preview August 22, 2022 20:56 View deployment

nits

817326e

vercel bot deployed to Preview October 18, 2022 21:48 View deployment

brendankenny reviewed Oct 26, 2022

View reviewed changes

re-renames

223eafd

vercel bot deployed to Preview October 28, 2022 14:39 View deployment

uh ok

39edc02

vercel bot deployed to Preview October 28, 2022 14:46 View deployment

keys

1f0dbfa

vercel bot deployed to Preview October 28, 2022 15:11 View deployment

brendankenny reviewed Oct 28, 2022

View reviewed changes

core/audits/network-requests.js Outdated Show resolved Hide resolved

core/audits/network-requests.js Outdated Show resolved Hide resolved

brendankenny mentioned this pull request Oct 31, 2022

core(network-request): backport rendererStartTime #14481

Merged

connorjclark added 2 commits November 4, 2022 12:34

Merge remote-tracking branch 'origin/main' into network-request-timin…

5502fb1

…g-overhaul

partial review pass

1415f79

vercel bot deployed to Preview November 4, 2022 19:47 View deployment

paulirish reviewed Nov 4, 2022

View reviewed changes

add new props to lr fetch timings test

9410216

vercel bot deployed to Preview November 4, 2022 20:54 View deployment

connorjclark mentioned this pull request Nov 4, 2022

update lantern to use new rendererStartTime timing #14500

Closed

update simulator test

798064e

vercel bot deployed to Preview November 4, 2022 21:15 View deployment

reorder

49a9555

vercel bot deployed to Preview November 4, 2022 21:45 View deployment

Merge remote-tracking branch 'origin/main' into network-request-timin…

3f8dd5c

…g-overhaul

vercel bot deployed to Preview November 28, 2022 20:16 View deployment

connorjclark mentioned this pull request Nov 28, 2022

core(network-request): use ms instead of seconds #14567

Merged

connorjclark closed this Nov 29, 2022

connorjclark mentioned this pull request Dec 1, 2022

core(network-request): add new timing properties #14574

Closed

connorjclark mentioned this pull request Feb 26, 2024

core(network-request): use rendererStartTime for initiator candidates #15832

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

core: refactor NetworkRequest time properties #14311

core: refactor NetworkRequest time properties #14311

connorjclark commented Aug 22, 2022 •

edited

Loading

connorjclark Aug 22, 2022

brendankenny Aug 22, 2022

brendankenny Oct 26, 2022

brendankenny left a comment

connorjclark commented Aug 22, 2022

brendankenny left a comment •

edited

Loading

brendankenny Oct 26, 2022

connorjclark Nov 4, 2022 •

edited

Loading

brendankenny Nov 4, 2022

brendankenny Oct 26, 2022

brendankenny Oct 26, 2022

connorjclark Oct 28, 2022

paulirish Oct 28, 2022

brendankenny Oct 28, 2022

brendankenny Oct 26, 2022

connorjclark Oct 28, 2022

paulirish Oct 28, 2022

brendankenny Oct 26, 2022

connorjclark Nov 4, 2022 •

edited

Loading

connorjclark Nov 4, 2022

connorjclark Nov 4, 2022

paulirish Nov 4, 2022

paulirish Nov 4, 2022

connorjclark Nov 4, 2022

connorjclark Nov 4, 2022 •

edited

Loading

connorjclark Nov 4, 2022 •

edited

Loading

paulirish commented Nov 4, 2022

		timestamp:
		networkRecord.redirectResponseTimestamp \|\| networkRecord.mainThreadStartTime / 1000 \|\| 0,

		@@ -111,10 +111,10 @@ describe('NetworkRequest', () => {
		describe('update fetch stats for Lightrider', () => {

core: refactor NetworkRequest time properties #14311

core: refactor NetworkRequest time properties #14311

Conversation

connorjclark commented Aug 22, 2022 • edited Loading

new time properties / renames

s -> ms

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

brendankenny left a comment

Choose a reason for hiding this comment

connorjclark commented Aug 22, 2022

brendankenny left a comment • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

connorjclark Nov 4, 2022 • edited Loading

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

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

connorjclark Nov 4, 2022 • edited Loading

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

connorjclark Nov 4, 2022 • edited Loading

Choose a reason for hiding this comment

connorjclark Nov 4, 2022 • edited Loading

Choose a reason for hiding this comment

paulirish commented Nov 4, 2022

connorjclark commented Aug 22, 2022 •

edited

Loading

brendankenny left a comment •

edited

Loading

connorjclark Nov 4, 2022 •

edited

Loading

connorjclark Nov 4, 2022 •

edited

Loading

connorjclark Nov 4, 2022 •

edited

Loading

connorjclark Nov 4, 2022 •

edited

Loading