Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Performance of the Per site switches counters #756

Closed
8 tasks done
gwarser opened this issue Oct 14, 2019 · 48 comments
Closed
8 tasks done

Performance of the Per site switches counters #756

gwarser opened this issue Oct 14, 2019 · 48 comments
Labels
fixed issue has been addressed

Comments

@gwarser
Copy link

gwarser commented Oct 14, 2019

Prerequisites

Prerequisites

  • I verified that this is not a filter issue
  • This is not a support issue or a question
  • I performed a cursory search of the issue tracker to avoid opening a duplicate issue
    • Your issue may already be reported.
  • I tried to reproduce the issue when...
    • uBlock Origin is the only extension
    • uBlock Origin with default lists/settings
    • using a new, unmodified browser profile
  • I am running the latest version of uBlock Origin
  • I checked the documentation to understand that the issue I report is not a normal behavior

Description

High cpu usage, over 4s in querySelectorAll, every time uBO popup is opened when on gorhill/uBlock@3224d9b

Even on https://github.com/orgs/uBlockOrigin/teams/ublock-issues-volunteers I see times over 1s.

Example profile:
https://profiler.firefox.com/public/540cf7624a701b19a0927eef13c3fc5283aa364e/calltree/?globalTrackOrder=0-1&implementation=js&localTrackOrderByPid=17028-0~17307-0~&thread=1&v=4

Nothing seems to be freezing or locking, but it's just waste of resources. Hmmm... I think I had problems on my phone - opening popup can be slow/jaggy, but I will need to profile this specifically.

Even Chrome is not very good, over 1s:
image

Internal discussion: https://github.com/orgs/uBlockOrigin/teams/ublock-issues-volunteers/discussions/146

A specific URL where the issue occurs

gorhill/uBlock@3224d9b

Steps to Reproduce

  1. Open page with large DOM, example gorhill/uBlock@3224d9b
  2. Click uBO button to open popup panel

Expected behavior:

No impact on CPU usage

Actual behavior:

High CPU usage for up to few secons

Your environment

  • uBlock Origin version: 1.22.5rc3
  • Browser Name and version: Nightly 71, Chrome 77
  • Operating System and version: Manjaro
@gwarser gwarser added the TODO todo label Oct 14, 2019
@gorhill
Copy link
Member

gorhill commented Oct 30, 2019

Expected behavior:

No impact on CPU usage

That is just impossible, the overhead is in inside document.querySelectorAll, which means the only remedy would be to not call document.querySelectorAll and consequently to not show the number of matched elements in the popup panel. Is this what you are suggesting?

@gwarser
Copy link
Author

gwarser commented Oct 30, 2019

Of course this should be "no huge impact on CPU usage".

I thing there is no point to call this function every time popup is opened. For me it will be ok to fix this by:

  • simply putting checkmark overlay once, when something at all has been blocked, without counting every occurrence; OR
  • call it on first open and cache results for at least few dozens seconds.

@gorhill
Copy link
Member

gorhill commented Oct 30, 2019

checkmark overlay once, when something at all has been blocked

Just finding out if one single element has been filtered potentially requires testing all injected cosmetic filters -- which is what happens in the mentioned test case -- so just finding out if only one element is filtered is no better than counting them all when no elements are filtered.

@gwarser
Copy link
Author

gwarser commented Oct 30, 2019

Then only this case - few clicks in a row.

@gorhill
Copy link
Member

gorhill commented Oct 30, 2019

I don't understand "Then only this case". You mean "then only this case" should be fixed?

@gwarser
Copy link
Author

gwarser commented Oct 30, 2019

You mean "then only this case" should be fixed?

Yes. If nothing can be done to improve this querySelector(All) call, then it should be called as rarely as possible.

gorhill added a commit to gorhill/uBlock that referenced this issue Oct 31, 2019
Related issue:
- uBlockOrigin/uBlock-issues#756

This is the code used to find out the count values
displayed as badge on the cosmetic filtering and
scripting per-site switches in the popup panel.

The issue is that document.querySelector*() -- used to
find out the number of hidden elements -- is unduly
expensive on large DOM.

The changes in this commit have focused on avoiding the
use of document.querySelector*() as much as possible.

Also, the results are cached for reuse unless DOM
mutations are detected.
@gwarser gwarser closed this as completed Oct 31, 2019
@gwarser gwarser added fixed issue has been addressed and removed TODO todo labels Oct 31, 2019
@gorhill
Copy link
Member

gorhill commented Oct 31, 2019

How does profiler results compare with before?

@gwarser
Copy link
Author

gwarser commented Oct 31, 2019

Hard to say. On page from OP it's ~2x faster. No, or small load on subsequent clicks, so this part is good. On the other hand on youtube.com or new.reddit.com first call looks very bad in profile. However CPU load seems to be more evenly distributed between CPU cores, so it may be less jerky.

https://mega.nz/#F!bcIAgSrR!R2ytB8Cqc9Heli6w5DP_NA

@gorhill
Copy link
Member

gorhill commented Nov 1, 2019

seems to be more evenly distributed between CPU cores

uBO's content scripts run in the same process as the page's script.

I am not very happy with those results. I will re-open. There does not seem to be solution -- removing the badge count for the cosmetic filtering icon is really what would get rid of the issue; other blockers do not have this feature and thus are not suffering from it.

@gorhill gorhill reopened this Nov 1, 2019
@gorhill
Copy link
Member

gorhill commented Nov 1, 2019

At this link, https://www.reddit.com/r/uBlockOrigin/, default settings in uBO, I get ~40 ms in Chromium stable and ~50 ms in Firefox stable. I used integrated performance profiler for Chromium and Firefox Profiler for Firefox.

Edit: I do get undue CPU usage when I scroll down two pages. In this case I find that a lot of elements have offsetParent set to null, which is one of the condition used by the new code to decide whether the matching should be tested or not. So a high count of elements with null offsetParent may end up be more costly than just a plain querySelectorAll. Not sure how common that scenario occurs.

@uBlock-user uBlock-user added something to address something to address and removed fixed issue has been addressed labels Nov 1, 2019
gorhill added a commit to gorhill/uBlock that referenced this issue Nov 1, 2019
Related issue:
- uBlockOrigin/uBlock-issues#756

The badge value for the no-cosmetic-filtering
switch will be evaluated on-demand only, when
the user hover over the switch with the mouse
cursor.

For touch screen displays, a tap on the switch
will cause the badge to be rendered if not
already done, otherwise this will toggle the
switch as usual.
gorhill added a commit to gorhill/uBlock that referenced this issue Nov 1, 2019
Related issue:
- uBlockOrigin/uBlock-issues#756

The code used to count expensive-to-survey particular
inline javascript occurrences will be executed if and
only if no other script tags have been found in the
DOM. This is acceptable since the badge count is to be
deemed approximate (as per documentation).
@gwarser
Copy link
Author

gwarser commented Nov 1, 2019

seems to be more evenly distributed between CPU cores

uBO's content scripts run in the same process as the page's script.

What I meant, heavy calculation in one large loop/function call can block other tasks - can prevents switching to them. If load is distributed between many calls to "small" function, tasks can be switched more often, which may have good effect on browser responsiveness.

I am not very happy with those results. I will re-open. There does not seem to be solution -- removing the badge count for the cosmetic filtering icon is really what would get rid of the issue; other blockers do not have this feature and thus are not suffering from it.

👍

At this link, reddit.com/r/uBlockOrigin, default settings in uBO, I get ~40 ms in Chromium stable and ~50 ms in Firefox stable. I used integrated performance profiler for Chromium and Firefox Profiler for Firefox.

I tried clean profile with https://old.reddit.com/r/uBlockOrigin/ which loads only 25 results by default, and in b5 getFilteredElementCount takes 82ms, in b7 surveyResults.hiddenElementCount takes 68 ms.
In new.reddit 74ms in b5 and 84ms in b7. But with old code I clearly see spikes in cpu usage, where in new they hide in noise.


I need to check why on my daily profile it requires 1-1.5s for this.

Heh ??? It looks like moderation privilege causes uBO subreddit to be 2 to 5 times slower :D No add-ons except uBO b9, surveyResults.hiddenElementCount< time logged as gwarser on https://old.reddit.com/r/uBlockOrigin/ -> 1400ms, logged in my second account -> 300ms, gwarser on https://old.reddit.com/r/firefox/ -> ~500ms, second account -> ~550ms

@gorhill
Copy link
Member

gorhill commented Nov 1, 2019

If load is distributed between many calls to "small" function

Sure but that is not really what I implemented -- collating all the hidden elements still requires one JS pass.

In any case, the latest changes are:

  • For hidden elements: update the badge value on-demand, when hovering over it.
  • For inline script tags or other sort of inline JS code: search for these if and only if no other script tags has been found (not in dev build yet).
  • For either, the result is cached until the DOM is mutated.

@uBlock-user
Copy link
Contributor

uBlock-user commented Nov 2, 2019

On this page and the ones where there are lots of responses on this issue tracker, it takes upto a second or two for the . . . to disappear. Is this normal ? I do have all annoyances lists activated.

Edit: I can reproduce this issue even far worse on facebook. Keep scrolling and scrolling and scrolling... and then open the popup panel, hover over the switch which will cause to look for elements indefinitely as the DOM grew large and large with the scrolling and then you get a warning from Firefox --

image

For Twitter keep scrolling on this profile until you reach the very first tweet, will take a long while to reach.

Edit2: Happening with b7 build too which had the previous functionality..querySelectorAll and enormous DOMs don't work well 😫

@gwarser
Copy link
Author

gwarser commented Nov 2, 2019

@gorhill
Copy link
Member

gorhill commented Nov 2, 2019

I do have all annoyances lists activated.

That can make a big difference, so far I tested with default lists.

@gorhill
Copy link
Member

gorhill commented Nov 2, 2019

Please, I need to know what URL visited and what filter lists are selected with profiling results, I am unable to guess. I tried this page here along with all Annoyances lists enabled and I got 210 ms on Firefox 70.0.1:

https://profiler.firefox.com/public/d51106894cd056d26b97bf13260c2143270d42a7/calltree/?globalTrackOrder=0-1-2&implementation=js&thread=2&v=4

@uBlock-user
Copy link
Contributor

uBlock-user commented Nov 2, 2019

Built-In -- all except Unbreak, Ads -- 4/4, Privacy 3/3, Annoyances -- 6/6,

Custom --

https://easylist-downloads.adblockplus.org/adwarefilters.txt
https://raw.githubusercontent.com/metaphoricgiraffe/tracking-filters/master/trackingfilters.txt
https://raw.githubusercontent.com/uBlock-user/uBO-Personal-Filters/master/uPF.txt
https://raw.githubusercontent.com/yourduskquibbles/webannoyances/master/filters/generic_filters.txt
https://raw.githubusercontent.com/yourduskquibbles/webannoyances/master/filters/modal_filters.txt
https://raw.githubusercontent.com/yourduskquibbles/webannoyances/master/filters/newsletter_filters.txt
https://raw.githubusercontent.com/yourduskquibbles/webannoyances/master/filters/social_filters.txt 

URLs -

https://github.com/uBlockOrigin/uBlock-issues/issues/756
https://facebook.com (probably will need an account)
https://twitter.com/Jack
https://github.com/uBlockOrigin/uBlock-issues/issues/615

profiling results

I didn't profile, just my observation if you try to element count on those pages with aformentioned lists enabled.

@gorhill
Copy link
Member

gorhill commented Nov 2, 2019

For Twitter keep scrolling on this profile until you reach the very first tweet, will take a long while to reach.

On this one I can reproduce a 4s delay, without needing to go to the very first tweet -- default lists + all Annoyances lists selected + AdGuard Base list.

So the conclusion is simple, uBO needs to bail out after a set time to avoid this, meaning it may happen the badge can't be evaluated due to performance considerations.

@uBlock-user
Copy link
Contributor

Can you not reproduce on this page on github ?

@gorhill
Copy link
Member

gorhill commented Nov 2, 2019

Can you not reproduce on this page on github ?

I commented above:

I tried this page here along with all Annoyances lists enabled and I got 210 ms on Firefox 70.0.1

@uBlock-user
Copy link
Contributor

uBlock-user commented Nov 2, 2019

This is not a isolated incident, performance always drops whenever you start scrolling on your newsfeed on facebook for longer periods of time, this just happens to be the one of the issues on their website, but on the browser side of things we do need a native API for this.

@gorhill
Copy link
Member

gorhill commented Nov 2, 2019

There is a logic mistake in my last commit, it does not bail out as it's supposed to, it currently needs to find at least one matching element before it bails out, which means the issue is still there for when there is not a single one matching element on a page.

gorhill added a commit to gorhill/uBlock that referenced this issue Nov 2, 2019
@troysjanda
Copy link

troysjanda commented Nov 2, 2019

Can there be a advance setting to revert to showing how many are blocked. Every site now just displays "?" and I have an 8 core processor. I do not like this change FYI! The roll over "..." is ok but after visiting almost every bookmark and getting just an ? Reverting to prior version.

@gorhill
Copy link
Member

gorhill commented Nov 2, 2019

Advanced setting is not possible, the scriptlet has to execute in a synchronous manner. 8 core processor does not matter here, the scriptlet execute in the content process, i.e. one core. The issue is probably you have a lot of cosmetic filters.

@troysjanda
Copy link

Advanced setting is not possible, the scriptlet has to execute in a synchronous manner. 8 core processor does not matter here, the scriptlet execute in the content process, i.e. one core. The issue is probably you have a lot of cosmetic filters.

I use the standard lists that come with Ubo, no custom lists. Besides the default Ubo lists I use easylist easy privacy, and fanboy annoyance, and fanboy cookie. Every site displays a "?" after rolling over the "...", I guess that Ill be stuck using the v1.23.1b6.

@gorhill
Copy link
Member

gorhill commented Nov 2, 2019

What the issue here says is that I should have never put it in in the first place, other blockers do not have this, so currently the fix here is the least worst option, the worst is removing the badge altogether. I can't do magic.

@troysjanda
Copy link

ill just use the v1.23.1b6 version until it no longer works. I might be the minority here but I like to see the count numbers, I read through this issue and I don't use facebook, twitter and I am not seeing any spikes in cpu usage that are a result of Ubo. I understand that you cant please everyone. Just don't like this particular change and Ill make due with the older version until it no longer works.

@uBlock-user
Copy link
Contributor

here is the least worst option

or you could keep the badge but don't show the numbers but instead show the switch bolded or darkend so to signify that something has been blocked, possible ?

@troysjanda
Copy link

troysjanda commented Nov 2, 2019

ill just use the v1.23.1b6 version until it no longer works. As I said I might be in a real minority of those that like to see the numbers. I don't want to be that guy that messes up a change that the majority might like ill just continue to use ill just use the v1.23.1b6.

@gorhill
Copy link
Member

gorhill commented Nov 2, 2019

something has been blocked

On this page here, to find out whether something has been blocked requires not bailing out, meaning 100% CPU usage for seconds as shown in the above profiling results. uBO needs to bail out, there is no magic way to deal with this performance issue.

@gorhill
Copy link
Member

gorhill commented Nov 2, 2019

the majority might like

It's not even a matter of like/not like, it's a matter of preventing uBO from hogging the CPU for seconds just for the sake of badge count, and potentially interfering seriously with a site's proper functioning.

@troysjanda
Copy link

Thank you, Maybe its just me but I am not seeing spikes in cpu. This is a great addons and ill continue to use v1.23.1b6 thanks for your time.

@gwarser
Copy link
Author

gwarser commented Nov 2, 2019

After latest comment here, I started getting insane numbers in profiler, like 15 seconds!

I think I have found optimization - there is no point counting nodes inside already hidden nodes, so maybe something like this:

diff --git a/src/js/scriptlets/dom-survey-elements.js b/src/js/scriptlets/dom-survey-elements.js
index e315b8b1..4d5b43cd 100644
--- a/src/js/scriptlets/dom-survey-elements.js
+++ b/src/js/scriptlets/dom-survey-elements.js
@@ -79,6 +79,7 @@
             for (;;) {
                 const node = nodeIter.nextNode();
                 if ( node === null ) { break; }
+                if ( node.parentNode.offsetParent == null ) { continue; }
                 if ( node.offsetParent === null ) {
                     candidates.add(node);
                 }

Then matches and closest is executed on smaller number of nodes. And gives me sane timing again.


This is still on b9!

@gorhill
Copy link
Member

gorhill commented Nov 2, 2019

Advanced setting is not possible

Took a break from computer then it occurred to me I don't need to pass setting to the scriptlet, I just need to inject a different scriptlet, so I can bring back the previous behavior with an advanced setting.

@gorhill
Copy link
Member

gorhill commented Nov 2, 2019

there is no point counting nodes inside already hidden nodes

Good idea (sorry I didn't read properly before my deleted comment). In such case, it might be better if I use a TreeWalker instead of a node iterator, if a node is hidden, I just move to the next sibling instead of the next node.

@gorhill
Copy link
Member

gorhill commented Nov 2, 2019

Good idea

Well actually I don't think this can work, offsetParent can be null even when a node is not necessarily affected by display: none, see "Notes" at documentation. So maybe you got better result because offsetParent for document.body is always null, meaning you were essentially testing one single node only, document.body.

Edit: well I suppose I can rewrite the loop to skip descendants when there is a match rather then when offsetParent is null.

@gwarser
Copy link
Author

gwarser commented Nov 2, 2019

I tested this on https://old.reddit.com/r/uBlockOrigin/ and returned valid numbers (over 50 blocked).


Custom filter for "glided":

reddit.com##body.listing-page a > .gilded-icon,.buttons.flat-list > .give-gold-button

@gorhill
Copy link
Member

gorhill commented Nov 2, 2019

Interesting,

URL: https://www.google.ca/search?hl=en&q=laptop

When I skip descendants in case of match, I get 2 matches on the badge.

Using 1.23.0, I get ~80 matches

Using 1.23.1b12, I get ?.

So obviously skipping descendants is better than ending up with ?, though not exactly what was reported before. To achieve this, there will be an advanced setting to restore the old, potentially slow surveyor code.

@gorhill
Copy link
Member

gorhill commented Nov 2, 2019

returned valid numbers (over 50 blocked).

There would be a problem if any of the cosmetically filtered elements are children of body or of a position: fixed element -- so we really need to skip descendants only in case of match.

gorhill added a commit to gorhill/uBlock that referenced this issue Nov 2, 2019
Related issue:
- uBlockOrigin/uBlock-issues#756

As per various feedbacks:

Added an advanced setting to keep the original behavior,
which can be potentially costly CPU-wise on some sites:

    popupCosmeticFilterBadgeSlow

Default to `false`. Set to `true` to restore original
method of surveying the number of elements hidden as
a result of applying cosmetic filtering.

As suggested by <https://github.com/gwarser>, skip
descendant of nodes which have been found to be a
match in order to potentially increase the number
of nodes which can be surveyed in the alloted time.
@gwarser
Copy link
Author

gwarser commented Nov 3, 2019

"all" code should be set as default an other code removed. With on-demand approach there is no longer issue with performance every time popup is opened (based on OP description - solved). querySelectorAll is still faster than node walking code (when checked with time limit unlocked). Time limit was good, but when requested on demand, can be frustrating to get ? half the time - I'm willing to wait few seconds to get "exact" numbers when I really want them, but now it's "protected in two steps" by on-demand mouse hover, and then time limit which finally gives ?.

@uBlock-user uBlock-user added fixed issue has been addressed and removed something to address something to address labels Nov 3, 2019
gorhill added a commit to gorhill/uBlock that referenced this issue Nov 3, 2019
@gwarser
Copy link
Author

gwarser commented Nov 3, 2019

👍

Thank you.

@BoneTone

This comment has been minimized.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
fixed issue has been addressed
Projects
None yet
Development

No branches or pull requests

5 participants