947772 - Sync adds tracker observers regardless of engine enabled state

Status: VERIFIED FIXED

(Firefox :: Sync, defect)

Description

[Patrick Storz]

I lately noticed heavy hard disk activity whenever navigating to a new page in Firefox - even if the page was already in cache and despite the fact that I have stored my cache on a RAM disk anyway.

I tracked down the problem with Windows resource monitor: Firefox reads/writes every time when clicking a link from/to "%FF_profile_dir%\weave\changes\history-1.json"

Actually I found "history-1.json" does not exist. "history.json" existed though and was over 10 MB [!] in size (I assume the other file is only temporarily created and then renamed?). I'm afraid Firefox was reading/writing the whole file whenever I clicked a link. This even caused some noticeable delay in the end.

I worked around the issue by simply deleting "history.json" for now. However it was recreated and is again growing (amounting to 148 KB after two days of browsing).

I see two problems here:
1) "history.json" should be purged from time to time (what is saved in there anyway?). I should also note that I clear my Firefox history daily and have set Sync to only synchronize Bookmarks!
2) Why is there read/write activity to this file on every click in the first place? Why aren't those I/O operations cached in memory and only flushed after a specific time or amount of data is reached?

Comment 1

[Richard Newman [:rnewman]]

Sync shouldn't be recording history events if history sync is turned off. In your case, apparently that's not the case... but because you're not syncing history, the tracked changes aren't being written out and cleared.

Most users will never see this file get above a few bytes (mine is 417 bytes right now).

Let me take a look, see if there's a bug hiding here.

Comment 2

[Richard Newman [:rnewman]]

Attachment: Sync adds tracker observers regardless of engine enabled state.

Comment 3

[Richard Newman [:rnewman]]

Comment on attachment 8348560 [details] [diff] [review]
Sync adds tracker observers regardless of engine enabled state.

This includes some minor fixes for SteamEngine, then goes on to make sure that trackers don't track unless their engine is enabled. Adds a basic test for that.

Comment 4

[Gregory Szorc [:gps]]

Comment on attachment 8348560 [details] [diff] [review]
Sync adds tracker observers regardless of engine enabled state.

Review of attachment 8348560 [details] [diff] [review]:
-----------------------------------------------------------------

This looks sane to me. The new API looks much more sane and easier to comprehend than the old mess.

Just some minor nits on review. Nothing beyond your ability to correct without another review, methinks.

Thank you for beautifying the code as part of this refactor.

::: services/sync/modules/engines.js
@@ +185,5 @@
> +    }
> +    return this.engine.enabled;
> +  },
> +
> +  onEngineEnabledChanged: function(engineEnabled) {

Nit: space after "function"

::: services/sync/modules/engines/passwords.js
@@ +279,1 @@
>          return;

It isn't clear from the diff, but it appears the case statements for w:e:start-tracking and w:e:stop-tracking are empty. Why don't you do Tracker.prototype.observe.call() outside of the switch like you do for other engines?

@@ +298,5 @@
> +        }
> +
> +        this.score += SCORE_INCREMENT_XLARGE;
> +        this._log.trace(data + ": " + subject.guid);
> +        this.addChangedID(subject.guid);

Amazing how much nicer well-formatted code is to read and comprehend.

::: services/sync/modules/engines/prefs.js
@@ +221,5 @@
>    },
>  
> +  startTracking: function() {
> +    Cc["@mozilla.org/preferences-service;1"]
> +      .getService(Ci.nsIPrefBranch).addObserver("", this, false);

Services.prefs.addObserver

@@ +227,5 @@
> +
> +  stopTracking: function() {
> +    this.__prefs = null;
> +    Cc["@mozilla.org/preferences-service;1"]
> +      .getService(Ci.nsIPrefBranch).removeObserver("", this);

Ditto.

::: services/sync/modules/engines/tabs.js
@@ +308,5 @@
> +        subject.addEventListener("load", function onLoad(event) {
> +          subject.removeEventListener("load", onLoad, false);
> +          // Only register after the window is done loading to avoid unloads.
> +          this._registerListenersForWindow(subject);
> +        }.bind(this), false);

You could probably use an arrow function. Although I can't remember how safe that will be to uplift if that's a goal.

subject.addEventListener("load", (event) => {
  subject.removeEventListener(...);
}, false);

::: services/sync/tests/unit/test_engine.js
@@ +197,5 @@
> +  do_check_false(tracker._isTracking);
> +  do_check_empty(tracker.changedIDs);
> +
> +  do_check_false(tracker.engineIsEnabled());
> +  tracker.observe(null, "weave:engine:start-tracking", null);

It still bothers me that observers execute on the same tick.

@@ +204,5 @@
> +
> +  engine.enabled = true;
> +  tracker.observe(null, "weave:engine:start-tracking", null);
> +  do_check_true(tracker._isTracking);
> +  do_check_empty(tracker.changedIDs);

It would be nice if you added a changed ID so you could test that changedIDs is reset as part of disabling the engine.

Comment 5

[Richard Newman [:rnewman]]

Thanks for the speedy review!

> > +  onEngineEnabledChanged: function(engineEnabled) {
> 
> Nit: space after "function"

Heh, I just got a review comment from mfinkle complaining about me putting a space in there :)

I've just cleaned up the function signatures in the rest of engines.js, and will land alongside these changes.

> ::: services/sync/modules/engines/passwords.js
> @@ +279,1 @@
> >          return;
> 
> It isn't clear from the diff, but it appears the case statements for
> w:e:start-tracking and w:e:stop-tracking are empty. Why don't you do
> Tracker.prototype.observe.call() outside of the switch like you do for other
> engines?

This is actually the spot where I'm *less* lazy -- we only delegate to the start/stop handling in the superclass when necessary. But it's six of one and half a dozen of the other, and better to be consistent and to not leak that abstraction, so I've changed this.

(Really I should have Tracker.observe return true if it handled the message, so these subclasses can return early, but meh.)


> > +        subject.addEventListener("load", function onLoad(event) {
> > +          subject.removeEventListener("load", onLoad, false);
> > +          // Only register after the window is done loading to avoid unloads.
> > +          this._registerListenersForWindow(subject);
> > +        }.bind(this), false);
> 
> You could probably use an arrow function. Although I can't remember how safe
> that will be to uplift if that's a goal.

We should probably uplift this, but I think arrows landed in 22, so we're good.


> > +  engine.enabled = true;
> > +  tracker.observe(null, "weave:engine:start-tracking", null);
> > +  do_check_true(tracker._isTracking);
> > +  do_check_empty(tracker.changedIDs);
> 
> It would be nice if you added a changed ID so you could test that changedIDs
> is reset as part of disabling the engine.

Will do.

Comment 6

[Richard Newman [:rnewman]]

Landed this in s-c to make sure I get multiple platform xpcshell coverage (password tracker tests are disabled...).

https://hg.mozilla.org/services/services-central/rev/ad12a958aa02

needinfo on me for the merge.

Comment 7

[Richard Newman [:rnewman]]

Fix test_history_tracker:

https://hg.mozilla.org/services/services-central/rev/e8c4daf4f84b

Comment 8

[Gregory Szorc [:gps]]

(In reply to Richard Newman [:rnewman] from comment #5)
> Thanks for the speedy review!
> 
> > > +  onEngineEnabledChanged: function(engineEnabled) {
> > 
> > Nit: space after "function"
> 
> Heh, I just got a review comment from mfinkle complaining about me putting a
> space in there :)

My logic for justifying a space is that the space takes the place of the function name. You don't write "functionfoo()", you write "function foo()". In my head, the grammar is "function" + <sp> + <?name> + "(" .... Leaving the space in is being more consistent about the grammar and not relying on the parser to recognize two forms :)

Comment 9

[Richard Newman [:rnewman]]

https://hg.mozilla.org/mozilla-central/rev/ad12a958aa02
https://hg.mozilla.org/mozilla-central/rev/e8c4daf4f84b

Comment 10

[James Bonacci [:jbonacci]]

Let me know if this needs any QA love...

Comment 11

[Richard Newman [:rnewman]]

If you have time to do it, James, yeah. Basic smoke-testing (that changes on one desktop end up being synced to another), and also the original report: that when an engine is turned off in Preferences, that the tracker file ($profile/weave/changes/$engine*.json) doesn't keep growing as changes occur.

Please also set the appropriate test suite flag (in-litmus-esque) to make sure this doesn't regress in the future.

Thanks!

Comment 12

[James Bonacci [:jbonacci]]

:rnewman - it will have to wait until Jan 6. :-)
Remind me where I pull a build and I will get to this on that Monday.

Comment 13

[Richard Newman [:rnewman]]

(In reply to James Bonacci [:jbonacci] from comment #12)
> :rnewman - it will have to wait until Jan 6. :-)
> Remind me where I pull a build and I will get to this on that Monday.

Any regular Nightly from today onwards will do the trick.

Comment 14

[James Bonacci [:jbonacci]]

(In reply to Richard Newman [:rnewman] from comment #13)
> (In reply to James Bonacci [:jbonacci] from comment #12)
> > :rnewman - it will have to wait until Jan 6. :-)
> > Remind me where I pull a build and I will get to this on that Monday.
> 
> Any regular Nightly from today onwards will do the trick.

Got it thanks...

Comment 15

[Richard Newman [:rnewman]]

Ping, James?

Comment 16

[Richard Newman [:rnewman]]

Comment on attachment 8348560 [details] [diff] [review]
Sync adds tracker observers regardless of engine enabled state.

[Approval Request Comment]
Bug caused by (feature/regressing bug #): 
  Forever!

User impact if declined: 
  Sync will track and persist to disk all changed IDs, even if you're not syncing the selected datatype. That's (a) unexpected, (b) not free, (c) uses up disk space.

Testing completed (on m-c, etc.): 
  Has been baking for a while. Manual "break this" QA is about to happen.

Risk to taking this patch (and alternatives if risky): 
  Should be fairly slim. The core logic change is quite straightforward.

String or IDL/UUID changes made by this patch:
  None.

Comment 17

[James Bonacci [:jbonacci]]

OK, will stuff happens.
Will see what I can do with this before Friday.

Comment 18

[bhavana bajaj [:bajaj]]

(In reply to Richard Newman [:rnewman] from comment #16)
> Comment on attachment 8348560 [details] [diff] [review]
> Sync adds tracker observers regardless of engine enabled state.
> 
> [Approval Request Comment]
> Bug caused by (feature/regressing bug #): 
>   Forever!
> 
> User impact if declined: 
>   Sync will track and persist to disk all changed IDs, even if you're not
> syncing the selected datatype. That's (a) unexpected, (b) not free, (c) uses
> up disk space.
> 
> Testing completed (on m-c, etc.): 
>   Has been baking for a while. Manual "break this" QA is about to happen.
> 
> Risk to taking this patch (and alternatives if risky): 
>   Should be fairly slim. The core logic change is quite straightforward.
> 
> String or IDL/UUID changes made by this patch:
>   None.

Before approving this on Beta I would like to have it QA tested. Also given Fx27 is almost wrapping up with only a few beta's left slightly concerned on the late uplift given this has existed forever. Thoughts? Is this change easily backoutable if needed ? Also, how much automation does this already have and would the fallouts be obvious (easily discoverable) ? Based on QA test results and :rnewman's response we can think of taking this on Monday when Beta 8 goes to build, but would not risk post that.

Comment 19

[James Bonacci [:jbonacci]]

FWIW I was planning on testing this with a nightly build as mentioned in previous comments.
Are you asking for more QA testing than that in Nightly/Aurora?

Comment 20

[Richard Newman [:rnewman]]

(In reply to James Bonacci [:jbonacci] from comment #19)
> FWIW I was planning on testing this with a nightly build as mentioned in
> previous comments.
> Are you asking for more QA testing than that in Nightly/Aurora?

The code should be identical between Nightly and Aurora, so it won't matter which you test.

(In reply to bhavana bajaj [:bajaj] from comment #18)

> Before approving this on Beta I would like to have it QA tested.

It's on jbonacci's plate.

> Is this change easily backoutable if needed ?

Yes. It has no significant dependencies.

> Also, how much automation does this already
> have and would the fallouts be obvious (easily discoverable) ? 

There's a lot of test code that verifies tracking, and if we broke the 'positive' branch -- that is, if we affected syncing for engines you have chosen to sync -- it would be pretty obvious. The 'negative' branch was already broken, of course!

There are also automated tests added for this fix itself. My desire for QA is motivated by thoroughness, rather than thinking that this is high risk.

Comment 21

[Lukas Blakk [:lsblakk] use ?needinfo]

Comment on attachment 8348560 [details] [diff] [review]
Sync adds tracker observers regardless of engine enabled state.

Thanks for the thoroughness, to take this to beta it should land today and get the most coverage with the build that will get kicked off tomorrow.

Comment 22

[Richard Newman [:rnewman]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/a8246d76fff7

Comment 23

[Richard Newman [:rnewman]]

https://hg.mozilla.org/releases/mozilla-beta/rev/879920f2739b

Comment 24

[James Bonacci [:jbonacci]]

Will finally get to test this tomorrow (1/16) - I will grab one of the channels...

Comment 25

[James Bonacci [:jbonacci]]

:rnewman

Here is what I am using: Nightly
on Mac: Nightly 29.0a1 (2014-01-16)
on Windows: Nightly 29.0a1 (2014-01-16)

I uncheck all the boxes in Sync prefs.
I make various changes to history, tabs, bookmarks, etc.
I use Sync Now.

At that point, I do see changes to the sync logs (more success logs for example).
I also see file size changes to the "engine".json files here:
..../Nightly/weave/changes
on both devices

If I do not use Sync Now, I still see updates to "engine".json files.
For example, if I clear recent history or close some tabs.

So maybe I am missing something here?

Comment 26

[James Bonacci [:jbonacci]]

My misunderstanding.
File time/date stamps continue to get updated.
File sizes are not changing if the collections are not being synced.