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)

Product:
Firefox
Component:
Extension Compatibility
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
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/
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
(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.
> 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.
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
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.
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
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: 6 years ago
Resolution: --- → INACTIVE
You need to log in before you can comment on or make changes to this bug.