1230892 - Bookmarks sync error with high cpu/disk usage

Status: RESOLVED WORKSFORME

(Firefox :: Sync, defect)

Description

[Vladimir GT]

User Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:42.0) Gecko/20100101 Firefox/42.0
Build ID: 20151029151421

Steps to reproduce:

Using firefox since first versions, my places database size is:

83886080 places.sqlite                        
1507328 places.sqlite-shm                    
2787352 places.sqlite-wal                    

SELECT count(*) FROM moz_bookmarks --44409
SELECT count(*) FROM moz_places --104765

Firefox running from portable drive.



Actual results:

When syncing starts, firefox becomes unresponsive.

Some pictures with procexp
http://www.skillz.ru/images/201512/ffsync/firefox-sync-cpu-usage.png
http://www.skillz.ru/images/201512/ffsync/places-sqlite-wal.png

Error log:

...truncated...to many Record XXX is not an orphan records
1449473825269	Sync.Store.Bookmarks	DEBUG	Record ElI-Tz1VMZtU is not an orphan.
1449473825324	Sync.Store.Bookmarks	DEBUG	Applying record ElKt6E6Pumpe
1449473825324	Sync.Store.Bookmarks	DEBUG	Local parent is unfiled
1449473825324	Sync.Store.Bookmarks	DEBUG	Record ElKt6E6Pumpe is not an orphan.
1449473827324	Sync.Status	DEBUG	Status for engine bookmarks: error.engine.reason.unknown_fail
1449473827324	Sync.Status	DEBUG	Status.service: success.status_ok => error.sync.failed_partial
1449473827324	Sync.ErrorHandler	DEBUG	bookmarks failed: Error: NS_ERROR_NET_PARTIAL_TRANSFER (resource://services-sync/resource.js:409:19) JS Stack trace: [e-mail]:102:7 < [e-mail]:405:14 < [e-mail]:429:12 < [e-mail]:1112:18 < [e-mail]:432:7 < [e-mail]:1524:7 < [e-mail]:229:11 < [e-mail]:226:1 < [e-mail]:148:21 < [e-mail]:668:5 < [e-mail]:199:7 < [e-mail]:149:15 < [e-mail]:1304:7 < [e-mail]:148:21 < [e-mail]:103:16 < [e-mail]:1294:12 < sync/<@service.js:1286:14 < [e-mail]:77:16 < [e-mail]:1274:5 < [e-mail]:429:12 < [e-mail]:1112:18 < [e-mail]:432:7 < [e-mail]:1524:7 < [e-mail]:229:11 < [e-mail]:226:1 < [e-mail]:148:21 < [e-mail]:668:5 < [e-mail]:199:7 < [e-mail]:149:15 < [e-mail]:1304:7 < [e-mail]:148:21 < [e-mail]:103:16 < [e-mail]:1294:12 < sync/<@service.js:1286:14 < [e-mail]:77:16 < [e-mail]:1274:5
1449473827324	Sync.Synchronizer	INFO	Sync completed at 2015-12-07 10:37:07 after 323.55 secs.
1449473827325	Sync.Declined	DEBUG	Handling remote declined: ["forms","history","passwords","prefs","tabs","addons"]
1449473827325	Sync.Declined	DEBUG	Handling local declined: ["forms","history","passwords","prefs","tabs","addons"]
1449473827325	Sync.Declined	DEBUG	Declined changed? false
1449473827326	Sync.Service	INFO	No change to declined engines. Not reuploading meta/global.
1449473827327	browserwindow.syncui	DEBUG	observed: weave:service:sync:finish
1449473827327	browserwindow.syncui	DEBUG	onActivityStop with numActive: 1
1449473827327	browserwindow.syncui	DEBUG	_loginFailed has sync state=success.login
1449473827327	Sync.SyncScheduler	DEBUG	Next sync in 600000 ms.
1449473827327	Sync.ErrorHandler	ERROR	Some engines did not sync correctly.

Comment 1

[Vladimir GT]

After 20 days, I still can't use sync!

\ff\Data\profile>dir place*

25.12.2015  12:20        83 886 080 places.sqlite
25.12.2015  12:19         3 211 264 places.sqlite-shm
25.12.2015  12:20    13 121 358 120 places.sqlite-wal

Every time sync uses 13Gb for about 100 bookmarks diff? is this normal behavior?
Sync runnning for about 10 min with 25%CPU and 20MB/s HDD write.
It killing my portable drive. WTF?

Comment 2

[Mark Hammond [:markh] [:mhammond]]

I suspect the "is not an orphan" message repeating is the root problem here, but sadly I'm not sure of what causes this.

Comment 3

[Richard Newman [:rnewman]]

"is not an orphan" just means that we found the parent folder's numeric ID, which is a good thing.

What happens immediately after that is regular record application, which consists of:

* Checking to see if the record is known. This is a database query by GUID.
* If it doesn't exist, calling bookmarks.insertBookmark. We log right after this.
* Otherwise, calling update: this leads to a call to find out the local type, then looking up the parent, then setting titles and URLs, and so on. This is very expensive indeed.

Each bookmark record application involves a bunch of database queries. You have over 40,000 bookmarks in a database over 80MB in size, and you're running off a portable disk. Your WAL is huge, so it'll take even longer to run each query.

My hypothesis is that the download connection is being closed part-way through the very prolonged record application process, and that's interrupting the sync. Next time it comes to sync, it starts from the last timestamp at which it succeeded, so it'll try and fail to apply those 100 records every time. Even worse, all of the previous attempts left data in the DB, so almost every record will be an update rather than an insert.

My recommendation:

* Install and run the Places Maintenance add-on.

https://addons.mozilla.org/en-US/firefox/addon/places-maintenance/?src=api

* Run a sync on your profile from a fast disk, at least once.
* Clean up your old bookmarks.

Comment 4

[Vladimir GT]

Thx, Richard!

I had followed your recommendations and now sync seems working.

My steps:

1. Copy FF to local drive
2. Run sync
3. Run places maintenance
4. Move back weave folder, places.sqlite file
5. Merge prefs.js differences