Closed Bug 691988 Opened 8 years ago Closed 8 years ago

OS X: Spurious 'back' events from idle observer cause too many instant syncs

Categories

(Firefox :: Sync, defect)

x86
macOS
defect
Not set

Tracking

()

VERIFIED FIXED
mozilla10
Tracking Status
firefox7 --- affected
firefox8 --- verified
firefox9 --- verified
firefox10 --- verified

People

(Reporter: philikon, Assigned: philikon)

References

(Depends on 1 open bug)

Details

(Keywords: verified-aurora, verified-beta, Whiteboard: [verified in services][qa!])

Attachments

(4 files, 3 obsolete files)

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.
Attached patch v1 (obsolete) — Splinter Review
Assignee: nobody → philipp
Status: NEW → ASSIGNED
Attachment #564726 - Flags: review?(rnewman)
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/
Attached patch v2Splinter Review
Addressed nits and added another test (for positive behaviour), too.
Attachment #564726 - Attachment is obsolete: true
Attachment #564726 - Flags: review?(rnewman)
Attachment #564729 - Flags: review?(rnewman)
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,
Attachment #564729 - Flags: review?(rnewman) → review+
Blocks: 692006
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.
Note that the idle stuff only has any effect if there are at least 2 devices connected to the account.
Depends on: 692225
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.
Whiteboard: [fixed in services] → [verified in services]
Attached file logs during verification pass (obsolete) —
shows "smoking gun" per philikon. successfully ignoring spurious back notification
Attachment #565041 - Attachment is obsolete: true
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.
Attachment #564729 - Flags: approval-mozilla-aurora?
Attached patch patch for beta and release (obsolete) — Splinter Review
Requesting approval for Beta and Release. Please see comment 11 for justification.
Attachment #565055 - Flags: approval-mozilla-release?
Attachment #565055 - Flags: approval-mozilla-beta?
Comment on attachment 565055 [details] [diff] [review]
patch for beta and release

Bah, wrong bug for this patch.
Attachment #565055 - Attachment is obsolete: true
Attachment #565055 - Flags: approval-mozilla-release?
Attachment #565055 - Flags: approval-mozilla-beta?
Attached patch patch for betaSplinter Review
Requesting approval for Beta. Please see comment 11 for justification.
Attachment #565077 - Flags: approval-mozilla-beta?
Request approval for Release. Please see comment 11 for justification.
Attachment #565078 - Flags: approval-mozilla-release?
https://hg.mozilla.org/mozilla-central/rev/7b01879fc0a3
Status: ASSIGNED → RESOLVED
Closed: 8 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla10
Attachment #565077 - Flags: approval-mozilla-beta? → approval-mozilla-beta+
Attachment #564729 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
qa+ for verification in Firefox 8, 9, and 10 using the testcase in comment 6.
Whiteboard: [verified in services] → [verified in services][qa+]
Attachment #565078 - Flags: approval-mozilla-release?
verified cross channel
Status: RESOLVED → VERIFIED
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
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.
Whiteboard: [verified in services][qa+] → [verified in services][qa!]
Component: Firefox Sync: Backend → Sync
Product: Cloud Services → Firefox
You need to log in before you can comment on or make changes to this bug.