clients(lightrider): always get transferSize from X-TotalFetchedSize header #7478

connorjclark · 2019-03-12T22:24:50Z

After inspecting the devtools log locally with the NS on and off, I'm mostly convinced that Chrome is right, and LH needs to be tweaked

The pattern dataLength=x,encodedDataLength=0 + dataLength=0,encodedDataLength=y only happens for resources that load in one chunk. And x = y only when the content is not compressed. It seems that if all the data for a resource comes in one chunk, the first "dataReceived" event always has 0 for encodedLength, but the second event will have the entire encoded length. If the resource is loaded in multiple chunks, the first dataReceived event has some of the total encoded length, the next won't have much or any, and the remaining unreported encoded length is on the last event. Inspecting the logic in the code linked in #3 seems to support this.

I think the behavior before could be considered incorrect, and the "bugged" version is what should be expected. An encodedDataLength of zero doesn't really make sense, but we were depending on it :) In other words, no issue with Chrome, let's fix LH.

Fixes internal bug b/123996856. Googlers, see internal changes cl/238109521.

brendankenny · 2019-03-12T22:28:27Z

even the comment in the PR itself is a better PR description than this one :P :P

fixed it

connorjclark · 2019-03-12T22:29:03Z

Didn't want to repeat myself ;)

patrickhulce

Seems fine to me! I'm not surprised that this is now buggy. This entire workaround was done hastily in response to devtools logs that had all 0 transfer size records without being able to reproduce or explained at the time by DT folks 😆

patrickhulce · 2019-03-12T22:59:55Z

It seems that if all the data for a resource comes in one chunk, the first "dataReceived" event always has 0 for encodedLength, but the second event will have the entire encoded length. If the resource is loaded in multiple chunks, the first dataReceived event has some of the total encoded length, the next won't have much or any, and the remaining unreported encoded length is on the last event

I had thought that in WRS loaders there was no incremental loading on the Chrome side and it always appeared to showup in one big chunk over the protocol, or at least that's what early devtools logs appeared to show, so if that wasn't true, it certainly explains the troubles we see now.

connorjclark · 2019-03-12T23:05:10Z

It seems that if all the data for a resource comes in one chunk, the first "dataReceived" event always has 0 for encodedLength, but the second event will have the entire encoded length. If the resource is loaded in multiple chunks, the first dataReceived event has some of the total encoded length, the next won't have much or any, and the remaining unreported encoded length is on the last event

I had thought that in WRS loaders there was no incremental loading on the Chrome side and it always appeared to showup in one big chunk over the protocol, or at least that's what early devtools logs appeared to show, so if that wasn't true, it certainly explains the troubles we see now.

That is true. Orthogonal to how many dataReceived events are seen is - whether or not encodedDataLength is set on them. The weird pattern of dataLength=x,encodedDataLength=0 + dataLength=0,encodedDataLength=y stuck out because of the guaranteed single-chunk loading in WRS, and looked like a weird bug at first, until realizing that a request with 0 encodedDataLength doesn't make much sense.

paulirish · 2019-03-13T19:07:24Z

Copying from the internal thread...

Here's how I understand things..

"Correct" pattern (we see in desktop chrome regardless of NS) when data is received in one chunk:

Network.responseReceived: ...
Network.dataReceived: {dataLength:<allbytes>, encodedDataLength:0},
Network.dataReceived: {dataLength:0, encodedDataLength:<gzippedbytes>},

Old WRS:

Network.responseReceived {headers: {X-TotalFetchedSize: <gzippedbytes>}}
Network.dataReceived: {dataLength:<allbytes>, encodedDataLength:0}, (encoded=0 IS A LIE)

ToT WRS:

Network.responseReceived {headers: {X-TotalFetchedSize: <gzippedbytes>}}
Network.dataReceived: {dataLength:<allbytes>, encodedDataLength:0},
Network.dataReceived: {dataLength:0, encodedDataLength:<allbytes>}, (encoded=allbytes IS A LIE)

This seems correct to everyone?

if so...

Due to reasons, we can't have encodedDataLength populated correctly in WRS, so we have to accept a lie. So we have to handle the special situation here on the LH side.

ResponseReceived is received first and already has the full encodedDataLength.

Proposal: If this is Lightrider and we receive that header, then we use that as our transferSize and ignore all the encodedDataLength's.
That's roughly in line with your PR here but I'm wondering if we should set transferSize (via _updateTransferSizeForLightRiderIfNecessary) from inside of onResponseReceived() instead. wdyt?

patrickhulce · 2019-03-13T19:25:13Z

"Correct" pattern (we see in desktop chrome regardless of NS) when data is received in one chunk:

In practice I see, Network.loadingFinished being the actual source of all transfer size information the normal case. We may get those encodedDataLength events, but they always get overridden by loadingFinished. Otherwise that seems correct to me!

That's roughly in line with your PR here but I'm wondering if we should set transferSize (via _updateTransferSizeForLightRiderIfNecessary) from inside of onResponseReceived() instead. wdyt?

seems fine to me 👍

paulirish · 2019-03-13T19:37:00Z

In practice I see, Network.loadingFinished being the actual source of all transfer size information the normal case.

Ah I see. loadingFinished's value should override the sum of dataReceived's. I guess we'd use the dataReceived ones if it was loadingFailed or some other weird situation. mkay.

Okay in that case, let's continue to set LR transferSize here in loadingFinished, but let's add a shitton of comments that explain this shit so we don't have to research it so hard next time.

YES? YES.

paulirish

plz add so many more comments on the sequencing and where we expect the data

connorjclark · 2019-03-13T19:55:03Z

Here's how I understand things..
This seems correct to everyone?

Yupper

I'm wondering if we should set transferSize (via _updateTransferSizeForLightRiderIfNecessary) from inside of onResponseReceived() instead. wdyt?

_updateTransferSizeForLightRiderIfNecessary is currently called for onResponseReceived and onLoadingFinished. The order goes:

responseReceived
dataReceived
dataReceived
loadingFinished / loadingFailed

It seems we could remove the call to _updateTransferSizeForLightRiderIfNecessary in responseReceived and just have it in loadingFinished (and maybe loadingFailed too?). We could just have it in just responseReceived, but we'd also need to not accumulate the encodedDataLength as dataReceived events are processed in LR.

options as I see it;

call _updateTransferSizeForLightRiderIfNecessary in loadingFinished / loadingFailed
call _updateTransferSizeForLightRiderIfNecessary in responseReceived and never accumulate encodedDataLength on dataReceived in LR.

brendankenny · 2019-03-13T20:47:57Z

Can we keep the changes for lightrider limited to a single place? What happened to

and just have it in loadingFinished (and maybe loadingFailed too?).

Seems like the new behavior is the same as in 8406bc9 (disregard normal way of setting this.transferSize, use the header instead) if we just move the _updateTransferSizeForLightRiderIfNecessary call to finished/failed?

We should also get some tests in for this.

patrickhulce · 2019-03-13T20:57:54Z

I'd strongly prefer to just have _updateTransferSizeForLightRiderIfNecessary be called as frequently as necessary (loadingFinished/loadingFailed) then have extra logic for not accumulating on dataReceived :)

connorjclark · 2019-03-13T21:31:34Z

doneski :)

brendankenny

just to make the testing more work, can we pick a site with fewer requests? :)

Or we can trim down to just the requests we care about? It seems fine to rely on this fixture just for checking this issue

brendankenny · 2019-03-13T22:03:39Z

lighthouse-core/lib/network-request.js

@@ -246,6 +247,18 @@ module.exports = class NetworkRequest {

    this.responseReceivedTime = timestamp;

+    this.responseHeadersText = response.headersText || '';


move these lines back?

brendankenny · 2019-03-13T22:03:58Z

lighthouse-core/lib/network-request.js

+    // a value via the accumulation.
+    // In Lightrider, we do not have true value for encodedDataLength, and we get the actual size
+    // of the encoded data via a special response header. Because the values are totally bogus,
+    // we do no accumulation.


move comment down to _updateTransferSizeForLightrider?

brendankenny · 2019-03-13T22:21:12Z

Or we can trim down to just the requests we care about?

like ...

json.filter(entry => {
  return entry.method.startsWith('Network') &&
    ['B38A026891F997E88601C20D85DC4616', '1000170085.13'].includes(entry.params.requestId);
});

?

:)

brendankenny

it's a beauty

paulirish

can you also leave a comment on L70 that says go read the _updateTransferSizeForLightrider comment?

paulirish · 2019-03-13T22:30:36Z

lighthouse-core/lib/network-request.js

+
+    // The total length of the encoded data is spread out among multiple events. The sum of the
+    // values in onResponseReceived and all the onDataReceived events will equal the value
+    // seen on the onLoadingFinished event. As we process onResonseReceived and onDataReceived


The sum of the
// values in onResponseReceived and all the onDataReceived events will equal the value
// seen on the onLoadingFinished event.

I don't know exactly what leads to a situation when the loadingFinished total is different than the sum of the parts, but apparently it does happen.

I just tried against 6 saved devtoolslogs i have. (Disclaimer: the artifacts were collected months ago definitely without networkservice, though I wouldn't expect it to matter)... There's, 320 network requests in total and nearly all of them have a sum that matches (or the sum was 0).. But I found 3 requests where this wasn't the case.

encodedSum encodedTotalInLoadingFinished url

108 12640 http://localhost:10200/dobetterweb/dbw_tester.html

139 144 http://localhost:10200/dobetterweb/empty_module.js?delay=500

650 714 https://s.amazon-adsystem.com/x/da2e6c890e6e3636

Again.. don't know what leads to this situation, but it happens. I'm happy with admitting that in the comment or we can ask caseq/network people about the circumstances..

ooh that is funky. With NS off, it's good. But on it was off by 5 for "empty_module?delay=500". And there was no dataReceived event!

paulirish · 2019-03-13T22:35:42Z

lighthouse-core/lib/network-request.js

+    // we accumulate the total encodedDataLength. When we process onLoadingFinished, we override
+    // the accumulated total. We do this so that if the request is aborted or fails, we still get
+    // a value via the accumulation.
+    // In Lightrider, we do not have true value for encodedDataLength, and we get the actual size


we do no accumulation.

Looks like we do, as of now.. We just override the transferSize in loadingFinished

Thank you VERY MUCH for writing all this shit out. These comments are so Good.

here's a very small rewrite of this second para for clarity:

In Lightrider, due to instrumentation limitations, our values for encodedDataLength are bogus and not valid. However the resource's true encodedDataLength/transferSize is shared via a special response header, X-TotalFetchedSize. In this situation, we read this value from responseReceived, use it for the transferSize and ignore the encodedDataLength values in both dataReceived and loadingFinished.

oops thanks for the revisions ❤️

paulirish

two nits

thanks for digging in on this!

paulirish · 2019-03-13T23:19:54Z

lighthouse-core/lib/network-request.js

+   * 'X-TotalFetchedSize' is the canonical transfer size in LR. Nothing should supersede it.
+   *
+   * The total length of the encoded data is spread out among multiple events. The sum of the
+   * values in onResponseReceived and all the onDataReceived events will equal the value


will equal => typically equals

and add

In <1% of cases we see the values differ.

paulirish · 2019-03-13T23:20:39Z

lighthouse-core/lib/network-request.js

-  _updateTransferSizeForLightRiderIfNecessary() {
-    // Bail if we're not in LightRider, this only applies there.
-    if (!global.isLightRider) return;
+  _updateTransferSizeForLightrider() {


can you also leave a comment on L70 that says go read the _updateTransferSizeForLightrider comment?

patrickhulce

sorrrrrryy I'm late to the party

patrickhulce · 2019-03-14T01:50:03Z

lighthouse-core/lib/network-request.js

+   * The total length of the encoded data is spread out among multiple events. The sum of the
+   * values in onResponseReceived and all the onDataReceived events typically equals the value
+   * seen on the onLoadingFinished event. In <1% of cases we see the values differ. As we process
+   * onResonseReceived and onDataReceived we accumulate the total encodedDataLength. When we


typo onResponseReceived

patrickhulce · 2019-03-14T01:50:48Z

lighthouse-core/lib/network-request.js

+   *
+   * The total length of the encoded data is spread out among multiple events. The sum of the
+   * values in onResponseReceived and all the onDataReceived events typically equals the value
+   * seen on the onLoadingFinished event. In <1% of cases we see the values differ. As we process


fwiw in ~70% of cases in my local devtoolslog of a run I just did the final encodedDataLength differs from the sum of the events, not sure if I'm broken or the something else has changed :)

interesting. could you or paul share your test scripts / LH code diff / devtool logs? We should control for what logs we are using + NS + Chrome version so we know what's actually happening.

oh I just looked at the last latest-run/defaultPass.devtoolslog.json I had, so it's probably fairly old

patrickhulce · 2019-03-14T01:54:01Z

lighthouse-core/lib/network-request.js

+   * seen on the onLoadingFinished event. In <1% of cases we see the values differ. As we process
+   * onResonseReceived and onDataReceived we accumulate the total encodedDataLength. When we
+   * process onLoadingFinished, we override the accumulated total. We do this so that if the
+   * request is aborted or fails, we still get a value via the accumulation.


or fails

did we decide not to override for onLoadingFailed?

_updateTransferSizeForLightrider is being called on failed now, or did you mean something else?

oh I just missed it and comment didn't mention it so I got confused, we're all good :)

…header (#7478)

lightrider: always get transferSize from X-TotalFetchedSize header

8406bc9

connorjclark requested review from brendankenny and paulirish as code owners March 12, 2019 22:24

brendankenny changed the title ~~lightrider: always get transferSize from X-TotalFetchedSize header~~ clients(lightrider): always get transferSize from X-TotalFetchedSize header Mar 12, 2019

patrickhulce approved these changes Mar 12, 2019

View reviewed changes

brendankenny approved these changes Mar 12, 2019

View reviewed changes

paulirish requested changes Mar 13, 2019

View reviewed changes

connorjclark added 2 commits March 13, 2019 13:15

comments and more explicit handling

e8cbbe2

parse headers before using them

49c70ca

brendankenny self-requested a review March 13, 2019 20:39

connorjclark added 3 commits March 13, 2019 14:20

add test

a208c69

force add devtools log

fd7d187

revert some changes

17e6bd8

brendankenny reviewed Mar 13, 2019

View reviewed changes

connorjclark added 3 commits March 13, 2019 15:22

trim devtools log

9ff988b

move

852ed20

move

e669481

brendankenny approved these changes Mar 13, 2019

View reviewed changes

paulirish requested changes Mar 13, 2019

View reviewed changes

revise comment

779fcfa

paulirish approved these changes Mar 13, 2019

View reviewed changes

//

e50eb65

paulirish merged commit b548452 into master Mar 14, 2019

paulirish deleted the lr-transfersize branch March 14, 2019 00:26

patrickhulce reviewed Mar 14, 2019

View reviewed changes

connorjclark added a commit that referenced this pull request Mar 19, 2019

clients(lightrider): always use transferSize from X-TotalFetchedSize …

b5492d4

…header (#7478)

		@@ -246,6 +247,18 @@ module.exports = class NetworkRequest {

		this.responseReceivedTime = timestamp;

		this.responseHeadersText = response.headersText \|\| '';

encodedSum	encodedTotalInLoadingFinished	url
108	12640	http://localhost:10200/dobetterweb/dbw_tester.html
139	144	http://localhost:10200/dobetterweb/empty_module.js?delay=500
650	714	https://s.amazon-adsystem.com/x/da2e6c890e6e3636

clients(lightrider): always get transferSize from X-TotalFetchedSize header #7478

clients(lightrider): always get transferSize from X-TotalFetchedSize header #7478

Conversation

connorjclark commented Mar 12, 2019 • edited by brendankenny Loading

brendankenny commented Mar 12, 2019 • edited Loading

connorjclark commented Mar 12, 2019

patrickhulce left a comment

Choose a reason for hiding this comment

patrickhulce commented Mar 12, 2019

connorjclark commented Mar 12, 2019

paulirish commented Mar 13, 2019

"Correct" pattern (we see in desktop chrome regardless of NS) when data is received in one chunk:

Old WRS:

ToT WRS:

patrickhulce commented Mar 13, 2019

paulirish commented Mar 13, 2019

paulirish left a comment

Choose a reason for hiding this comment

connorjclark commented Mar 13, 2019

brendankenny commented Mar 13, 2019

patrickhulce commented Mar 13, 2019

connorjclark commented Mar 13, 2019

brendankenny left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

brendankenny commented Mar 13, 2019

brendankenny left a comment

Choose a reason for hiding this comment

paulirish left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

connorjclark Mar 13, 2019 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

paulirish left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

patrickhulce left a 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 commented Mar 12, 2019 •

edited by brendankenny

Loading

brendankenny commented Mar 12, 2019 •

edited

Loading

connorjclark Mar 13, 2019 •

edited

Loading