mirror of
https://github.com/floccusaddon/floccus.git
synced 2026-04-25 14:16:12 +03:00
[GH-ISSUE #973] High, constant CPU usage in Firefox #633
Labels
No labels
browser-specific
bug
correctness issues
enhancement
feature: Google Drive
feature: Linkwarden
feature: git
feature: nextcloud-bookmarks
feature: tabs
feature: webdav
help wanted
native-app
priority: high
priority: low
priority: medium
pull-request
question
question
stale
upstream
waiting for more information
wontfix
🙁 Not following issue template
No milestone
No project
No assignees
1 participant
Notifications
Due date
No due date set.
Dependencies
No dependencies set.
Reference
starred/floccus#633
Loading…
Add table
Add a link
Reference in a new issue
No description provided.
Delete branch "%!s()"
Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?
Originally created by @nirvdrum on GitHub (Sep 27, 2021).
Original GitHub issue: https://github.com/floccusaddon/floccus/issues/973
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)
Server
I use Fastmail as my WebDAV provider. I do not have any insights into what their deployment environment is.
Debug log
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.
@fazlerabbi37 commented on GitHub (Sep 30, 2021):
Can confirm the issue with Firefox 92 with Nextcloud.
@marcelklehr commented on GitHub (Oct 3, 2021):
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 commented on GitHub (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[bot] commented on GitHub (Oct 18, 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.
@nirvdrum commented on GitHub (Oct 18, 2021):
Ahh, good ol' stalebot.
@marcelklehr commented on GitHub (Oct 18, 2021):
Here's how you can debug:
Firefox
about:debuggingThis firefoxinspectbutton next to floccus entrysync nowfor the account of your choice.Chrome
chrome://extensionsDeveloper modedist/html/background.htmlbutton in floccus' entry next to "Inspect views: "sync nowfor the account of your choice@stale[bot] commented on GitHub (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.
@fazlerabbi37 commented on GitHub (Nov 6, 2021):
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[bot] commented on GitHub (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.
@didierm commented on GitHub (Nov 23, 2021):
Issue confirmed with :
@didierm commented on GitHub (Nov 23, 2021):
@didierm commented on GitHub (Nov 23, 2021):
Some more information :
In the above described cases, the commonly observed behaviour is :
For testing purposes, I :
With the new Firefox profile, the behaviour is slightly different :
@marcelklehr commented on GitHub (Nov 24, 2021):
Investigating this, I found that the indeterminate loading bar animation at the top of a syncing account card causes a huge CPU load.
I couldn't reproduce this, so far, but will investigate further.
@didierm commented on GitHub (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 commented on GitHub (Nov 24, 2021):
How do you know that the sync is successful or even done, if the UI still says loading?
@didierm commented on GitHub (Nov 24, 2021):
By examing the Apache/httpd (Nextcloud) access logs :
@marcelklehr commented on GitHub (Nov 24, 2021):
This only means that the current server state was fetched, not that sync is finished.
@didierm commented on GitHub (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)
Start browser
open Floccus
click [pull sync once]
@marcelklehr commented on GitHub (Nov 24, 2021):
@didierm In this case, it would be interesting to know what floccus is stuck on, ideally by debugging: https://github.com/floccusaddon/floccus/issues/973#issuecomment-945893817
@didierm commented on GitHub (Nov 24, 2021):
I cleared all bookmarks in the Firefox test profile ;
At 14:42 CET (13:42Z) I reinitialized a Floccus .xbel pull sync (approx. 3000 bookmarks) :
-rw-r--r-- 1 apache apache 42 Nov 24 14:42 bookmarks.xbel.lockAt 16:44 CET, still high CPU usage :
...
The above debug log is only an extract (visible messages in the 15:05-16:52 debug log = ~ 57000 messages).
Many bookmarks seem to be constantly reordered, although not at the same rate :
e.g. in the debug log between 15:05 and 16:52, one bookmark/URL is 442 times present, another bookmark/URL 127 times.
@didierm commented on GitHub (Nov 24, 2021):
Sync completed at 18:21 CET (elapsed time since sync start : 3h 40'), with CPU usage dropping to normal level.
@didierm commented on GitHub (Nov 25, 2021):
places.sqlite-walhas grown to approx. 8.5 GB) ;@marcelklehr commented on GitHub (Nov 25, 2021):
Woah. Something's going really wrong here :/
@marcelklehr commented on GitHub (Nov 25, 2021):
Can you submit a complete log of this to https://cloud.marcelklehr.de/s/PCi3iLWrzdMZSmw ?
@didierm commented on GitHub (Nov 25, 2021):
Thought so ... Could be the size of my bookmarks collection (?), but there is no info about the bookmarks size of the other reporters.
I could also start dissecting the bookmarks file (by means of HTML export, dissecting, and subsequent import), but not sure whether this effort is worthwhile with cross-reference experience of the other reporters.
@didierm commented on GitHub (Nov 25, 2021):
Sure, I am not opposed to that (no debugging without logs), but :
https://user:password@occurances, unless there is a regexp for replacing all http(s)://... with e.g.{url-obfuscated};@didierm commented on GitHub (Nov 25, 2021):
@mnalis commented on GitHub (Nov 25, 2021):
@didierm perhaps you can use perl oneliner I wrote in https://github.com/floccusaddon/floccus/issues/912#issuecomment-881459667 to do most of the anonymizing. You would still need to sanity-check that nothing important leaked, but it should do vast majority of the work.
@fazlerabbi37 commented on GitHub (Nov 26, 2021):
just an idea: would be nice to see in integrated with floccus for sending quick logs.
@marcelklehr commented on GitHub (Dec 6, 2021):
This should be fixed in the latest release now, at least.
@stale[bot] commented on GitHub (Dec 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.
@didierm commented on GitHub (Dec 21, 2021):
Any suggestions for capturing the entire log ?
(Firefox : menu > Tools > Browser Tools > Web Developer Tools > Console)
@fazlerabbi37 commented on GitHub (Dec 21, 2021):
unfortunately, the problem still persist for me in 4.8.7 😞
@didli commented on GitHub (Dec 31, 2021):
Issue confirmed for me too. It is especially noticeable with push sync (but happens anyway with the other modes as well).
Worked just fine before firefox 95.0.2 (fedora 35).
Inspector is not throwing that much errors. This one below appears more than once, while still working in the end :
@stale[bot] commented on GitHub (Jan 15, 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.
@didierm commented on GitHub (Jan 15, 2022):
ping
@mnalis commented on GitHub (Jan 25, 2022):
ref: https://github.com/floccusaddon/floccus/issues/1007#event-5944440732
@stale[bot] commented on GitHub (Feb 8, 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.
@marcelklehr commented on GitHub (Feb 15, 2022):
The latest release of floccus now allows always downloading the debug logs from the account settings and also includes anonymized logs.
@stale[bot] commented on GitHub (Mar 1, 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.
@marcelklehr commented on GitHub (Mar 1, 2022):
@didierm Floccus has log redaction built-in now. Go to settings scroll down to dangerous actions and click on "download anonymized logs"
@didierm commented on GitHub (Mar 1, 2022):
Thank you ; will try again in the near future (bit swamped right now).
@cracket commented on GitHub (Mar 12, 2022):
small diagnostics hint if you don't know where to start:
$ MOZ_LOG=timestamp,mozStorage:5 firefox
grep lines with mozStorage #x and see what's is messing your browser, in my case it was small query
'/* 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'
In my case of slow hardware such query takes 50 seconds to be run
quick googling suggests that similar queries are part of FF UrlBarProviderAutofill
https://hg.mozilla.org/mozilla-central/rev/77d3548f6c1ba333ef3ab9cf3ff6186aafa8970d
but I need to read and understand what is happening there
Hope this explains your case but I'm not sure how this is related to floccus when both browser and synchronization are idle.
@marcelklehr commented on GitHub (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 commented on GitHub (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 commented on GitHub (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:
I'm surprised by still huge size of favicons, but I assume it should not impact synchronization queries
@stale[bot] commented on GitHub (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.
@didierm commented on GitHub (Apr 6, 2022):
ping
@marcelklehr commented on GitHub (Apr 6, 2022):
@cracket Thanks for sharing these, should be quite useful in tackling this!
@marcelklehr commented on GitHub (Apr 13, 2022):
Can you try the latest release and see if that fixes things?
@marcelklehr commented on GitHub (Apr 19, 2022):
Ping @cracket
@stale[bot] commented on GitHub (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.
@nirvdrum commented on GitHub (May 5, 2022):
We should probably keep this open until the issue is confirmed to be fixed.
@marcelklehr commented on GitHub (May 7, 2022):
@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 commented on GitHub (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:
@marcelklehr commented on GitHub (May 16, 2022):
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[bot] commented on GitHub (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.
@github-actions[bot] commented on GitHub (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.