722379 - [meta] Extended High CPU usage, possibly due to sync

Status: RESOLVED INCOMPLETE

(Firefox for Android Graveyard :: Android Sync, defect, P1)

Description

[JR Conlin [:jrconlin,:jconlin]]

Attachment: system log

Noticed that nightly was consuming north of 80% CPU for over 10 minutes before failing with a force close message.

See attached log.

(Droid Razr, running 2.3.5)

Comment 1

[JR Conlin [:jrconlin,:jconlin]]

Watching further log messages, the problem seems to be around syncing large histories. May want to either limit that to only when the device is plugged in (and optionally on wifi) or throttle the history to some smaller subset of history.

Comment 2

[Richard Newman [:rnewman]]

We also need to do batching (bug on file).

The difficulty with limiting history is in trying to maintain a useful Awesomebar when we limit your history and end up pulling just your last 250 Gmail URLs. We need to find a useful compromise there.

Still, in your case it appears that each history insert is taking half a second or more. That might be due to missing indexes in the Fennec browser provider, or because your device is fsyncing every time we finish a DB write.

Comment 3

[Richard Newman [:rnewman]]

While I'm looking at the log… Lucas, this looks suspicious:

  01-30 10:27:06.905 17278 17300 D GeckoBrowserProvider: Getting writable database for URI: content://org.mozilla.fennec.db.browser/history?sync=true&show_deleted=true

  01-30 10:27:07.311 17278 17300 D GeckoBrowserProvider: Deleted 1 rows for URI: content://org.mozilla.fennec.db.browser/history?sync=true&show_deleted=true

  ...

  01-30 10:27:07.389 17278 17300 D GeckoBrowserProvider: Getting writable database for URI: content://org.mozilla.fennec.db.browser/history?sync=true&show_deleted=true
  
  01-30 10:27:07.764 17278 17300 D GeckoBrowserProvider: Deleted 1 rows for URI: content://org.mozilla.fennec.db.browser/history?sync=true&show_deleted=true


Lots of pairs there where we're seeing half-second pauses for deletion. (The current code does a DELETE then an INSERT when it pulls down a reconciled item. This is fixed in my tree.)

My hypothesis is that JR's sync hasn't ever finished yet. Each time it tries again, it pulls down all of his history records, queries on GUID for each, deletes the current record, and inserts -- one query and two writes per record. The deletions are taking 400msec each.

And JR seems to have 28,000 history items. No wonder it's sitting and spinning :)

Is there anything obvious that stands out in the CP that could be improved here? Presumably guid is indexed, right?

Batching (Bug 713542) will help here, as will my improvements to replace-in-place, but we'll still be issuing lots of DELETEs…

Comment 5

[Myk Melez [:myk] [@mykmelez]]

In case it helps, attachment 592847 [details] is another log of presumably the same problem, although it also contains a bunch of messages like the following, which I don't see in JR's log:

01-30 11:53:06.690 D/DBUtils ( 1480): Returning history record KnEkLMSNCY33 (3976)
01-30 11:53:06.690 D/DelayedWorkTracker( 1480): Incrementing outstanding.
01-30 11:53:06.690 D/DBUtils ( 1480): > Title:            [TITLE]
01-30 11:53:06.694 D/DBUtils ( 1480): > URI:              [URL]
01-30 11:53:06.694 D/DBUtils ( 1480): > Visited:          1327359449149
01-30 11:53:06.694 D/DBUtils ( 1480): > Visits:           1

Comment 6

[Richard Newman [:rnewman]]

Should be assigned to someone.

Limiting requests (done), batching of fetches (Bug 730142), and batching of inserts (Bug 713542, Bug 735083) should address all of this. I'm aiming to get history batching done for beta if I can.

Comment 7

[Richard Newman [:rnewman]]

If it's a blocker, it's a P1.

This is a meta bug, so perhaps this shouldn't have a blocking flag...

Comment 9

[Richard Newman [:rnewman]]

Tracking the two outstanding dependencies individually. Closing this for now.