1694170 - Performance issue around the "convert" function

Status: NEW

(WebExtensions :: General, defect, P2)

Description

[Julien Wajsberg [:julienw]]

Today, I realized that my computer's fan were running a lot, and with about:processes I've seen that Firefox' main process was taking 100% of CPU.
So I started profiling, and this is the profile I got: https://share.firefox.dev/2NQ2ymQ
It looks like we spend a lot of time in the WebExt code.

The profile only keeps these tracks because there was nothing interesting in other tracks. Especially the WebExtensions thread had not one sample in it, which is indeed weird.

I didn't keep the list of extensions in this upload, but I can share it here:

    Web Compatibility Interventions
    WebCompat Reporter
    French Holiday Form Generator
    DoH Roll-Out
    NoCoffee
    ClearURLs
    eBay
    Close Tabs By Pattern
    No Coin - Block miners on the web!
    Zoom Scheduler
    Firefox DevTools ADB Extension
    Default
    Amazon.co.uk
    Tab Counter
    uBlock Origin
    DuckDuckGo
    Bing
    Form Autofill
    Wikipédia (fr)
    MyQOnly
    Qwant
    Intégration à GNOME Shell
    phab-test-policy
    Google
    phab-conventional-comments
    Firefox Screenshots
    Duplicate Tabs Closer

This is Nightly v87 from build 20210213095234 (which probably means this Firefox runs for ~9days, with moments where the computer was suspended).
Also for context I have ~1490 tabs open. So I understand that this might be a problem for some code that targets more normal users :-)

Comment 1

[Tomislav Jovanovic :zombie]

If I'm reading this profile correctly, just the StructuredCloneHolder constructor seems to be taking 6.4% of cpu, which implies this is working on a lot of data, potentially some huge data: URIs or something. With that assumption, having regex pattern matching take 3-4 times more time than just serializing the data doesn't seem unreasonable.

More than that, seem hard to understand what's exactly going on with so many extensions. If one or more extensions are calling tabs.getAll() often with 1000+ tabs, I wouldn't expect a profile much different from this.

Are you perhaps able to bisect which extension is the culprit, so that we might investigate closer?

Comment 2

[Julien Wajsberg [:julienw]]

It will be difficult to bisect, because the problem appears quite randomly after a long period of time.

I looked at the profile again. I first switched to the JavaScript view, and I see 2 very different parts:

• first part at the start, until ~1.3s => from the stack chart, it looks like we first have an "idle callback", we want to save the state and collect the tab information, and then we postMessage which spends a lot of time serializing with the structured clone writer. This code is probably owned by the session store folks, and possibly by the JS folks for the structured clone part.
• Second part after that => we see 7 times the same operations, so it's probably a good idea to zoom in on one of them. This part is the query operation seemingly calling convert on a lot of tabs. This is caused by an actor message in the first place.

Is it possible that the first part causes the second part? I mean, that the postMessage at the end of the first part triggers the message handler in the second part. If this is the case, I'd say that we could try to avoid the structured clone because we're in the same process.

Then I looked a bit closer at the code for convert following what the profile says. Especially I see in the profile that get isReaderMode seems to take a lot of time because of matchesHostPermission (which is called at other places too). So I've been curious :-)

Maybe there are some things that could be improved.
First, the implementation of get isInReaderMode [1].

  get isInReaderMode() {
    return this.url && this.url.startsWith(READER_MODE_PREFIX);
  }

Here we get this.url twice, which would be OK if this was just a normal property, but it's not [2]:

  get url() {
    if (this.hasTabPermission) {
      return this._url;
    }
  }

So at the very least we could get this.url only once in get isInReaderMode.
Also do we need the "permission-checking" code for isInReaderMode? If not we could use this._url instead of this.url.

But please read further too.

hasTabPermission itself is another getter:

  get hasTabPermission() {
    return (
      this.extension.hasPermission("tabs") ||
      this.hasActiveTabPermission ||
      this.matchesHostPermission
    );
  }

(note that hasTabPermission is called also directly by convert)

And matchesHostPermission is especially costly:

  get matchesHostPermission() {
    return this.extension.allowedOrigins.matches(this._uri);
  }

Is it possible to cache it? It's not clear to me what operations could invalidate the result: are _uri and allowedOrigins constants in a specific tab object, or can they change? My rough guess is that _uri can change, so we could memoize the last result using this value.

I see getting _url itself seems costly too:

  get _url() {
    return this.browser.currentURI.spec;
  }

But I'm not sure we can do something easily about it.
Focusing on this function in the profiler, then switching to "all stacks" it looks like we spend time allocating. It would be interesting to look closer at whether the allocations happens when getting currentURI or getting spec. My rough guess is that spec will always be the same for one currentURI so we could also try to memoize it in the same way (I mean: the last result only). But memoization itself can be costly, so profiling will be needed for sure.

Getting the sharingState looks costly too:

  get sharingState() {
    return this.window.gBrowser.getTabSharingState(this.nativeTab);
  }

But that one can probably change easily over time, so it doesn't seem a good idea to cache it.

[1] https://searchfox.org/mozilla-central/rev/e9eb869e90a8d717678c3f38bf75843e345729ab/browser/components/extensions/parent/ext-browser.js#901-903
[2] https://searchfox.org/mozilla-central/rev/e9eb869e90a8d717678c3f38bf75843e345729ab/toolkit/components/extensions/parent/ext-tabs-base.js#230-234

Then of course MatchPatternSet takes a lot of time. From the profile (focus on matches and switch to all stacks) it looks like we spend a lot of time creating uris, not really by the matching itself. But this looks like an old tradeoff (bug 1397536) that probably benefits the normal use cases.

Of course all this is amplified by the number of tabs. So I'd understand that you'd prefer to focus on more common use cases :-)

So, I hope this analysis helps!
I'm happy to spend some more time on the profiler UI with you, with this profile but also with other profiles, if you want to. We also have the Joy of Profiling matrix channel for any question.

Comment 3

[Julien Wajsberg [:julienw]]

I realized that even with my new computer / profile where I have "only" 100 tabs, I could see the query call in profiles. So I tried to disable the addons where I had doubts.

So now I think my specific problem comes from Tab Counter, possibly this line:
https://github.com/DaAwesomeP/tab-counter/blob/bb54fb3ec313673a53221bbffd760f8ae92fbaf5/src/background.js#L192

Comment 4

[Tomislav Jovanovic :zombie]

Thank you Julien for the detailed analysis, this looks like some good candidates for some easy optimizations.

That Tab Counter code looks to be querying all tabs on every (internal) extension message received, which is could probably be optimized by using tabs.onUpdated. Maybe worth reaching out to them.

Comment 5

[Julien Wajsberg [:julienw]]

They use tabs.onUpdated but also all of other events, which in turn calls:
https://github.com/DaAwesomeP/tab-counter/blob/bb54fb3ec313673a53221bbffd760f8ae92fbaf5/src/background.js#L38

They have an existing issue: https://github.com/DaAwesomeP/tab-counter/issues/33, I added a comment pointing to this bug.

Thanks!

Comment 6

[Oriol Brufau [:Oriol]]

Yeah, there is some wasted work because tab counter extensions only care about the number of tabs, but the converter provides all kinds of tab information that won't be used.

But this specific tab counter is not much well designed, calling browser.tabs.query({}) whenever the number of tabs change is clearly bad for performance. There are other tab counters which call it like every second, so it's bad even if you are not opening nor closing tabs.

That's why I had to wrote my own tab counter extension, existing ones were not good.

Comment 7

[BugBot [:suhaib / :marco]]

The Bugbug bot thinks this bug should belong to the 'DevTools::General' component, and is moving the bug to that component. Please revert this change in case you think the bot is wrong.