2026228 - Opening devtools on the Console tab causes so much overhead on network transfers that I can't profile what my page is doing

Status: RESOLVED FIXED

(DevTools :: General, defect, P3)

Description

[Florian Quèze [:florian]]

I opened devtools to see console.log statements in my page that is loading slower than I would like. Just having devtools open on the Console slowed down all network loads by a lot. Here's a profile: https://share.firefox.dev/4uQrjzx showing the parent process main thread is busy in onInputStreamReady from resource://devtools/shared/network-observer/NetworkResponseListener.sys.mjs.

Comment 1

[Julian Descottes [:jdescottes]]

Thanks for filing and sharing a profile! DevTools slowing down the load is a known issue, but your test case seems extremely bad.
I also thought we had a bug on file for this but I can't find it at the moment.

Can you share the page where you experienced this?

Comment 2

[Julian Descottes [:jdescottes]]

We should check why we are starting NetworkObserver regardless of whether the Network panel is selected / enabled. If you don't have the XHR/Request filters enabled in the console, we might be able to disable Network observers, but we know users in general want network monitoring to start as soon as possible.

Potential improvements to look at:

• postponing the decoding of the stream (same as BiDi)
• only request the buffer when needed (either at the end or on demand)

Comment 3

[Julian Descottes [:jdescottes]]

Florian: can you share your test case?

Comment 4

[Florian Quèze [:florian]]

https://share.firefox.dev/3OgswQ5 is a profile captured today on a current mozilla-central opt local build, or loading https://tests.firefox.dev/try.html?rev=0e27a8d9e7f82c9ea3688e0f24eb3d41155eb056 with the devtools console open. Neither "XHR" nor "Requests" is selected.

Comment 5

[Julian Descottes [:jdescottes]]

Some comparisons on the same build / clean profile:

• with bidi monitoring network events: https://share.firefox.dev/47wfvIH
• with bidi monitoring network events and capturing response data: https://share.firefox.dev/4tqm8oy
• with devtools https://share.firefox.dev/47CiaRb

With DevTools onInputStreamReady seems to take ~3000ms, while with BiDi it's below 300ms.

Even if we have some differences in the way we consume the input stream, a 10x difference is surprising.

Comment 6

[Julian Descottes [:jdescottes]]

Oh well, if I disable decoding the response body on the fly in devtools, the figures are much closer to BiDi: https://share.firefox.dev/4tcPtSY

I had a patch somewhere to do that for devtools but it didn't seem to have any performance impact so I didn't move forward with it. In theory there's no reason to decode everything immediately.

Comment 7

[Julian Descottes [:jdescottes]]

The patch I had 8 months ago: https://hg-edge.mozilla.org/try/rev/767ab091d930eb27977f0d983550b29bdc2a4f0b but the commit summary says "BROKEN" so I'm going to assume this wasn't fully working and I just wanted to check the impact on DAMP.

Comment 8

[Julian Descottes [:jdescottes]]

Attachment: Bug 2026228 - [devtools] Only decode response content when requested by the client

Comment 9

[Julian Descottes [:jdescottes]]

The reason why this has such an impact on Florian's website is that it loads around 150 json files, each being between 10 and 100MB after decoding. This means several GB of data after decoding/decompression. Although we normally cap at 1MB per response, I'm wondering if playing with the devtools.netmonitor.responseBodyLimit helps here (and if increasing the limit makes the issue even worse?).

Also worth noting that devtools currently grows the parent process memory to 4GB with this scenario.

This is an extreme scenario, but the netmonitor should still behave correctly. Disabling on the fly decoding fixes most of the issue, but has some hard to mitigate side effects:

• the displayed size becomes the compressed/encoded size, whereas it used to be the decoded decompressed size. It also becomes slightly redundant with the transferred size which was already the compressed/encoded size + header size.
• the truncation is now chunk based: if a chunk exceeds the allocated size it gets discarded.

Comment 10

[Julian Descottes [:jdescottes]]

I'm also hitting an issue specifically with brotli encoded responses. They seem to require a http channel to be processed now, in case we are doing dictionary compressed brotli. But this is not supported at the moment by devtools, maybe we can lift the requirement.

Comment 11

[Julian Descottes [:jdescottes]]

Attachment: Bug 2026228 - [necko] Stop throwing when decoding regular brotli without a channel

Comment 12

[Julian Descottes [:jdescottes]]

I implemented something around reading the decoded body size from the content process but there are a few issues with this:

• the values still differ from the current one we have, most likely because it doesn't include the headers size
• some requests fail to be matched with the target actor in content processes (eg font requests)
• some requests have a 0B decoded body size despite having a real size with the current approach (again font requests)

Comment 13

[Julian Descottes [:jdescottes]]

some requests have a 0B decoded body size despite having a real size with the current approach (again font requests)

Found the root cause for that. Only compressed requests have a decodedBodySize, others should fallback to encodedBodySize.

Comment 14

[Julian Descottes [:jdescottes]]

I tried to fix a few things, but 1/ this adds (a lot) of complexity to the implementation and 2/ in some cases necko's decodedBodySize in content still has unexpected values compared to DevTools' current implementation.

For instance in devtools/client/netmonitor/test/filters/browser_net_filter-flags.js we expect a heavily gzipped payload to have a size of 10989: https://searchfox.org/firefox-main/rev/986b2e474acca54ab469aca8d549b71cdcea33a5/devtools/client/netmonitor/test/filters/browser_net_filter-flags.js#265

setFreetextFilter("size:10989");

The content is the string Hello gzip! repeated 999 times, which takes 10989 characters in total, and that's what we measure when we decompress the data manually.
However, nsIHttpChannel.decodedBodySize for this channel is only 106 bytes, versus a 82 bytes for encoded body size.

I have no idea what this decodedBodySize corresponds to then, but it doesn't seem to map to what devtools expects at the moment.

I am starting to feel like we should go back to what we discussed earlier and rather repurpose the size column to show the encoded size, and show the decoded body size only dynamically when the user opens the response panel and we decode the content.

Valentin, do you know what could explain a decodedBodySize of 106 bytes for a 11k long gzipped string such as what I described above?

Comment 15

[Phabricator Automation]

Comment on attachment 9564087 [details]
Bug 2026228 - [necko] Stop throwing when decoding regular brotli without a channel

Revision D291959 was moved to bug 2034540. Setting attachment 9564087 [details] to obsolete.

Comment 16

[Valentin Gosu [:valentin]]

Valentin, do you know what could explain a decodedBodySize of 106 bytes for a 11k long gzipped string such as what I described above?

There are a few possibilities.

• we check decodedBodySize in the parent and we decompress it in the child
• we check decodedBodySize in the child and we decompress it in the parent
• the channel gets cancelled before we fully decompress it, or something else prevents it from being fully decompressed.
• the channel doesn't actually do the decompression, but just passes it to the consumer, and the consumer decompresses it.

If you give me the commands to reproduce this, I could take a closer look.

Comment 17

[Julian Descottes [:jdescottes]]

./mach test devtools/client/netmonitor/test/filters/browser_net_filter-flags.js

will hit it, but it's a pretty long test. The request which interests us here is sjs_content-type-test-server.sjs?fmt=gzip if you can easily filter that.
I imagine you don't need my patches to read the decodedBodySize from necko, you can do that off central?

Comment 18

[Valentin Gosu [:valentin]]

Attachment: Bug 2026228 - Make nsHTTPCompressConv::GetDecodedDataLength check listener chain r=#necko

nsHTTPCompressConv::GetDecodedDataLength was only returning the stats the first
decompression step. Instead it should also walk the converter chain.
The last decompressor is the one that has the correct decoded body size.

Comment 19

[Valentin Gosu [:valentin]]

It seems it was the double gzip encoding that was causing the mismatch.
The patch should fix it. Thanks!

Comment 20

[Julian Descottes [:jdescottes]]

Oh an actual bug then!
Thanks so much for the patch, I'll rebase on top of this and resume my work.

Comment 21

[Pulsebot]

Pushed by [e-mail]:
https://github.com/mozilla-firefox/firefox/commit/6eeeea566e37
https://hg.mozilla.org/integration/autoland/rev/a8d0facffe88
Make nsHTTPCompressConv::GetDecodedDataLength check listener chain r=necko-reviewers,kershaw,jdescottes
https://github.com/mozilla-firefox/firefox/commit/c43b38e47261
https://hg.mozilla.org/integration/autoland/rev/43bd79db9fc0
[devtools] Only decode response content when requested by the client r=bomsy,devtools-reviewers,nchevobbe

Comment 22

[Pulsebot]

Pushed by [e-mail]:
https://github.com/mozilla-firefox/firefox/commit/5d2bf4927282
https://hg.mozilla.org/integration/autoland/rev/b9ca6d1551ab
Revert "Bug 2026228 - Make nsHTTPCompressConv::GetDecodedDataLength check listener chain r=necko-reviewers,kershaw,jdescottes" for causing dt failures in browser_net_har_copy_all_as_har.js
https://github.com/mozilla-firefox/firefox/commit/070648a6ca9f
https://hg.mozilla.org/integration/autoland/rev/183e84c0eaf2
Revert "Bug 2026228 - [devtools] Only decode response content when requested by the client r=bomsy,devtools-reviewers,nchevobbe" for causing dt failures in browser_net_har_copy_all_as_har.js

Comment 23

[Cristian Tuns]

Backed out for causing dt failures

• Backout link
• Push with failures
• Failure Log
• Failure line: TEST-UNEXPECTED-FAIL | devtools/client/netmonitor/src/har/test/browser_net_har_copy_all_as_har.js | Response body must be truncated - Got +0, expected 10

Comment 24

[Julian Descottes [:jdescottes]]

Oh, I reverted all the test changes, but I didn't notice that browser_net_har_copy_all_as_har.js still was impacted. Truncation works slightly differently with the new solution.

Comment 25

[Pulsebot]

Pushed by [e-mail]:
https://github.com/mozilla-firefox/firefox/commit/538462581c2b
https://hg.mozilla.org/integration/autoland/rev/43a36d07c5e8
Make nsHTTPCompressConv::GetDecodedDataLength check listener chain r=necko-reviewers,kershaw,jdescottes
https://github.com/mozilla-firefox/firefox/commit/f1d4c8c340fe
https://hg.mozilla.org/integration/autoland/rev/2000f9117226
[devtools] Only decode response content when requested by the client r=bomsy,devtools-reviewers,nchevobbe

Comment 26

[Cosmin Sabou [:CosminS]]

https://hg.mozilla.org/mozilla-central/rev/43a36d07c5e8
https://hg.mozilla.org/mozilla-central/rev/2000f9117226