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

High, constant CPU usage in Firefox #973

Closed
nirvdrum opened this issue Sep 27, 2021 · 58 comments
Closed

High, constant CPU usage in Firefox #973

nirvdrum opened this issue Sep 27, 2021 · 58 comments

Comments

@nirvdrum
Copy link

nirvdrum commented Sep 27, 2021

Describe the bug

Ever since upgrading from Firefox 91 to 92, I've noticed very high CPU usage of the browser. I ran in troubleshooting mode and the browser ran fine, indicating it was likely a problem with an add-on. I've since then gone through every add-on I have installed and enabled them one by one, isolating the problematic add-on. Floccus appears to be the source of the issue. I did verify disabling the extension reduces CPU consumption (requiring a browser restart, unfortunately). Enabling the add-on immediately jumps the CPU to 100 - 250%.

It may be that the Firefox upgrade was incidental and the issue was actually due to a Floccus upgrade. I have Floccus automatically update, so I don't know what I may have been running previously.

To Reproduce

Steps to reproduce the behavior:

The CPU usage climbs immediately after enabling the add-on. I use WebDAV synchronization. The Floccus panel shows that it is constantly trying to synchronize, with a "normal sync" process.

Expected behavior

I'd expect Floccus to perform synchronization in the background with bursty CPU usage. Instead, it keeps at least one hardware thread fully utilized.

Desktop

(please complete the following information)

  • OS: Ubuntu 21.04
  • Browser: Firefox
  • Browser: 92.0
  • Floccus version: 4.8.1
  • Floccus sync method: WebDAV

Server

I use Fastmail as my WebDAV provider. I do not have any insights into what their deployment environment is.

Debug log

It is often useful to provide a debug log file along with the issue. You can obtain a debug log of the most recent sync runs by clicking 'Debug log' in the bottom right corner of the floccus panel in your browser.

Note: As your debug log usually contains large parts of your bookmark data, instead of attaching it publicly to the issue here, I recommend uploading it privately at the following URL https://cloud.marcelklehr.de/s/PCi3iLWrzdMZSmw

  • [] Debug log provided

Unfortunately, I don't see the the link to download the debug log. My lower-right corner is a link to "Secure your Credentials". I've looked for it on the add-on preferences page, but can't see anything there either.

Additional context

The add-on is unresponsive when clicking the "Cancel Sync" button.

@nirvdrum nirvdrum added the bug label Sep 27, 2021
@fazlerabbi37
Copy link

Can confirm the issue with Firefox 92 with Nextcloud.

@marcelklehr
Copy link
Member

Floccus may be caught in an infinite loop :/ Does it help to disable the addon and re-enable it? Triggering a sync from scratch in the settings (with backup beforehand)?

@nirvdrum
Copy link
Author

nirvdrum commented Oct 3, 2021

Disabling and re-enabling doesn't help. That was how I was able to narrow down the add-on as being the source of the problem, unfortunately. I haven't tried blowing my settings or anything like that. If there's a way for me to help you debug it, please let me know. I don't have experience with web extensions, but I have general development experience, including writing NPAPI plugins.

@stale

This comment has been minimized.

@stale stale bot added the stale label Oct 18, 2021
@nirvdrum
Copy link
Author

Ahh, good ol' stalebot.

@marcelklehr
Copy link
Member

Here's how you can debug:

Firefox

  • Go to about:debugging
  • Go to This firefox
  • click on inspect button next to floccus entry
  • trigger a sync by clicking on sync now for the account of your choice.
  • go back to the inspector window and inspect the logs

Chrome

  • Go to chrome://extensions
  • enable Developer mode
  • click on dist/html/background.html button in floccus' entry next to "Inspect views: "
  • trigger a sync by clicking on sync now for the account of your choice
  • go back to the inspector window and inspect the logs

@stale stale bot removed the stale label Oct 18, 2021
@stale
Copy link

stale bot commented Nov 1, 2021

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

@stale stale bot added the stale label Nov 1, 2021
@fazlerabbi37
Copy link

fazlerabbi37 commented Nov 6, 2021

No message found with name LabelFunddevelopment in locale en. Using default locale 'en' options.js:9:51204
No message found with name LabelSecurecredentials in locale en. Using default locale 'en' options.js:9:51204
No message found with name LabelUnlock in locale en. Using default locale 'en' options.js:9:51204
No message found with name LabelKey in locale en. Using default locale 'en' options.js:9:51204
No message found with name LabelUnlock in locale en. Using default locale 'en' options.js:9:51204
[Vuetify] [UPGRADE] 'v-content' is deprecated, use 'v-main' instead.

found in

---> <VMain>
       <VApp>
         <App> at src/ui/App.vue
           <Root> options.js:7:65872
Error: Cannot find module './en-US.json'
    r moz-extension://7b76d6f4-649e-4a66-bc0d-445482b74de5/dist/js/options.js:17
    a moz-extension://7b76d6f4-649e-4a66-bc0d-445482b74de5/dist/js/options.js:17
    load moz-extension://7b76d6f4-649e-4a66-bc0d-445482b74de5/dist/js/options.js:9
    promise callback*m</t.prototype.load/</< moz-extension://7b76d6f4-649e-4a66-bc0d-445482b74de5/dist/js/options.js:9
    p moz-extension://7b76d6f4-649e-4a66-bc0d-445482b74de5/dist/js/options.js:9
    p moz-extension://7b76d6f4-649e-4a66-bc0d-445482b74de5/dist/js/options.js:9
    o moz-extension://7b76d6f4-649e-4a66-bc0d-445482b74de5/dist/js/options.js:9
    o moz-extension://7b76d6f4-649e-4a66-bc0d-445482b74de5/dist/js/options.js:9
    load moz-extension://7b76d6f4-649e-4a66-bc0d-445482b74de5/dist/js/options.js:9
    <anonymous> moz-extension://7b76d6f4-649e-4a66-bc0d-445482b74de5/dist/js/options.js:57
    <anonymous> moz-extension://7b76d6f4-649e-4a66-bc0d-445482b74de5/dist/js/options.js:57
    a moz-extension://7b76d6f4-649e-4a66-bc0d-445482b74de5/dist/js/options.js:1
    <anonymous> moz-extension://7b76d6f4-649e-4a66-bc0d-445482b74de5/dist/js/options.js:57
    a moz-extension://7b76d6f4-649e-4a66-bc0d-445482b74de5/dist/js/options.js:1
    <anonymous> moz-extension://7b76d6f4-649e-4a66-bc0d-445482b74de5/dist/js/options.js:1
    <anonymous> moz-extension://7b76d6f4-649e-4a66-bc0d-445482b74de5/dist/js/options.js:1
options.js:9:50365
Loading failed for the <script> with source “moz-extension://7b76d6f4-649e-4a66-bc0d-445482b74de5/dist/js/7.js”. options.html:1:1

I get this in the console. Hope it helps.

Just keeping the addon enable, consumes a lot of RAM, making the whole system unusable.

@stale
Copy link

stale bot commented Nov 20, 2021

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

@stale stale bot added the stale label Nov 20, 2021
@didierm
Copy link

didierm commented Nov 23, 2021

Issue confirmed with :

  • Firefox 94.0.2 (Fedora 35) , floccus 4.8.4 and Nextcloud WebDAV .xbel storage
  • all other extensions disabled.

@stale stale bot removed the stale label Nov 23, 2021
@didierm
Copy link

didierm commented Nov 23, 2021

11:01:27.171 Syncing failed with E027: Sync process was interrupted background-script.js:2:230274
    sync moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/background-script.js:2
    s moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/background-script.js:2
    s moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/background-script.js:2
    i moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/background-script.js:2
    (Async: promise callback)
    u moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/background-script.js:2
    s moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/background-script.js:2
    (Async: promise callback)
    u moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/background-script.js:2
    i moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/background-script.js:2
    (Async: promise callback)
    u moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/background-script.js:2
    i moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/background-script.js:2
    (Async: promise callback)
    u moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/background-script.js:2
    s moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/background-script.js:2
    s moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/background-script.js:2
    sync moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/background-script.js:2
    syncAccount moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/background-script.js:2
    scheduleSync moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/background-script.js:2
    add moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/background-script.js:2
    _tryToStartAnother moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/background-script.js:2
    add moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/background-script.js:2
    add moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/background-script.js:2
    scheduleSync moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/background-script.js:2
    checkSync moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/background-script.js:2
    setEnabled moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/background-script.js:2
    (Async: setTimeout handler)
    setEnabled moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/background-script.js:2
    <anonymous> moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/background-script.js:2
    (Async: promise callback)
    <anonymous> moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/background-script.js:2
    <anonymous> moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/background-script.js:2
    <anonymous> moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/background-script.js:2
    <anonymous> moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/background-script.js:2

11:01:27.174 Uncaught (in promise) TypeError: this.syncProcess is undefined
    cancelSync moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/background-script.js:2
    s moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/background-script.js:2
    s moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/background-script.js:2
    s moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/background-script.js:2
    s moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/background-script.js:2
    cancelSync moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/background-script.js:2
    cancelSync moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/background-script.js:2
    CANCEL_SYNC moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    h moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    dispatch moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    dispatch moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    onCancelSync moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    Ut moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    e moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    Ut moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    $emit moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    click moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    Ut moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    e moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    _wrapper moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    bn moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    oi moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    _n moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    h moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    m moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    ca moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    _update moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    n moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    get moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    ge moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    mount moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    $mount moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    init moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    m moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    m moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    g moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    m moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    g moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    m moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    g moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    m moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    g moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    m moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    g moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    m moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    g moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    m moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    ca moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    _update moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
    n moz-extension://2c2bbf32-149c-49a3-8ef1-1f745c224783/dist/js/options.js:2
background-script.js:2:231019

@didierm
Copy link

didierm commented Nov 23, 2021

Some more information :

  • In the above described cases, the commonly observed behaviour is :

    • a constant high CPU usage as soon as the browser is started ;
    • CPU usage does not drop when disabling the extension ;
    • CPU usage returns to normal when the browser is restarted (with the extension disabled) ;
    • reenabling the extension repeats this pattern.
  • For testing purposes, I :

    • exported the floccus account (NextCloud WebDAV sync) and the (approx. 3000) bookmarks ;
    • imported both the bookmarks and the flocus account in a new Firefox (v94) profile.

With the new Firefox profile, the behaviour is slightly different :

  • CPU usage is normal, until :
  • the floccus icon ("Open Floccus options") is clicked, revealing the sync process.
    • At this point, CPU usage jumps to 100%
  • Hiding the sync process (by e.g. clicking outside the floccus sync popup window) drops CPU usage to normal levels.
  • After a successful sync ( [Auto-sync] disabled, [Pull Sync once] button selected),
    • CPU usage is 100% ;
    • the "Syncing" icon is locked in an infinite loop ;
    • status = "Synchronization in progress."
    • the [Cancel Sync] button is responsive, but does not cancel the synchronization.
  • No error messages in the "Console" debugging window.

@marcelklehr
Copy link
Member

  • the floccus icon ("Open Floccus options") is clicked, revealing the sync process.
    • At this point, CPU usage jumps to 100%
  • Hiding the sync process (by e.g. clicking outside the floccus sync popup window) drops CPU usage to normal levels.

Investigating this, I found that the indeterminate loading bar animation at the top of a syncing account card causes a huge CPU load.

After a successful sync ( [Auto-sync] disabled, [Pull Sync once] button
CPU usage is 100% ;

I couldn't reproduce this, so far, but will investigate further.

@didierm
Copy link

didierm commented Nov 24, 2021

Perhaps providing a test version without the loading bar animation (and the sync animation ?) may shed some proverbial light whether there is a correlation with the other above reported CPU usage issues ?

@marcelklehr
Copy link
Member

After a successful sync

How do you know that the sync is successful or even done, if the UI still says loading?

marcelklehr added a commit that referenced this issue Nov 24, 2021
@didierm
Copy link

didierm commented Nov 24, 2021

How do you know that the sync is successful or even done, if the UI still says loading?

By examing the Apache/httpd (Nextcloud) access logs :

"GET /pub/remote.php/webdav/{obfuscated}/bookmarks.xbel.lock HTTP/1.1" 404 11415
"PUT /pub/remote.php/webdav/{obfuscated}/bookmarks.xbel.lock HTTP/1.1" 201 -
"GET /pub/remote.php/webdav/{obfuscated}/bookmarks.xbel HTTP/1.1" 200 6982662

@marcelklehr
Copy link
Member

"GET /pub/remote.php/webdav/{obfuscated}/bookmarks.xbel

This only means that the current server state was fetched, not that sync is finished.

@didierm
Copy link

didierm commented Nov 24, 2021

Indeed, it seems the sync process does not finish (lockfile is not removed) :
(lockfile creation/removal is verified by examining the filesystem directory of the floccus NextCloud/WebDAV folder location)

# ll
total 6824
-rw-r--r-- 1 apache apache 6982662 Nov 23 00:05 bookmarks.xbel
-rw-r--r-- 1 apache apache      42 Nov 24 13:41 bookmarks.xbel.lock
  • Start browser

  • open Floccus

  • click [pull sync once]

[24/Nov/2021:13:47:24 +0100] "GET /pub/remote.php/webdav/{obfuscated}/bookmarks.xbel.lock HTTP/1.1" 200 42
...
[24/Nov/2021:13:47:38 +0100] "GET /pub/remote.php/webdav/{obfuscated}/bookmarks.xbel.lock HTTP/1.1" 200 42
[24/Nov/2021:13:47:42 +0100] "GET /pub/remote.php/webdav/{obfuscated}/bookmarks.xbel.lock HTTP/1.1" 200 42
  • click [cancel sync]
[24/Nov/2021:13:47:46 +0100] "DELETE /pub/remote.php/webdav/{obfuscated}/bookmarks.xbel.lock HTTP/1.1" 204 -
# ll
total 6820
-rw-r--r-- 1 apache apache 6982662 Nov 23 00:05 bookmarks.xbel
  • click [pull sync once]
192.168.2.200 - didier [24/Nov/2021:13:51:07 +0100] "GET /pub/remote.php/webdav/{obfuscated}/bookmarks.xbel.lock HTTP/1.1" 404 11415
192.168.2.200 - didier [24/Nov/2021:13:51:08 +0100] "PUT /pub/remote.php/webdav/{obfuscated}/bookmarks.xbel.lock HTTP/1.1" 201 -
192.168.2.200 - didier [24/Nov/2021:13:51:08 +0100] "GET /pub/remote.php/webdav/{obfuscated}/bookmarks.xbel HTTP/1.1" 200 6982662
# ll
total 6824
-rw-r--r-- 1 apache apache 6982662 Nov 23 00:05 bookmarks.xbel
-rw-r--r-- 1 apache apache      42 Nov 24 13:51 bookmarks.xbel.lock

marcelklehr added a commit that referenced this issue Mar 16, 2022
@marcelklehr
Copy link
Member

marcelklehr commented Mar 16, 2022

I may at long last have found a reason for this. Or at least identified one performance leak. Let's see if the next release improves the situation here.

@cracket
Copy link

cracket commented Mar 22, 2022

I have bad news - upgraded to 4.12.0 and checked if problem still occurs.
It does. I have run firefox with --safe-mode - all my mozStorage queries last 1msec.
I have started ff with all my plugins disabled - same result ( 1-3 msec)

As soon as I enable floccus plugin (4.12.0 with auto-sync turned off) - trace log is getting bombed by huge queries (see log below).

I'm not running any sync, floccus debug logs have no new entries.
As a result 1 core of my CPU is constantly busy due to floccus queries.

( plugin disabled)
2022-03-22 19:57:07.278065 UTC - [Parent 3832: IndexedDB #5]: D/mozStorage TRACE_TIME on 8ce9c9c0: 1ms
2022-03-22 19:57:07.278133 UTC - [Parent 3832: IndexedDB #6]: D/mozStorage TRACE_TIME on 87312840: 1ms
2022-03-22 19:57:27.888246 UTC - [Parent 3832: Main Thread]: D/mozStorage TRACE_TIME on 8c02a060: 1ms
2022-03-22 19:57:27.892388 UTC - [Parent 3832: Main Thread]: D/mozStorage TRACE_TIME on 8c02a060: 2ms
2022-03-22 19:57:27.912102 UTC - [Parent 3832: mozStorage #1]: D/mozStorage TRACE_TIME on 8c02a060: 1ms
2022-03-22 19:57:27.924366 UTC - [Parent 3832: mozStorage #1]: D/mozStorage TRACE_TIME on 8c02a060: 1ms
2022-03-22 19:57:32.603123 UTC - [Parent 3832: Main Thread]: D/mozStorage TRACE_TIME on 8c02a060: 1ms
2022-03-22 19:57:32.606889 UTC - [Parent 3832: Main Thread]: D/mozStorage TRACE_TIME on 8c02a060: 2ms
2022-03-22 19:57:32.626164 UTC - [Parent 3832: mozStorage #1]: D/mozStorage TRACE_TIME on 8c02a060: 1ms
2022-03-22 19:57:32.628137 UTC - [Parent 3832: mozStorage #1]: D/mozStorage TRACE_TIME on 8c02a060: 1ms
2022-03-22 19:57:32.630022 UTC - [Parent 3832: mozStorage #1]: D/mozStorage TRACE_TIME on 8c02a060: 1ms
2022-03-22 19:57:32.633231 UTC - [Parent 3832: mozStorage #1]: D/mozStorage TRACE_TIME on 8c02a060: 1ms
2022-03-22 19:58:32.615224 UTC - [Parent 3832: mozStorage #2]: D/mozStorage TRACE_TIME on 8c02a420: 1ms
2022-03-22 19:58:34.951146 UTC - [Parent 3832: mozStorage #2]: D/mozStorage TRACE_TIME on 8c02a420: 1ms
2022-03-22 19:58:34.954045 UTC - [Parent 3832: mozStorage #1]: D/mozStorage TRACE_TIME on 8c02a060: 1ms
2022-03-22 19:58:34.968110 UTC - [Parent 3832: mozStorage #1]: D/mozStorage TRACE_TIME on 8c02a060: 1ms
2022-03-22 19:58:41.660079 UTC - [Parent 3832: mozStorage #1]: D/mozStorage TRACE_TIME on 8c02a060: 1ms
2022-03-22 19:58:42.478040 UTC - [Parent 3832: mozStorage #4]: D/mozStorage TRACE_TIME on 87312e80: 1ms
2022-03-22 19:58:42.479025 UTC - [Parent 3832: mozStorage #4]: D/mozStorage TRACE_TIME on 87312e80: 1ms

( plugin enabled from firefox UI somewhere here)

2022-03-22 19:59:26.367696 UTC - [Parent 3832: Permission]: D/mozStorage TRACE_TIME on 9ee1d9c0: 20ms
2022-03-22 19:59:26.377832 UTC - [Parent 3832: Permission]: D/mozStorage TRACE_TIME on 9ee1d9c0: 10ms
2022-03-22 19:59:26.397338 UTC - [Parent 3832: Permission]: D/mozStorage TRACE_TIME on 9ee1d9c0: 19ms
2022-03-22 19:59:26.765038 UTC - [Parent 3832: QuotaManager IO]: D/mozStorage TRACE_TIME on 80606e80: 1ms
2022-03-22 19:59:26.775010 UTC - [Parent 3832: IndexedDB #8]: D/mozStorage TRACE_TIME on 80607240: 1ms
2022-03-22 19:59:26.776056 UTC - [Parent 3832: IndexedDB #8]: D/mozStorage TRACE_TIME on 80607240: 1ms
2022-03-22 19:59:28.036034 UTC - [Parent 3832: mozStorage #4]: D/mozStorage TRACE_TIME on 87312e80: 1ms
2022-03-22 19:59:29.766041 UTC - [Parent 3832: IndexedDB #8]: D/mozStorage TRACE_TIME on 80607240: 1ms
2022-03-22 19:59:33.819101 UTC - [Parent 3832: IndexedDB #8]: D/mozStorage TRACE_TIME on 80607240: 1ms
2022-03-22 19:59:53.309107 UTC - [Parent 3832: QuotaManager IO]: D/mozStorage TRACE_TIME on 7f115ca0: 1ms
2022-03-22 19:59:53.336190 UTC - [Parent 3832: mozStorage #4]: D/mozStorage TRACE_TIME on 87312e80: 1ms
2022-03-22 19:59:53.412294 UTC - [Parent 3832: mozStorage #1]: D/mozStorage TRACE_TIME on 8c02a060: 1ms
2022-03-22 19:59:53.415271 UTC - [Parent 3832: mozStorage #1]: D/mozStorage TRACE_TIME on 8c02a060: 1ms
2022-03-22 19:59:54.507044 UTC - [Parent 3832: mozStorage #1]: D/mozStorage TRACE_TIME on 8c02a060: 1ms
2022-03-22 19:59:54.516112 UTC - [Parent 3832: mozStorage #1]: D/mozStorage TRACE_TIME on 8c02a060: 1ms
2022-03-22 20:00:13.051655 UTC - [Parent 3832: mozStorage #2]: D/mozStorage TRACE_TIME on 8c02a420: 46231ms
2022-03-22 20:00:13.056107 UTC - [Parent 3832: mozStorage #1]: D/mozStorage TRACE_TIME on 8c02a060: 1ms
2022-03-22 20:00:37.774207 UTC - [Parent 3832: mozStorage #1]: D/mozStorage TRACE_TIME on 8c02a060: 1ms
2022-03-22 20:00:38.129075 UTC - [Parent 3832: QuotaManager IO]: D/mozStorage TRACE_TIME on 7cd6e660: 1ms
2022-03-22 20:00:38.150135 UTC - [Parent 3832: IndexedDB #8]: D/mozStorage TRACE_TIME on 806fc340: 1ms
2022-03-22 20:00:38.256090 UTC - [Parent 3832: mozStorage #1]: D/mozStorage TRACE_TIME on 8c02a060: 1ms
2022-03-22 20:00:38.338324 UTC - [Parent 3832: mozStorage #1]: D/mozStorage TRACE_TIME on 8c02a060: 1ms
2022-03-22 20:00:39.229389 UTC - [Parent 3832: mozStorage #1]: D/mozStorage TRACE_TIME on 8c02a060: 1ms
2022-03-22 20:00:59.525025 UTC - [Parent 3832: mozStorage #2]: D/mozStorage TRACE_TIME on 8c02a420: 46474ms
2022-03-22 20:01:26.751017 UTC - [Parent 3832: IndexedDB #9]: D/mozStorage TRACE_TIME on 806fdc40: 1ms
2022-03-22 20:01:44.795637 UTC - [Parent 3832: mozStorage #2]: D/mozStorage TRACE_TIME on 8c02a420: 45270ms
2022-03-22 20:02:02.430044 UTC - [Parent 3832: IndexedDB #9]: D/mozStorage TRACE_TIME on 806fc7a0: 1ms
2022-03-22 20:02:02.433272 UTC - [Parent 3832: IndexedDB #9]: D/mozStorage TRACE_TIME on 806fc7a0: 1ms
2022-03-22 20:02:02.625379 UTC - [Parent 3832: IndexedDB #9]: D/mozStorage TRACE_TIME on 806fc7a0: 1ms
2022-03-22 20:02:26.750027 UTC - [Parent 3832: IndexedDB #9]: D/mozStorage TRACE_TIME on 97cfb1a0: 1ms
2022-03-22 20:02:26.752135 UTC - [Parent 3832: IndexedDB #9]: D/mozStorage TRACE_TIME on 97cfb1a0: 1ms
2022-03-22 20:02:30.359737 UTC - [Parent 3832: mozStorage #2]: D/mozStorage TRACE_TIME on 8c02a420: 45564ms
2022-03-22 20:03:15.898935 UTC - [Parent 3832: mozStorage #2]: D/mozStorage TRACE_TIME on 8c02a420: 45538ms
2022-03-22 20:03:26.751017 UTC - [Parent 3832: IndexedDB #10]: D/mozStorage TRACE_TIME on 7f115b60: 1ms
2022-03-22 20:03:26.753045 UTC - [Parent 3832: IndexedDB #10]: D/mozStorage TRACE_TIME on 7f115b60: 1ms
2022-03-22 20:03:28.776026 UTC - [Parent 3832: IndexedDB #10]: D/mozStorage TRACE_TIME on 7f115b60: 1ms
2022-03-22 20:04:01.202003 UTC - [Parent 3832: mozStorage #2]: D/mozStorage TRACE_TIME on 8c02a420: 45302ms

@cracket
Copy link

cracket commented Mar 22, 2022

one more remark related to my previous comment - I have cleared my whole browsing history so only bookmarks managed by floccus are kept within profile:

-rw-r--r--  1 linux linux 15728640 mar 22 21:07 places.sqlite
-rw-r--r--  1 linux linux 12091392 mar 22 20:53 favicons.sqlite
-rw-r--r--  1 linux linux  5574672 mar 22 21:07 places.sqlite-wal
-rw-r--r--  1 linux linux  4328576 lut 12 19:38 storage-sync-v2.sqlite-wal
-rw-r--r--  1 linux linux  4128768 mar 22 21:07 webappsstore.sqlite
-rw-r--r--  1 linux linux  1016584 mar 22 21:07 favicons.sqlite-wal
-rw-r--r--  1 linux linux   557496 mar 22 21:17 cookies.sqlite-wal
-rw-r--r--  1 linux linux   524288 mar 22 21:17 cookies.sqlite

I'm surprised by still huge size of favicons, but I assume it should not impact synchronization queries

@stale
Copy link

stale bot commented Apr 6, 2022

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

@stale stale bot added the stale label Apr 6, 2022
@didierm
Copy link

didierm commented Apr 6, 2022

ping

@marcelklehr
Copy link
Member

@cracket Thanks for sharing these, should be quite useful in tackling this!

@marcelklehr
Copy link
Member

Can you try the latest release and see if that fixes things?

@marcelklehr
Copy link
Member

Ping @cracket

@stale
Copy link

stale bot commented May 4, 2022

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

@stale stale bot added the stale label May 4, 2022
@nirvdrum
Copy link
Author

nirvdrum commented May 5, 2022

We should probably keep this open until the issue is confirmed to be fixed.

@stale stale bot removed the stale label May 5, 2022
@marcelklehr
Copy link
Member

marcelklehr commented May 7, 2022

Can you try the latest release and see if that fixes things?

@nirvdrum I'm happy to collaborate and troubleshoot and work on fixes, but I need feedback. If nobody tests the latest release I'm closing the issue.

@cracket
Copy link

cracket commented May 9, 2022

Sorry for delay, but I didnt have access to slow hardware.

I've checked version 4.13.1 and there are some good news - namely there were only 5 huge queries executed taking 45 secs each. After that - there are no huge queries looping for ever while firefox is idle. I have no proof these queries origin from flooccus and not firefox itself, but I attach some logs for you:

2022-05-09 15:33:01.174300 UTC - [Parent 2795: Cookie]: D/mozStorage Opening connection to 'cookies.sqlite' (a3d03700)
2022-05-09 15:33:06.872151 UTC - [Parent 2795: mozStorage #2]: D/mozStorage TRACE_STMT on 90c67740: '/* do not warn (bug no): cannot use an index */
       WITH RECURSIVE
       descendants(fk, level, type, id, guid, parent, parentGuid, position,
                   title, dateAdded, lastModified) AS (
         SELECT b1.fk, 0, b1.type, b1.id, b1.guid, b1.parent,
                (SELECT guid FROM moz_bookmarks WHERE id = b1.parent),
                b1.position, b1.title, b1.dateAdded, b1.lastModified
         FROM moz_bookmarks b1 WHERE b1.guid='root________'
         UNION ALL
         SELECT b2.fk, level + 1, b2.type, b2.id, b2.guid, b2.parent,
                descendants.guid, b2.position, b2.title, b2.dateAdded,
                b2.lastModified
         FROM moz_bookmarks b2
         JOIN descendants ON b2.parent = descendants.id AND b2.id <> 4)
       SELECT d.level, d.id, d.guid, d.parent, d.parentGuid, d.type,
              d.position AS [index], IFNULL(d.title, '') AS title, d.dateAdded,
              d.lastModified, h.url, (SELECT icon_url FROM moz_icons i
                      JOIN moz_icons_to_pages ON icon_id = i.id
                      JOIN moz_pages_w_icons pi ON page_id = pi.id
                      WHERE pi.page_url_hash = hash(h.url) AND pi.page_url = h.url
                      ORDER BY width DESC LIMIT 1) AS iconuri,
              (SELECT GROUP_CONCAT(t.title, ',')
               FROM moz_bookmarks b2
               JOIN moz_bookmarks t ON t.id = +b2.parent AND t.parent = 4
               WHERE b2.fk = h.id
              ) AS tags,
              (SELECT a.conten	t FROM moz_annos a
               JOIN moz_anno_attributes n ON a.anno_attribute_id = n.id
               WHERE place_id = h.id AND n.name = 'URIProperties/characterSet'
              ) AS charset
       FROM descendants d
       LEFT JOIN moz_bookmarks b3 ON b3.id = d.parent
       LEFT JOIN moz_places h ON h.id = d.fk
       ORDER BY d.level, d.parent, d.position'
2022-05-09 15:33:52.436852 UTC - [Parent 2795: mozStorage #2]: D/mozStorage TRACE_TIME on 90c67740: 45564ms

2022-05-09 15:33:52.440815 UTC - [Parent 2795: mozStorage #2]: D/mozStorage TRACE_STMT on 90c67740: '/* do not warn (bug no): cannot use an index */
       WITH RECURSIVE
       descendants(fk, level, type, id, guid, parent, parentGuid, position,
                   title, dateAdded, lastModified) AS (
         SELECT b1.fk, 0, b1.type, b1.id, b1.guid, b1.parent,
                (SELECT guid FROM moz_bookmarks WHERE id = b1.parent),
                b1.position, b1.title, b1.dateAdded, b1.lastModified
         FROM moz_bookmarks b1 WHERE b1.guid='root________'
         UNION ALL
         SELECT b2.fk, level + 1, b2.type, b2.id, b2.guid, b2.parent,
                descendants.guid, b2.position, b2.title, b2.dateAdded,
                b2.lastModified
         FROM moz_bookmarks b2
         JOIN descendants ON b2.parent = descendants.id AND b2.id <> 4)
       SELECT d.level, d.id, d.guid, d.parent, d.parentGuid, d.type,
              d.position AS [index], IFNULL(d.title, '') AS title, d.dateAdded,
              d.lastModified, h.url, (SELECT icon_url FROM moz_icons i
                      JOIN moz_icons_to_pages ON icon_id = i.id
                      JOIN moz_pages_w_icons pi ON page_id = pi.id
                      WHERE pi.page_url_hash = hash(h.url) AND pi.page_url = h.url
                      ORDER BY width DESC LIMIT 1) AS iconuri,
              (SELECT GROUP_CONCAT(t.title, ',')
               FROM moz_bookmarks b2
               JOIN moz_bookmarks t ON t.id = +b2.parent AND t.parent = 4
               WHERE b2.fk = h.id
              ) AS tags,
              (SELECT a.content FROM moz_annos a
               JOIN moz_anno_attributes n ON a.anno_attribute_id = n.id
               WHERE place_id = h.id AND n.name = 'URIProperties/characterSet'
              ) AS charset
       FROM descendants d
       LEFT JOIN moz_bookmarks b3 ON b3.id = d.parent
       LEFT JOIN moz_places h ON h.id = d.fk
       ORDER BY d.level, d.parent, d.position'
2022-05-09 15:34:38.760232 UTC - [Parent 2795: mozStorage #2]: D/mozStorage TRACE_TIME on 90c67740: 46320ms

2022-05-09 15:34:38.760557 UTC - [Parent 2795: mozStorage #2]: D/mozStorage TRACE_STMT on 90c67740: '/* do not warn (bug no): cannot use an index */
       WITH RECURSIVE
       descendants(fk, level, type, id, guid, parent, parentGuid, position,
                   title, dateAdded, lastModified) AS (
         SELECT b1.fk, 0, b1.type, b1.id, b1.guid, b1.parent,
                (SELECT guid FROM moz_bookmarks WHERE id = b1.parent),
                b1.position, b1.title, b1.dateAdded, b1.lastModified
         FROM moz_bookmarks b1 WHERE b1.guid='root________'
         UNION ALL
         SELECT b2.fk, level + 1, b2.type, b2.id, b2.guid, b2.parent,
                descendants.guid, b2.position, b2.title, b2.dateAdded,
                b2.lastModified
         FROM moz_bookmarks b2
         JOIN descendants ON b2.parent = descendants.id AND b2.id <> 4)
       SELECT d.level, d.id, d.guid, d.parent, d.parentGuid, d.type,
              d.position AS [index], IFNULL(d.title, '') AS title, d.dateAdded,
              d.lastModified, h.url, (SELECT icon_url FROM moz_icons i
                      JOIN moz_icons_to_pages ON icon_id = i.id
                      JOIN moz_pages_w_icons pi ON page_id = pi.id
                      WHERE pi.page_url_hash = hash(h.url) AND pi.page_url = h.url
                      ORDER BY width DESC LIMIT 1) AS iconuri,
              (SELECT GROUP_CONCAT(t.title, ',')
               FROM moz_bookmarks b2
               JOIN moz_bookmarks t ON t.id = +b2.parent AND t.parent = 4
               WHERE b2.fk = h.id
              ) AS tags,
              (SELECT a.content FROM moz_annos a
               JOIN moz_anno_attributes n ON a.anno_attribute_id = n.id
               WHERE place_id = h.id AND n.name = 'URIProperties/characterSet'
              ) AS charset
       FROM descendants d
       LEFT JOIN moz_bookmarks b3 ON b3.id = d.parent
       LEFT JOIN moz_places h ON h.id = d.fk
       ORDER BY d.level, d.parent, d.position'
2022-05-09 15:35:24.738786 UTC - [Parent 2795: mozStorage #2]: D/mozStorage TRACE_TIME on 90c67740: 45978ms

2022-05-09 15:35:24.739084 UTC - [Parent 2795: mozStorage #2]: D/mozStorage TRACE_STMT on 90c67740: '/* do not warn (bug no): cannot use an index */
       WITH RECURSIVE
       descendants(fk, level, type, id, guid, parent, parentGuid, position,
                   title, dateAdded, lastModified) AS (
         SELECT b1.fk, 0, b1.type, b1.id, b1.guid, b1.parent,
                (SELECT guid FROM moz_bookmarks WHERE id = b1.parent),
                b1.position, b1.title, b1.dateAdded, b1.lastModified
         FROM moz_bookmarks b1 WHERE b1.guid='root________'
         UNION ALL
         SELECT b2.fk, level + 1, b2.type, b2.id, b2.guid, b2.parent,
                descendants.guid, b2.position, b2.title, b2.dateAdded,
                b2.lastModified
         FROM moz_bookmarks b2
         JOIN descendants ON b2.parent = descendants.id AND b2.id <> 4)
       SELECT d.level, d.id, d.guid, d.parent, d.parentGuid, d.type,
              d.position AS [index], IFNULL(d.title, '') AS title, d.dateAdded,
              d.lastModified, h.url, (SELECT icon_url FROM moz_icons i
                      JOIN moz_icons_to_pages ON icon_id = i.id
                      JOIN moz_pages_w_icons pi ON page_id = pi.id
                      WHERE pi.page_url_hash = hash(h.url) AND pi.page_url = h.url
                      ORDER BY width DESC LIMIT 1) AS iconuri,
              (SELECT GROUP_CONCAT(t.title, ',')
               FROM moz_bookmarks b2
               JOIN moz_bookmarks t ON t.id = +b2.parent AND t.parent = 4
               WHERE b2.fk = h.id
              ) AS tags,
              (SELECT a.content FROM moz_annos a
               JOIN moz_anno_attributes n ON a.anno_attribute_id = n.id
               WHERE place_id = h.id AND n.name = 'URIProperties/characterSet'
              ) AS charset
       FROM descendants d
       LEFT JOIN moz_bookmarks b3 ON b3.id = d.parent
       LEFT JOIN moz_places h ON h.id = d.fk
       ORDER BY d.level, d.parent, d.position'
2022-05-09 15:36:10.968393 UTC - [Parent 2795: mozStorage #2]: D/mozStorage TRACE_TIME on 90c67740: 46229ms



2022-05-09 15:36:10.968703 UTC - [Parent 2795: mozStorage #2]: D/mozStorage TRACE_STMT on 90c67740: '/* do not warn (bug no): cannot use an index */
       WITH RECURSIVE
       descendants(fk, level, type, id, guid, parent, parentGuid, position,
                   title, dateAdded, lastModified) AS (
         SELECT b1.fk, 0, b1.type, b1.id, b1.guid, b1.parent,
                (SELECT guid FROM moz_bookmarks WHERE id = b1.parent),
                b1.position, b1.title, b1.dateAdded, b1.lastModified
         FROM moz_bookmarks b1 WHERE b1.guid='root________'
         UNION ALL
         SELECT b2.fk, level + 1, b2.type, b2.id, b2.guid, b2.parent,
                descendants.guid, b2.position, b2.title, b2.dateAdded,
                b2.lastModified
         FROM moz_bookmarks b2
         JOIN descendants ON b2.parent = descendants.id AND b2.id <> 4)
       SELECT d.level, d.id, d.guid, d.parent, d.parentGuid, d.type,
              d.position AS [index], IFNULL(d.title, '') AS title, d.dateAdded,
              d.lastModified, h.url, (SELECT icon_url FROM moz_icons i
                      JOIN moz_icons_to_pages ON icon_id = i.id
                      JOIN moz_pages_w_icons pi ON page_id = pi.id
                      WHERE pi.page_url_hash = hash(h.url) AND pi.page_url = h.url
                      ORDER BY width DESC LIMIT 1) AS iconuri,
              (SELECT GROUP_CONCAT(t.title, ',')
               FROM moz_bookmarks b2
               JOIN moz_bookmarks t ON t.id = +b2.parent AND t.parent = 4
               WHERE b2.fk = h.id
              ) AS tags,
              (SELECT a.content FROM moz_annos a
               JOIN moz_anno_attributes n ON a.anno_attribute_id = n.id
               WHERE place_id = h.id AND n.name = 'URIProperties/characterSet'
              ) AS charset
       FROM descendants d
       LEFT JOIN moz_bookmarks b3 ON b3.id = d.parent
       LEFT JOIN moz_places h ON h.id = d.fk
       ORDER BY d.level, d.parent, d.position'
2022-05-09 15:36:57.471020 UTC - [Parent 2795: mozStorage #2]: D/mozStorage TRACE_TIME on 90c67740: 46502ms

@marcelklehr
Copy link
Member

Nice, I have indeed added a cache for the bookmarks full tree query which should result in a fixed number of long running queries on startup and no long running queries during runtime of the browser as you report. This means we've finally found the performance sink! If there was a different way to find out the id of the root folder I'd use it, but as of yet, to my knowledge, there is not.

@stale
Copy link

stale bot commented May 30, 2022

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

@stale stale bot added the stale label May 30, 2022
@github-actions
Copy link

github-actions bot commented Jun 3, 2023

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.

@github-actions github-actions bot locked as resolved and limited conversation to collaborators Jun 3, 2023
@marcelklehr marcelklehr moved this to Done in Floccus May 19, 2024
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
Status: Done
Development

No branches or pull requests

7 participants