uBlock Origin makes the loading of a long page hang the content process, mostly in XPCOMUtils_QueryInterface

RESOLVED INACTIVE

Status

()

defect
RESOLVED INACTIVE
4 years ago
2 months ago

People

(Reporter: botond, Unassigned)

Tracking

Firefox Tracking Flags

(Not tracked)

Details

Reporter

Description

4 years ago
STR:

  1. Run Firefox Nightly

  2. Install uBlock Origin [1]

  3. Load any webpage

  3. In a new tab, load 
     http://people.mozilla.org/~bgirard/doxygen/gfx/annotated.html
     
     It takes ~5 seconds to load, which is much longer than without
     uBlock Origin installed. This is itself a bug (or just poor
     performance on uBlock Origin's part), but nowhere near as severe
     as the following:

  4. While the new tab is loading, navigate back to the first tab.

Expected results:

  The contents of the first tab are rendered while the second tab is loading.

Actual results:

  Switching to the first tab shows a spinner, and the contents are not
  rendered until the second tab finishes loading (i.e. the 5 seconds are up).

  Basically, the entire content process appears to be hanging until the
  second tab loads. (The chrome process remains responsive.)

In a non-e10s window, it's even worse, as the loading of the second tab appears to block the main (only) process.

[1] https://addons.mozilla.org/en-us/firefox/addon/ublock-origin/
Successfully reproduced this issue with Latest Firefox Nightly 46.0a1 (2015-12-15) on Linux, 64 Bit

Build ID: 20151215030221
User Agent: Mozilla/5.0 (X11; Linux x86_64; rv:46.0) Gecko/20100101 Firefox/46.0

Changing to a better component!
QA Whiteboard: [bugday-20151214]
Component: Untriaged → Extension Compatibility

Comment 2

3 years ago
Using the current Nightly build, for the page load, I get:

- No extension: ~2 seconds.
- uBlock Origin 1.8.2: ~5 seconds.
- Adblock Plus 2.7.2.4196-beta: ~14 seconds.

So I wouldn't say "poor performance on uBlock Origin's part". A blocker such as uBO will of course add an overhead to page load -- in today's web this overhead is often paid back multiple times by not loading all the bloat.

This is a good test case however to benchmark to try to identify opportunity for performance improvement, though I doubt I will find anything else than marginal, the content script (which is what is causing the delay given that the page itself pulls very few external resources) has already been benchmarked a lot to squeeze as much performance as possible from it. Still I will see what I can find.

Comment 3

3 years ago
The same page on Chromium 51:

- uBlock Origin 1.8.2: <1 second.
- Adblock Plus 1.12.1: <1 second.

Comment 4

3 years ago
Ugh.. turns out that for my previous eye-balled page load measurement for Nightly above, I had multi-process disabled. So here are the measurements again, but with multi-process enabled:

- No extension: < 2 seconds.
- uBlock Origin 1.8.2: ~9 seconds.
- Adblock Plus 2.7.2.4196-beta: ~19 seconds.

I was not expecting such results.

So I decided to benchmark both performance and memory usage (separately) and here are the results -- keep in mind the benchmark results are for five page reload, allowing for a reasonable delay in between:

No extension:
 24,103.76 ms    72.14%    23174    Startup::XRE_InitChildProcess :386
  2,766.72 ms     8.28%     2660    nsHtml5TreeOpExecutor::RunFlushLoop :344
  2,500.45 ms     7.48%     2404    IPDL::PHttpChannel::RecvOnStartRequest :511
    728.08 ms     2.18%      700    PresShell::DoReflow annotated.html:9532
    507.58 ms     1.52%      488    PresShell::Flush (Flush_Style) :4042
    408.77 ms     1.22%      393    XPCOMUtils_QueryInterface XPCOMUtils.jsm:459
    275.63 ms     0.82%      265    nsStyleSet::FileRules :1078
    231.95 ms     0.69%      223    js::GCRuntime::collect
    195.54 ms     0.59%      188    js::RunScript
    117.53 ms     0.35%      113    nsCycleCollector::collectSlice :4170
    115.45 ms     0.35%      111    EventDispatcher::Dispatch :483
    102.97 ms     0.31%       99    ElementRestyler::ComputeStyleChangeFor Element: html.:3335
    101.93 ms     0.31%       98    js::SavedStacks::saveCurrentStack
    100.89 ms     0.30%       97    Request<.write protocol.js:617
     99.85 ms     0.30%       96    nsCycleCollector::forgetSkippable :4106
     79.05 ms     0.24%       76    Timer::Fire:465
     61.37 ms     0.18%       59    ChildDebuggerTransport.prototype.send transport.js:755
     58.25 ms     0.17%       56    IPDL::PHttpChannel::RecvOnTransportAndData :672
     56.17 ms     0.17%       54    IPDL::PBrowser::RecvAsyncMessage :3020
     43.69 ms     0.13%       42    exports.Framerate<._onRefreshDriverTick framerate.js:82

uBlock Origin:
 33,007.22 ms    33.90%    32301    IPDL::PBrowser::SendRpcMessage :650
 27,821.27 ms    28.57%    27226    Startup::XRE_InitChildProcess :386
 10,078.64 ms    10.35%     9863    nsHtml5TreeOpExecutor::RunFlushLoop:344
  8,763.50 ms     9.00%     8576    contentObserver.shouldLoad frameModule.js:201
  2,474.95 ms     2.54%     2422    IPDL::PHttpChannel::RecvOnStartRequest :511
  1,935.41 ms     1.99%     1894    vAPI.messaging.sendTo vapi-client.js:329
  1,798.48 ms     1.85%     1760    getMessageManager frameModule.js:41
  1,726.95 ms     1.77%     1690    XPCOMUtils_QueryInterface XPCOMUtils.jsm:459
  1,648.27 ms     1.69%     1613    domIsLoaded/surveyPhase1 contentscript.js:1221
  1,383.60 ms     1.42%     1354    js::Nursery::collect
    829.75 ms     0.85%      812    js::RunScript
    807.27 ms     0.83%      790    js::GCRuntime::collect
    734.72 ms     0.75%      719    add contentscript.js:792
    714.28 ms     0.73%      699    PresShell::DoReflow annotated.html:9532
    526.26 ms     0.54%      515    PresShell::Flush (Flush_Style) :4042
    435.31 ms     0.45%      426    domIsLoaded/< contentscript.js:1436
    308.60 ms     0.32%      302    nsStyleSet::FileRules :1078
    181.89 ms     0.19%      178    domIsLoaded/processHighHighGenerics contentscript.js:1150
    142.04 ms     0.15%      139    nsCycleCollector::forgetSkippable :4106
    142.04 ms     0.15%      139    domIsLoaded/processHighMediumGenericsForNodes contentscript.js:1118

Adblock Plus:
195,806.43 ms    62.27%   193840    IPDL::PContent::SendRpcMessage :3482
 45,702.98 ms    14.54%    45244    Startup::XRE_InitChildProcess :386
 13,028.85 ms     4.14%    12898    js::Nursery::collect
 11,909.61 ms     3.79%    11790    nsHtml5TreeOpExecutor::RunFlushLoop :344
  8,701.39 ms     2.77%     8614    sendSyncMessage messaging.js:53
  6,332.60 ms     2.01%     6269    PolicyImplementation.shouldLoad contentPolicy.js:274
  5,219.42 ms     1.66%     5167    processPolicyResponse contentPolicy.js:87
  3,814.31 ms     1.21%     3776    exports.Utils.getWindow utils.js:128
  2,583.95 ms     0.82%     2558    IPDL::PHttpChannel::RecvOnStartRequest :511
  1,937.46 ms     0.62%     1918    exports.getFrames utils.js:80
  1,850.58 ms     0.59%     1832    js::RunScript
  1,850.58 ms     0.59%     1832    XPCOMUtils_QueryInterface XPCOMUtils.jsm:459
  1,825.33 ms     0.58%     1807    js::GCRuntime::collect
  1,807.15 ms     0.57%     1789    RequestNotifier.addNodeData requestNotifier.js:334
  1,512.19 ms     0.48%     1497    exports.getWindowLocation utils.js:27
  1,337.43 ms     0.43%     1324    pbu_privacyContextFromWindow PrivateBrowsingUtils.jsm:47
  1,308.14 ms     0.42%     1295    exports.shouldAllow contentPolicy.js:133
  1,305.11 ms     0.42%     1292    nsStyleSet::FileRules :1078
  1,260.66 ms     0.40%     1248    exports.Utils.unwrapURL utils.js:176
    826.30 ms     0.26%      818    PresShell::DoReflow annotated.html:9532


Memory: explicit allocations (after minimizing memory usage 3 times):

No extension:
286.08 MB (100.0%) -- explicit
├──112.36 MB (39.28%) ++ js-non-window
├───55.08 MB (19.25%) ++ window-objects
├───39.97 MB (13.97%) ++ gfx
├───39.85 MB (13.93%) ── heap-unclassified
├───12.31 MB (04.30%) ++ (18 tiny)
├────9.64 MB (03.37%) ++ workers/workers(chrome)
├────6.92 MB (02.42%) ++ storage
├────6.69 MB (02.34%) ++ heap-overhead
└────3.26 MB (01.14%) ++ xpconnect

uBlock Origin:
239.21 MB (100.0%) -- explicit
├───68.91 MB (28.81%) ++ window-objects
├───59.89 MB (25.04%) ++ js-non-window
├───40.02 MB (16.73%) ++ gfx
├───25.19 MB (10.53%) ── heap-unclassified
├───10.14 MB (04.24%) ++ (16 tiny)
├────7.77 MB (03.25%) ++ heap-overhead
├────7.61 MB (03.18%) ++ add-ons
├────7.06 MB (02.95%) ++ storage
├────6.21 MB (02.60%) ++ workers/workers(chrome)
├────3.92 MB (01.64%) ++ startup-cache
└────2.50 MB (01.04%) ++ images

Adblock Plus:
452.73 MB (100.0%) -- explicit
├──165.92 MB (36.65%) ++ js-non-window
├───68.33 MB (15.09%) ++ add-ons
├───66.04 MB (14.59%) ── heap-unclassified
├───58.47 MB (12.92%) ++ window-objects
├───40.02 MB (08.84%) ++ gfx
├───17.65 MB (03.90%) ++ workers/workers(chrome)
├───12.03 MB (02.66%) ++ (16 tiny)
├────7.04 MB (01.55%) ++ heap-overhead
├────6.92 MB (01.53%) ++ storage
├────5.33 MB (01.18%) ++ layout
└────4.98 MB (01.10%) ++ atom-tables

I have all the saved data for the benchmarks and memory usage if needed.

Comment 5

3 years ago
The memory usage does not make much sense above, no way it would be lower with uBO compared with no extension. I wish I could edit the comment... Probably the error re. memory is that I click "Measure and save" after click "Measure" once. Here is what I get just using "Measure" (4 tabs opened: about:addons, this page, the test page above, and about:memory):

No extension:
145.09 MB (100.0%) -- explicit
├───52.23 MB (35.99%) ++ js-non-window
├───23.34 MB (16.09%) ── heap-unclassified
├───18.24 MB (12.57%) ++ gfx
├───16.24 MB (11.19%) ++ window-objects
├────9.17 MB (06.32%) ++ heap-overhead
├────6.81 MB (04.70%) ++ storage
├────6.22 MB (04.29%) ++ workers/workers(chrome)
├────4.92 MB (03.39%) ++ (16 tiny)
├────3.71 MB (02.56%) ++ startup-cache
├────2.39 MB (01.65%) ++ images
└────1.81 MB (01.25%) ++ xpconnect

uBlock Origin:
170.05 MB (100.0%) -- explicit
├───56.34 MB (33.13%) ++ js-non-window
├───28.85 MB (16.96%) ++ window-objects
├───22.48 MB (13.22%) ── heap-unclassified
├───18.29 MB (10.75%) ++ gfx
├───10.30 MB (06.06%) ++ heap-overhead
├────7.55 MB (04.44%) ++ add-ons
├────6.95 MB (04.09%) ++ storage
├────6.22 MB (03.66%) ++ workers/workers(chrome)
├────4.78 MB (02.81%) ++ (15 tiny)
├────3.92 MB (02.30%) ++ startup-cache
├────2.51 MB (01.48%) ++ images
└────1.87 MB (01.10%) ++ xpconnect

Adblock Plus:
310.10 MB (100.0%) -- explicit
├───94.96 MB (30.62%) ++ add-ons
├───85.90 MB (27.70%) ++ js-non-window
├───51.30 MB (16.54%) ── heap-unclassified
├───18.29 MB (05.90%) ++ gfx
├───15.98 MB (05.15%) ++ window-objects
├────9.25 MB (02.98%) ++ heap-overhead
├────7.58 MB (02.44%) ++ workers/workers(chrome)
├────7.05 MB (02.27%) ++ (15 tiny)
├────6.81 MB (02.20%) ++ storage
├────5.33 MB (01.72%) ++ layout
├────4.51 MB (01.45%) ++ startup-cache
└────3.14 MB (01.01%) ++ atom-tables

Comment 6

3 years ago
Ok I think I understand what is happening here. The web page contains only a dozen or so image resources. However this handful of images are reused many, many times in the page. I instrumented shouldLoad(), and there were nearly 30,000 invocation of shouldLoad() for that page, mostly just for the same images over and over. This is the current top bottleneck.

I do question whether it is really needed for shouldLoad() to be called for exactly the same resource in the same frame over and over. Calling only once for every distinct resource in every distinct origin would be much more friendly performance-wise.

In any case, in uBlock Origin, the purpose of the shouldLoad() handler is mostly to document from which frame a resource is pulled (for instance uMatrix does not use shouldLoad). That information is sent to the chrome process, which will later retrieve it when the corresponding HTTP request needs to be handled.

This means there is ground to improve for uBlock Origin: send the frame information to the chrome process *only* when we are not dealing with a resource for the top-level frame. When the HTTP handler in the chrome process does not find the frame information about a resource, it will be (correctly) assumed to be a resource sitting in the top-level frame (the top document). So here is a benchmark with that code change:

23,114.71 ms    45.62%    22387    Startup::XRE_InitChildProcess :386
 7,802.65 ms    15.40%     7557    nsHtml5TreeOpExecutor::RunFlushLoop :344
 2,992.20 ms     5.91%     2898    contentObserver.shouldLoad frameModule.js:202
 2,785.70 ms     5.50%     2698    domIsLoaded/surveyPhase1 contentscript.js:1245
 2,647.35 ms     5.23%     2564    IPDL::PHttpChannel::RecvOnStartRequest :511
 2,003.06 ms     3.95%     1940    vAPI.messaging.sendTo vapi-client.js:329
 1,545.66 ms     3.05%     1497    XPCOMUtils_QueryInterface XPCOMUtils.jsm:459
   748.57 ms     1.48%      725    add contentscript.js:816
   736.18 ms     1.45%      713    js::RunScript
   692.81 ms     1.37%      671    PresShell::DoReflow annotated.html:9532
   661.84 ms     1.31%      641    js::GCRuntime::collect
   510.06 ms     1.01%      494    PresShell::Flush (Flush_Style) :4042
   482.18 ms     0.95%      467    nset::FileRules :1078
   439.85 ms     0.87%      426    domIsLoaded/< contentscript.js:1455
   425.39 ms     0.84%      412    js::Nursery::collect
   244.70 ms     0.48%      237    ElementRestyler::ComputeStyleChangeFor Element: html.:3335
   182.75 ms     0.36%      177    domIsLoaded/processHighHighGenerics contentscript.js:1174
   173.46 ms     0.34%      168    nsCycleCollector::forgetSkippable :4106
   144.55 ms     0.29%      140    domIsLoaded/selectNodes contentscript.js:1217

I copy-pasted here the benchmark for uBO from before the code change (above), for easy reference:
 33,007.22 ms    33.90%    32301    IPDL::PBrowser::SendRpcMessage :650
 27,821.27 ms    28.57%    27226    Startup::XRE_InitChildProcess :386
 10,078.64 ms    10.35%     9863    nsHtml5TreeOpExecutor::RunFlushLoop:344
  8,763.50 ms     9.00%     8576    contentObserver.shouldLoad frameModule.js:201
  2,474.95 ms     2.54%     2422    IPDL::PHttpChannel::RecvOnStartRequest :511
  1,935.41 ms     1.99%     1894    vAPI.messaging.sendTo vapi-client.js:329
  1,798.48 ms     1.85%     1760    getMessageManager frameModule.js:41
  1,726.95 ms     1.77%     1690    XPCOMUtils_QueryInterface XPCOMUtils.jsm:459
  1,648.27 ms     1.69%     1613    domIsLoaded/surveyPhase1 contentscript.js:1221
  1,383.60 ms     1.42%     1354    js::Nursery::collect
    829.75 ms     0.85%      812    js::RunScript
    807.27 ms     0.83%      790    js::GCRuntime::collect
    734.72 ms     0.75%      719    add contentscript.js:792
    714.28 ms     0.73%      699    PresShell::DoReflow annotated.html:9532
    526.26 ms     0.54%      515    PresShell::Flush (Flush_Style) :4042
    435.31 ms     0.45%      426    domIsLoaded/< contentscript.js:1436
    308.60 ms     0.32%      302    nsStyleSet::FileRules :1078
    181.89 ms     0.19%      178    domIsLoaded/processHighHighGenerics contentscript.js:1150
    142.04 ms     0.15%      139    nsCycleCollector::forgetSkippable :4106
    142.04 ms     0.15%      139    domIsLoaded/processHighMediumGenericsForNodes contentscript.js:1118

There might be more opportunity to improve, but this was the top one I could spot.

Comment 7

3 years ago
After the latest changes in uBlock Origin, I measure ~4 seconds for the page <http://people.mozilla.org/~bgirard/doxygen/gfx/annotated.html> to load, regardless of whether multi-process is enabled or not.

Regarding point 4:

> Switching to the first tab shows a spinner, and the contents are not rendered until the second tab finishes loading (i.e. the 5 seconds are up).

The explanation (from my understanding) is that both tabs sit in the same content process, so it's expected that when a tab monopolizes the content process, other tabs in the same content process will be delayed -- *regardless* of whether there are extensions or not.

For example, I increased the dom.ipc.processCount to 2 in about:config, and this resolves the issue raised in point 4, the other tab displayed fine while the test page was being loaded.

Not calling sendRpcMessage() in shouldLoad() whenever possible will help general performance, and does help for the specific test page mentioned in this bug.

However, if one was to embed that test page in a frame, uBO would exhibit again the same performance issue. The real issue here is that uBO is *forced* to make use of shouldLoad()/sendRpcMessage() in order to attempt as best as possible to attach frame-id/parent-frame-id information to network requests.

The long-term solution would be make that information available directly from the HTTP observer (just like it is in Chromium's webRequest API) -- this would alleviate the need for shouldLoad()/sendRpcMessage() which is the bottleneck in OP's test case. (As mentioned, the page load in less than one second with Chromium).

Comment 8

3 years ago
It must be understood this was not an issue specific to uBlock Origin: as shown ABP suffers to a greater degree from what I call the shouldLoad() issue.

Any extension implementing shouldLoad() is a candidate for showing poor performance to load the test page in this bug report.

For example, I just measured that even with BluHell Firewall[1], a lightweight blocker, the page load completes after 20 seconds. The same performance issue has been found with Decentraleyes[2].

1. https://addons.mozilla.org/en-US/firefox/addon/bluhell-firewall/
2. https://github.com/Synzvato/decentraleyes/issues/114
Reporter

Comment 9

3 years ago
(In reply to R. Hill from comment #7)
> The long-term solution would be make that information available directly
> from the HTTP observer (just like it is in Chromium's webRequest API) --
> this would alleviate the need for shouldLoad()/sendRpcMessage() which is the
> bottleneck in OP's test case. (As mentioned, the page load in less than one
> second with Chromium).

If I understood correctly, this is a suggestion for a Firefox change that would enable better performance of uBlock Origin and other addons.

Could you file a new bug for this? Feel free to point to the explanations in this bug as the motivation.

Comment 10

3 years ago
> Could you file a new bug for this?

Your suggestion to open an issue made remember that the key information uBO needs to be able to do its job without the shouldLoad() code path currently required is already something fixed on Firefox's side: https://bugzilla.mozilla.org/show_bug.cgi?id=1242871

Once WebExtensions has all the required APIs, I will be able to start to experiment converting uBO to a WebExtensions-based extension, and if all work as expected, the shouldLoad() issue will become obsolete for uBO (as long as the webRequest.onBeforeRequest API does not internally use shouldLoad(), that is still unclear to me).

For other add-ons, only their maintainers can comment on what is best for them, and it could happen I suppose that not relying on shouldLoad() is not an option for them.

Comment 11

3 years ago
If I read the code correctly, the WebRequest API acquires the frameId and parentFrameId from the HTTP channel loadInfo.
https://dxr.mozilla.org/mozilla-central/source/toolkit/modules/addons/WebRequest.jsm#537-553
https://dxr.mozilla.org/mozilla-central/source/toolkit/components/extensions/ext-webRequest.js#41-42

Though this only applies to HTTP request. Non HTTP request still goes through shouldLoad().
https://dxr.mozilla.org/mozilla-central/source/toolkit/modules/addons/WebRequestContent.js#84-87

Comment 12

3 years ago
Thanks for the info anonbugreport. I imported the code into uBlock Origin, and tested for  Firefox 44, 45, 48, and Nightly, and I confirm this works very well for the various pages I have tested -- many with embedded iframes.

Comment 13

3 years ago
With the latest changes, these are the benchmark results, using the page load speed tool[1]. uBO 1.8.5b6 is available in the dev channel on AMO.

http://people.mozilla.org/~bgirard/doxygen/gfx/annotated.html
     1.8.4  : Average (valid): 8716.57 ms
     1.8.5b6: Average (valid): 2820.21 ms
No extension: Average (valid): 1283.98 ms

Above is an extreme case from the point of view of an extension implementing nsIContentPolicy.shouldLoad, given that shouldLoad() is called nearly 30,000 times for that page. I wanted to see the difference with a more normal but yet still quite a large page:

https://en.wikipedia.org/wiki/List_of_country_calling_codes
     1.8.4  : Average (valid):  971.42 ms
     1.8.5b6: Average (valid):  721.11 ms
No extension: Average (valid):  629.64 ms

A more common case, the front page of a major news outlet (no point testing without extension, because the ads/trackers would make the page load much slower without a blocker):

http://www.wsj.com/
     1.8.4  : Average (valid): 2043.42 ms
     1.8.5b6: Average (valid): 1909.21 ms

So I suppose the issue can be closed?


1. http://www.raymondhill.net/ublock/pageloadspeed.html

Updated

2 years ago
Summary: uBlock Origin makes the loading of a long page hang the content process → uBlock Origin makes the loading of a long page hang the content process, mostly in XPCOMUtils_QueryInterface

Closing as inactive.

Status: NEW → RESOLVED
Closed: 2 months ago
Resolution: --- → INACTIVE
You need to log in before you can comment on or make changes to this bug.