Last Comment Bug 691988 - OS X: Spurious 'back' events from idle observer cause too many instant syncs
: OS X: Spurious 'back' events from idle observer cause too many instant syncs
Status: VERIFIED FIXED
[verified in services][qa!]
: verified-aurora, verified-beta
Product: Cloud Services
Classification: Client Software
Component: Firefox Sync: Backend (show other bugs)
: unspecified
: x86 Mac OS X
: -- normal (vote)
: mozilla10
Assigned To: Philipp von Weitershausen [:philikon]
:
:
Mentors:
Depends on: 692225
Blocks: 664792 692006
  Show dependency treegraph
 
Reported: 2011-10-04 17:36 PDT by Philipp von Weitershausen [:philikon]
Modified: 2012-01-04 07:53 PST (History)
4 users (show)
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
affected
verified
verified
verified


Attachments
v1 (4.25 KB, patch)
2011-10-04 18:07 PDT, Philipp von Weitershausen [:philikon]
no flags Details | Diff | Splinter Review
v2 (5.34 KB, patch)
2011-10-04 18:17 PDT, Philipp von Weitershausen [:philikon]
rnewman: review+
christian: approval‑mozilla‑aurora+
Details | Diff | Splinter Review
logs during verification pass (44.71 KB, text/rtf)
2011-10-05 15:47 PDT, Tracy Walker [:tracy]
no flags Details
logs during verification pass (74.87 KB, text/html)
2011-10-05 15:52 PDT, Tracy Walker [:tracy]
no flags Details
patch for beta and release (14.70 KB, patch)
2011-10-05 16:19 PDT, Philipp von Weitershausen [:philikon]
no flags Details | Diff | Splinter Review
patch for beta (5.43 KB, patch)
2011-10-05 16:57 PDT, Philipp von Weitershausen [:philikon]
christian: approval‑mozilla‑beta+
Details | Diff | Splinter Review
patch for release (5.37 KB, patch)
2011-10-05 16:58 PDT, Philipp von Weitershausen [:philikon]
no flags Details | Diff | Splinter Review

Description Philipp von Weitershausen [:philikon] 2011-10-04 17:36:57 PDT
While my Windows machine syncs nicely every hour ('idleInterval') at night, my Mac "wakes up" every few minutes in the middle of the night just like that and decides to sync:

1317730539006	Sync.SyncScheduler	TRACE	We're no longer idle.
1317730539010	Sync.SyncScheduler	TRACE	We're idle.

1317733002010	Sync.SyncScheduler	TRACE	We're no longer idle.
1317733002012	Sync.SyncScheduler	TRACE	We're idle.

etc.

Note how close those notifications are. I suspect that within the same event loop tick, the idle observer is called for 'back' and for 'idle' again. I suggest we implement a "debouncer switch" for the 'back' observer.
Comment 1 Philipp von Weitershausen [:philikon] 2011-10-04 18:07:30 PDT
Created attachment 564726 [details] [diff] [review]
v1
Comment 2 Richard Newman [:rnewman] 2011-10-04 18:12:00 PDT
Comment on attachment 564726 [details] [diff] [review]
v1

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

Not reviewing tests yet (until the positive case is tested).

::: services/sync/modules/constants.js
@@ +122,5 @@
>  
>  // Delay before incrementing global score
>  SCORE_UPDATE_DELAY:                    100,
>  
> +// Delay for the back observer debouncer

Explain value, as discussed IRL.

::: services/sync/modules/policies.js
@@ +225,5 @@
>          // were just active.)
>          this.adjustSyncInterval();
>          break;
>        case "back":
>          this._log.trace("We're no longer idle.");

Perhaps change this to "Received notification that we're back from idle.", because it's not always accurate.

@@ +229,5 @@
>          this._log.trace("We're no longer idle.");
>          this.idle = false;
> +        Utils.namedTimer(function onBack() {
> +          if (this.idle) {
> +            this._log.trace("... and we're idle again. Not going to do anything.");

s/Not going to do anything/Ignoring spurious back notification/
Comment 3 Philipp von Weitershausen [:philikon] 2011-10-04 18:17:48 PDT
Created attachment 564729 [details] [diff] [review]
v2

Addressed nits and added another test (for positive behaviour), too.
Comment 4 Richard Newman [:rnewman] 2011-10-04 18:23:39 PDT
Comment on attachment 564729 [details] [diff] [review]
v2

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

::: services/sync/tests/unit/test_syncscheduler.js
@@ +509,5 @@
> +  SyncScheduler.observe(null, "idle", Svc.Prefs.get("scheduler.idleTime"));
> +  do_check_eq(SyncScheduler.idle, true);
> +
> +  // We don't actually expect the sync (or the login, for that matter) to
> +  // succeed. We just want to ensure that it happened.

s/happened/was attempted

@@ +521,5 @@
> +  SyncScheduler.observe(null, "back", Svc.Prefs.get("scheduler.idleTime"));
> +});
> +
> +add_test(function test_back_debouncing() {
> +  _("Ensure spurious back-then-idle events as observed on OS X don't trigger a sync.");

, as observed on OS X,
Comment 5 Philipp von Weitershausen [:philikon] 2011-10-04 20:55:40 PDT
https://hg.mozilla.org/services/services-central/rev/7b01879fc0a3
Comment 6 Philipp von Weitershausen [:philikon] 2011-10-05 11:25:41 PDT
STRs for QA:

* Get a Mac (I have an MBP)
* Set 'services.sync.log.appender.file.logOnSuccess' to true, 'services.sync.log.logger.service.main' to Trace, and then restart.
* Leave the machine sitting & syncing for a few hours.

Expected behaviour:

* The machine syncs with 'services.sync.scheduler.idleInterval' (default is 1 hour) once it's been sitting idle for 'services.sync.scheduler.idleTime' (default is 5 minutes).

Observed behaviour without this fix:

* The machine "wakes up" from idle every 10 to 20 minutes for just a few milliseconds (see log snippets in comment 0) and kicks off a sync.
Comment 7 Philipp von Weitershausen [:philikon] 2011-10-05 11:58:15 PDT
Note that the idle stuff only has any effect if there are at least 2 devices connected to the account.
Comment 8 Tracy Walker [:tracy] 2011-10-05 15:30:47 PDT
On XP and Mac with the latest s-c builds, testing this passes.  Once active sync timers settled to idle timer, I got syncs only once per hour as expected. No unexpected syncs in between. Then a sync on return from idle.
Comment 9 Tracy Walker [:tracy] 2011-10-05 15:47:01 PDT
Created attachment 565041 [details]
logs during verification pass

shows "smoking gun" per philikon. successfully ignoring spurious back notification
Comment 10 Tracy Walker [:tracy] 2011-10-05 15:52:56 PDT
Created attachment 565044 [details]
logs during verification pass
Comment 11 Philipp von Weitershausen [:philikon] 2011-10-05 16:17:04 PDT
Comment on attachment 564729 [details] [diff] [review]
v2

Requesting approval for Aurora as this patch will help reduce server load due to unnecessary syncing (caused by spurious back-from-idle notifications on Macs). The patch has been verified by Services QA.
Comment 12 Philipp von Weitershausen [:philikon] 2011-10-05 16:19:02 PDT
Created attachment 565055 [details] [diff] [review]
patch for beta and release

Requesting approval for Beta and Release. Please see comment 11 for justification.
Comment 13 Philipp von Weitershausen [:philikon] 2011-10-05 16:55:13 PDT
Comment on attachment 565055 [details] [diff] [review]
patch for beta and release

Bah, wrong bug for this patch.
Comment 14 Philipp von Weitershausen [:philikon] 2011-10-05 16:57:47 PDT
Created attachment 565077 [details] [diff] [review]
patch for beta

Requesting approval for Beta. Please see comment 11 for justification.
Comment 15 Philipp von Weitershausen [:philikon] 2011-10-05 16:58:17 PDT
Created attachment 565078 [details] [diff] [review]
patch for release

Request approval for Release. Please see comment 11 for justification.
Comment 16 Philipp von Weitershausen [:philikon] 2011-10-05 17:07:33 PDT
https://hg.mozilla.org/mozilla-central/rev/7b01879fc0a3
Comment 17 Philipp von Weitershausen [:philikon] 2011-10-06 16:46:25 PDT
https://hg.mozilla.org/releases/mozilla-aurora/rev/dc260d4908e8
Comment 18 Philipp von Weitershausen [:philikon] 2011-10-06 16:57:40 PDT
https://hg.mozilla.org/releases/mozilla-beta/rev/74718deb120f
Comment 19 Anthony Hughes (:ashughes) [GFX][QA][Mentor] 2011-10-13 11:28:13 PDT
qa+ for verification in Firefox 8, 9, and 10 using the testcase in comment 6.
Comment 20 Tracy Walker [:tracy] 2011-11-03 12:44:22 PDT
verified cross channel
Comment 21 Vlad [QA] 2012-01-04 07:32:04 PST
Hi Tracy

based on you comment, can I change the tracking status to verified on 8, 9, 10?

Thanks

(In reply to Tracy Walker [:tracy] from comment #20)
> verified cross channel
Comment 22 Tracy Walker [:tracy] 2012-01-04 07:53:56 PST
done. I'm not sure it's necessary to go back and update all the bugs that were affected by the change in status field.  Let's just use it instead of the ambiguous keywords going forward.  Thanks Vlad.

Note You need to log in before you can comment on or make changes to this bug.