Closed Bug 1481030 Opened 7 years ago Closed 7 years ago

Firefox sync never finishes and uses 100% CPU

Categories

(Firefox :: Sync, defect)

Product:
Firefox
Component:
Sync
Version:
61 Branch
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED DUPLICATE of bug 1435007

People

(Reporter: jeenuv, Unassigned)

Details

User Agent: Mozilla/5.0 (X11; Linux x86_64; rv:61.0) Gecko/20100101 Firefox/61.0 Build ID: 20180704003137 Steps to reproduce: I'm raising this issue following a discussion thread in the support forum: https://support.mozilla.org/en-US/questions/1228298. TLDR: On a pristine system (XFCE on Linux, via. crouton on Chromebook), I setup Firefox sync. I already have sync working for other machines that I use Firefox on. Actual results: Sync on this particular system won't complete, and Firefox uses 100% of CPU. This is the initial output of sync: https://pastebin.mozilla.org/9091055. Then I cleaned up stale entries for sync machines, and logged in again. I noticed that as soon as I signed into sync, there was a balloon with "Activate" button on it, and it prompted me to click on it. I had clicked on it every time before, but skipped this time. I noticed that sync was already in progress even without clicking on it. With that, I saw the CPU usage coming down to something like 50%, and got these logs: https://paste.ubuntu.com/p/k8bX5JgRFN/ The logs indicate that there were problems regarding synchronizing history, but I verified history from the trouble shooting page.
Component: Untriaged → Sync
Thanks for reporting! (In reply to Jeenu from comment #0) > Sync on this particular system won't complete, and Firefox uses 100% of CPU. > This is the initial output of sync: https://pastebin.mozilla.org/9091055. In that log file, it appears you were in the process of disconnecting and reconnecting the account, causing the "A key bundle must be supplied to decrypt" errors. > Then I cleaned up stale entries for sync machines, and logged in again. I > noticed that as soon as I signed into sync, there was a balloon with > "Activate" button on it, and it prompted me to click on it. I'm not sure what balloon you are talking about here - Firefox doesn't really have anything you describe. It will show a notification telling you sync is connected and syncing, but it has no "activate" button. A screen-shot of this would be handy. > I had clicked on > it every time before, but skipped this time. I noticed that sync was already > in progress even without clicking on it. With that, I saw the CPU usage > coming down to something like 50%, and got these logs: > https://paste.ubuntu.com/p/k8bX5JgRFN/ That second log file is strange - it shows history is being back-filled, which works OK until we hit: > 1533443917993 Sync.Collection WARN GET request to https://sync-546-us-west-2.sync.services.mozilla.com/1.5/88802411/storage/history?full=1&sort=newest&ids=<snip>&limit=1000 failed: [Exception... "Component is not available" nsresult: "0x80040111 (NS_ERROR_NOT_AVAILABLE)" location: "JS frame :: resource://services-sync/resource.js :: _doRequest :: line 167" data: no] Stack trace: _doRequest()@resource://services-sync/resource.js:167 Which appears to be fetch() failing - which seems very odd as we don't seem to be shutting down and earlier fetches appear to be working fine. After that we see Sync stop: > 1533443918001 Sync.Synchronizer INFO Sync completed at 2018-08-05 05:38:38 after 79.29 secs. > 1533443918004 Sync.SyncScheduler DEBUG Next sync in 600000 ms. (why=schedule) So when that log was generated, I wouldn't be surprised to see sync chewing cpu for 80 seconds, but then sync should stop for 10 minutes before trying again - possibly then chewing more CPU until the history back-fill is complete, after which time it should drop to almost zero. So from these logs it doesn't look like sync is responsible for continuous high CPU, just periodic high CPU that should resolve itself. If you flip the preference services.sync.log.appender.file.logOnSuccess to true, you will see log files for every sync, not just ones that report failure. Could you please flip this, then let it go for a day or so, then attach all logs created over that day here? That will give us a better idea of what is going on.
Flags: needinfo?(jeenuv)
I've created a screen cast of the entire process for you: https://youtu.be/flH6ruThYcU. There you can see the balloon with the Activate button, which I didn't click during this recording. Throughout, you can see that the CPU usage is inordinately high, and sync never stops. On other systems, the sync won't take this long to finish. Unfortunately, this is on a machine that I don't use that often, so I don't think I can provide a day-long log of what's happening. I however have flipped the config you mentioned, and captured the log again: https://paste.ubuntu.com/p/hjpvDWf5Ky/. Let me know how I can provide more information.
Flags: needinfo?(jeenuv)
I'd like to also note that this a copy of Firefox I downloaded as archive from firefox.com, not something I apt-get using the package manager.
History backfill being unreasonably slow is probably bug 1435007 (which when combined with resyncs will spend an even longer time syncing, IIRC), although I don’t know that there isnt something else going on here.
That "activate" button is strange - it doesn't appear on any other platforms. I'll dig into that, but I don't think that's related. I suspect that we are just seeing your history items be populated - a couple of minutes isn't really unexpected for a "first" sync. However, it is obviously a much larger problem if *every* sync behaves like that - but it's not clear we are seeing that. What's the longest you've seen it continue for?
Admittedly, I've only let it go for a couple of minutes, mainly because I've seen sync finishing far before than that on other systems I use. I can perhaps let it got for, say, 5 minutes, and let you know what happens.
OK, I let it go for 20 minutes or so. At one point, it did stop synching, and I thought the matter was over. However, I restated Firefox, and I was back to square one: synching restarted, never to finish again. I'm happy to try anything else you'd like me to.
This is probably a duplicate of bug 1435007 then (possibly in conjuncion with general sync perf issues a la bug 1460951). For context, if you have a lot of history records on the server, we will download them in a... quite inefficient manner. You made enough progress on the history backfill to exhaust the limit on "resyncs", but on the start up sync the next time through, it starts again to process more records. If you would rather sync not bother with the slow history backfill process, you can clear the excess server-side history by disabling history sync in your sync settings, syncing, then re-enabling it, and syncing again. This won't delete history on any device, but will mean future devices will not have quite as much history as they otherwise would. Otherwise your only option is to let it complete.
I think you're right. I renamed my profile on my home laptop, and tried to set it up again with a new profile, and the same thing happened--sync wouldn't finish even after half an hour, and CPU usage was very high! I think I'll disable history sync on newer profiles for now. Meanwhile, I've subscribed to 1435007. (Given that it hasn't moved for 4 months, I'm not sure if this will be fixed any time soon). Anyway, thanks for you help. You may dispose this bug as you see fit.
> I think I'll disable history sync on newer profiles for now After disabling it and syncing, if you re-enable it, history syncs should be substantially faster.
I still wouldn't mind seeing any recent entries in about:sync-log, just to be 100% sure it is the issue Thom mentions (which I suspect it is too)
We are confident this is a dupe of bug 1435007 - please feel free to attach further logs if you continue to see this issue.
Status: UNCONFIRMED → RESOLVED
Closed: 7 years ago
Resolution: --- → DUPLICATE
You need to log in before you can comment on or make changes to this bug.