Closed
Bug 1232354
Opened 9 years ago
Closed 6 years ago
uBlock Origin makes the loading of a long page hang the content process, mostly in XPCOMUtils_QueryInterface
Categories
(Firefox :: Extension Compatibility, defect)
Firefox
Extension Compatibility
Tracking
()
RESOLVED
INACTIVE
People
(Reporter: botond, Unassigned)
References
Details
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/
Comment 1•9 years ago
|
||
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
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.
The same page on Chromium 51:
- uBlock Origin 1.8.2: <1 second.
- Adblock Plus 1.12.1: <1 second.
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.
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
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.
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).
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•8 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•8 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•8 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•8 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•8 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•8 years ago
|
Comment 14•8 years ago
|
||
Looks good to me. To make this even faster, some help from the Gecko side is probably required. For example, 40% of the time in shouldLoad is now spent in XPCOMUtils_QueryInterface():
https://cleopatra.io/#report=4adc6ccfa2dcc263c261bf5aecb6c59556570c8e&filter=%5B%7B%22type%22%3A%22RangeSampleFilter%22,%22start%22%3A558595,%22end%22%3A562262%7D,%7B%22type%22%3A%22FocusedFrameSampleFilter%22,%22name%22%3A%22XPCOMUtils_QueryInterface()%20%40%20XPCOMUtils.jsm%3A459%22,%22focusedSymbol%22%3A2059%7D%5D
Updated•7 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
Comment 15•6 years ago
|
||
Closing as inactive.
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → INACTIVE
You need to log in
before you can comment on or make changes to this bug.
Description
•