1625006 - Include information about webRequest blocking handlers in profiles

Status: RESOLVED FIXED

(WebExtensions :: Request Handling, enhancement)

Description

[Andrew Swan [:aswan]]

It is not uncommon to have questions about how blocking webRequest listeners are affecting a particular Firefox profile (two recent examples are bug 1618129 and bug 1624685). Right now, requests that are suspended for a blocking webRequest listener just show a really long time in "Waiting for socket thread" in the request timing diagram in the profiler. It would be handy to have the actual time spent waiting for an extension more clearly labeled in a profile.

Comment 1

[Andrew Swan [:aswan]]

Attachment: Bug 1625006 Add profiler markers for blocking webRequest listeners

Comment 2

[Andrew Swan [:aswan]]

Shane/Florian, the attached patch is a quick hack, any thoughts?
I started looking at adding this to the network timing diagram but that's significantly trickier -- that information is carried around in a mozilla::net::TimingStruct which is used in enough other places that I would be wary of adding more data to it. Moreover, an individual request could be suspended/resumed multiple times so to really add that information to TimingStruct would mean adding a vector or something which gets gnarly (and would be hard to do without adding unwanted overhead).
This isn't perfect but it does add some useful information and the patch is pretty simple.
Thoughts?

Comment 3

[Shane Caraveo (:mixedpuppy)]

I don't feel too useful here since I know nothing about the socket thread stuff. Would it be useful to involve someone from the netwerk team? Dragana?

Would adding the channelId[1] to the data be useful?
Any use in knowing what listener is suspending the channel?
Should there be a cumulative time?

[1] https://searchfox.org/mozilla-central/source/netwerk/base/nsIChannel.idl#377

Comment 4

[Andrew Swan [:aswan]]

(In reply to Shane Caraveo (:mixedpuppy) from comment #3)

I don't feel too useful here since I know nothing about the socket thread stuff. Would it be useful to involve someone from the netwerk team? Dragana?

Sure, added Dragana, though if we keep this confined to ChannelWrapper, we're keeping mostly independent from necko. But perhaps some thoughts on comment 2?

Would adding the channelId[1] to the data be useful?
Any use in knowing what listener is suspending the channel?

Yes, I think those would be valuable as well. With the current patch, it would be a bigger change I think, we'd need to change from just using a setter on the suspended property to adding suspend()/resume() functions to which we could pass additional information.

Should there be a cumulative time?

There already is: every profiler marker has a start and end time and this patch sets those based on when the suspend and resume happen. When viewing a profile, the marker chart shows markers where the time difference is small as dots but longer intervals show up as longer bars.

Comment 5

[Shane Caraveo (:mixedpuppy)]

As well, perhaps this might be better to go into nsHttpChannel itself (or maybe the existing timing will be useful). There is some timing code in there[1], I haven't dug into seeing how its used (see bug 576006). We'd want timing from just before onModified[2] to just after onBeforeConnect, probably in Connect()[3] itself.

[1] https://searchfox.org/mozilla-central/rev/4d9cd186767978a99dafe77eb536a9525980e118/netwerk/protocol/http/nsHttpChannel.cpp#6809
[2] https://searchfox.org/mozilla-central/rev/4d9cd186767978a99dafe77eb536a9525980e118/netwerk/protocol/http/nsHttpChannel.cpp#496
[3] https://searchfox.org/mozilla-central/rev/4d9cd186767978a99dafe77eb536a9525980e118/netwerk/protocol/http/nsHttpChannel.cpp#729

Comment 6

[Shane Caraveo (:mixedpuppy)]

oh, and I just realized something. We suspend the channel if the listener returns a promise. We'll have already done a bunch of stuff in the observers before we even do that, such as url/filter matching, building the request data that gets sent to the listeners.

Comment 7

[Andrew Swan [:aswan]]

(In reply to Shane Caraveo (:mixedpuppy) from comment #5)

As well, perhaps this might be better to go into nsHttpChannel itself

Right, there is nsITimedChannel which I believe is what the existing timings shown in the profiler come from. As I said in comment 2, it appears to me that adding details timing about suspends there would be tricky and difficult to do with low overhead (which I assume is important here given that this is really hot code)

(In reply to Shane Caraveo (:mixedpuppy) from comment #6)

We suspend the channel if the listener returns a promise.

Yes, and in the parent process where the current ptch works a blocking listener always returns a Promise since we need to do IPC to the extension process. All this time seems like something we would like to measure -- if making it finer-grained is desirable, that could be done with additional markers in the extension process.

We'll have already done a bunch of stuff in the observers before we even do that, such as url/filter matching, building the request data that gets sent to the listeners.

Right, I think this is all synchronous though? Which means that if it is taking a long time, regular profiler samples are already an ideal tool for studying it?

Comment 8

[Shane Caraveo (:mixedpuppy)]

The response Bug 1624685 comment 7 shows that it is only blocking listeners, so that rules out all the "other stuff". So I think where you're doing the markers is good unless we wanted to measure only the waits on the promises. As far as the actual profile marking itself Florian is probably more knowledgeable that I am.

Comment 9

[Florian Quèze [:florian]]

A few thoughts:

• it's really nice to add more information about what's blocking network requests, thanks for looking into it!
• Julien (needinfo'ed for awareness) is who you want to talk to for adding this to the network timing diagram.
• it would be very nice to include some information about which add-on is responsible for blocking the resquest.
• sharing here an example profile that contains your new markers would be helpful to quickly get a sense of how these markers will help and which information is still missing.
• I think the existing "IPC Messages" feature of the profiler might show interesting information for interactions between the processes during these requests, I would encourage you to enable it for your next profiles.

Comment 10

[Julien Wajsberg [:julienw]]

Yeah, the fact that the network markers use the existing TimingStruct isn't super flexible. We want to introduce another struct to store more data, independent from this struct, in the future. I don't know when we'll work on this more though.

Comment 11

[Andrew Swan [:aswan]]

It sounds like there's consensus that adding this information to the timeline is desirable but significantly more work.
I'd be interested in helping out with that if practical but in the mean time, I'd like to push ahead with the simple marker based approach. Here's a profile collected with the updated patch: https://bit.ly/3bpfWVA To quickly see the what a marker looks like, open the Marker Chart or Table in the parent process and type "Suspend" in the search box (its not particularly interesting in this case, this was a test profile with uBlock Origin while loading www.mozilla.org, nothing all that interesting happens but it gives an idea what these look like)

Comment 12

[Julien Wajsberg [:julienw]]

If adding a marker solves your problem, I'm happy with this solution.
We just need to take care that it doesn't skew the result too much.

Also I think the name "Network" is too generic, maybe try a name closer to your concern.

Comment 13

[Andrew Swan [:aswan]]

(In reply to Julien Wajsberg [:julienw] from comment #12)

We just need to take care that it doesn't skew the result too much.

To be clear, you mean ensure that it doesn't add too much overhead (particularly when the profiler isn't enabled)?

Also I think the name "Network" is too generic, maybe try a name closer to your concern.

Whoops yeah, I think I confused the marker name and category when I initially wrote this, I will update it.
I'd also like to add the webRequest phase (e.g., onBeforeRequest, onHeadersReceived, etc...) and clean up the markers for redirects and cancels.
Additional feedback will still be gratefully received in the mean time though :)

Comment 14

[Julien Wajsberg [:julienw]]

To be clear, you mean ensure that it doesn't add too much overhead (particularly when the profiler isn't enabled)?

yes, exactly this! :-) But even with the profiler is enabled we need to take care. But I believe that we should be fine.

Comment 15

[Andrew Swan [:aswan]]

Attachment: Bug 1625006 Update listener names in HttpObserverManager

Make the names of the data structures used inside HttpObserverManager
match the webRequest event names.

Comment 16

[Andrew Swan [:aswan]]

Here is a profile gathered with the most recent patch: https://bit.ly/2yk4sVh

This profile covers loading huffpost.com with uBlock Origin installed -- uBO blocks several requests and redirects another. Additionally, the page load happens shortly after browser startup before uBO is fully initialized so you can see a slightly longer delay for initial requests while uBO initializes.

If you scroll down to the "Network" section of the marker chart, you can see how the markers appear for canceled requests, the redirected request, and requests that were suspended but ultimately allowed to proceed.

Comment 17

[Andrew Swan [:aswan]]

Revised to handle Shane's comments. Here's a new profile: https://bit.ly/2QWzU2e

I liked the way that markers for canceled and redirected requests really stood out in the previous revision but it seems like Shane dislikes them more than I like them :)

Comment 18

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/9b71bd542d41
Update listener names in HttpObserverManager r=mixedpuppy
https://hg.mozilla.org/integration/autoland/rev/82c93cdc8c49
Add profiler markers for blocking webRequest listeners r=mixedpuppy,gerald

Comment 19

[Cosmin Sabou [:CosminS]]

https://hg.mozilla.org/mozilla-central/rev/9b71bd542d41
https://hg.mozilla.org/mozilla-central/rev/82c93cdc8c49