From b409e25748bc8b9260dc70c8a6612fc732e094a6 Mon Sep 17 00:00:00 2001 From: Mark Hammond Date: Wed, 8 Jun 2022 23:22:07 +0000 Subject: [PATCH] Bug 1773219 - more efficent tab syncing on tab opening/switching/etc. r=skhamis Differential Revision: https://phabricator.services.mozilla.com/D148622 --- services/sync/modules/engines/tabs.js | 172 +++++++++++++++++- services/sync/modules/telemetry.js | 15 +- .../sync/tests/unit/test_tab_quickwrite.js | 137 ++++++++++++++ services/sync/tests/unit/test_tab_tracker.js | 6 +- services/sync/tests/unit/xpcshell.ini | 1 + 5 files changed, 317 insertions(+), 14 deletions(-) create mode 100644 services/sync/tests/unit/test_tab_quickwrite.js diff --git a/services/sync/modules/engines/tabs.js b/services/sync/modules/engines/tabs.js index 025e9d419ebc..139748ec4309 100644 --- a/services/sync/modules/engines/tabs.js +++ b/services/sync/modules/engines/tabs.js @@ -22,9 +22,22 @@ const { CryptoWrapper } = ChromeUtils.import( "resource://services-sync/record.js" ); const { Svc, Utils } = ChromeUtils.import("resource://services-sync/util.js"); -const { SCORE_INCREMENT_SMALL, URI_LENGTH_MAX } = ChromeUtils.import( - "resource://services-sync/constants.js" +const { + LOGIN_SUCCEEDED, + SCORE_INCREMENT_SMALL, + STATUS_OK, + URI_LENGTH_MAX, +} = ChromeUtils.import("resource://services-sync/constants.js"); +const { CommonUtils } = ChromeUtils.import( + "resource://services-common/utils.js" ); +const { Async } = ChromeUtils.import("resource://services-common/async.js"); + +const { SyncRecord, SyncTelemetry } = ChromeUtils.import( + "resource://services-sync/telemetry.js" +); + +const FAR_FUTURE = 4102405200000; // 2100/01/01 const lazy = {}; @@ -140,6 +153,132 @@ TabEngine.prototype = { this._tracker.modified = true; } }, + + async _onRecordsWritten(succeeded, failed, serverModifiedTime) { + await super._onRecordsWritten(succeeded, failed, serverModifiedTime); + if (failed.length) { + // This should be impossible, so make a note. Maybe upgrade to `.error`? + this._log.warn("the server rejected our tabs record"); + } + }, + + // Support for "quick writes" + _engineLock: Utils.lock, + _engineLocked: false, + + // Tabs has a special lock to help support its "quick write" + get locked() { + return this._engineLocked; + }, + lock() { + if (this._engineLocked) { + return false; + } + this._engineLocked = true; + return true; + }, + unlock() { + this._engineLocked = false; + }, + + // Quickly do a POST of our current tabs if possible. + // This does things that would be dangerous for other engines - eg, posting + // without checking what's on the server could cause data-loss for other + // engines, but because each device exclusively owns exactly 1 tabs record + // with a known ID, it's safe here. + async quickWrite() { + if (!this.enabled) { + // this should be very rare, and only if tabs are disabled after the + // timer is created. + this._log.info("Can't do a quick-sync as tabs is disabled"); + return; + } + // This quick-sync doesn't drive the login state correctly, so just + // decline to sync if out status is bad + if (this.service.status.checkSetup() != STATUS_OK) { + this._log.info( + "Can't do a quick-sync due to the service status", + this.service.status.toString() + ); + return; + } + if (!this.service.serverConfiguration) { + this._log.info("Can't do a quick sync before the first full sync"); + return; + } + try { + await this._engineLock("tabs.js: quickWrite", async () => { + // We want to restore the lastSync timestamp when complete so next sync + // takes tabs written by other devices since our last real sync. + // And for this POST we don't want the protections offered by + // X-If-Unmodified-Since - we want the POST to work even if the remote + // has moved on and we will catch back up next full sync. + const origLastSync = await this.getLastSync(); + await this.setLastSync(FAR_FUTURE); + try { + await this._doQuickWrite(); + } finally { + await this.setLastSync(origLastSync); + } + })(); + } catch (ex) { + if (!Utils.isLockException(ex)) { + throw ex; + } + this._log.info( + "Can't do a quick-write as another tab sync is in progress" + ); + } + }, + + // The guts of the quick-write sync, after we've taken the lock, checked + // the service status etc. + async _doQuickWrite() { + // We need to track telemetry for these syncs too! + const name = "tabs"; + let telemetryRecord = new SyncRecord( + SyncTelemetry.allowedEngines, + "quick-write" + ); + telemetryRecord.onEngineStart(name); + try { + Async.checkAppReady(); + // tracking the modified items is normally done by _syncStartup(), + // but we don't call that so we don't do the meta/global dances - + // these dances would be very important for any other engine, but + // we can avoid it for tabs because of the lack of reconcilliation. + this._modified.replace(await this.pullChanges()); + this._tracker.clearChangedIDs(); + this._tracker.resetScore(); + + // now just the "upload" part of a sync. + Async.checkAppReady(); + await this._uploadOutgoing(); + telemetryRecord.onEngineApplied(name, 1); + telemetryRecord.onEngineStop(name, null); + } catch (ex) { + telemetryRecord.onEngineStop(name, ex); + } finally { + // The top-level sync is never considered to fail here, just the engine + telemetryRecord.finished(null); + SyncTelemetry.takeTelemetryRecord(telemetryRecord); + } + }, + + async _sync() { + try { + await this._engineLock("tabs.js: fullSync", async () => { + await super._sync(); + })(); + } catch (ex) { + if (!Utils.isLockException(ex)) { + throw ex; + } + this._log.info( + "Can't do full tabs sync as a quick-write is currently running" + ); + } + }, }; function TabStore(name, engine) { @@ -436,17 +575,36 @@ TabTracker.prototype = { // If we are part of the experiment don't use score here // and instead schedule a sync once we detect a tab change - // to ensure the server always has the most up to date tabs + // to ensure the server always has the most up to date tabs if ( delayInMs > 0 && scheduler.numClients > 1 // Don't constantly schedule syncs for single client users ) { + if (this.tabsQuickWriteTimer) { + this._log.debug( + "Detected a tab change, but a quick-write is already scheduled" + ); + return; + } this._log.debug( - "Detected a tab change: scheduling a sync in " + delayInMs + "ms" + "Detected a tab change: scheduling a quick-write in " + delayInMs + "ms" + ); + CommonUtils.namedTimer( + () => { + this._log.trace("tab quick-sync timer fired."); + this.engine + .quickWrite() + .then(() => { + this._log.trace("tab quick-sync done."); + }) + .catch(ex => { + this._log.error("tab quick-sync failed.", ex); + }); + }, + delayInMs, + this, + "tabsQuickWriteTimer" ); - scheduler.scheduleNextSync(delayInMs, { - why: "tabschanged", - }); } else if (scoreIncrement) { this.score += scoreIncrement; } diff --git a/services/sync/modules/telemetry.js b/services/sync/modules/telemetry.js index 0f76ecf4015b..16a042d5c2fe 100644 --- a/services/sync/modules/telemetry.js +++ b/services/sync/modules/telemetry.js @@ -6,6 +6,7 @@ var EXPORTED_SYMBOLS = [ "ErrorSanitizer", // for testing. + "SyncRecord", "SyncTelemetry", ]; @@ -882,7 +883,8 @@ class SyncTelemetryImpl { _checkCurrent(topic) { if (!this.current) { - log.warn( + // This is only `info` because it happens when we do a tabs "quick-write" + log.info( `Observed notification ${topic} but no current sync is being recorded.` ); return false; @@ -961,18 +963,23 @@ class SyncTelemetryImpl { } this.current.finished(error); this.currentSyncNodeType = this.current.syncNodeType; + let current = this.current; + this.current = null; + this.takeTelemetryRecord(current); + } + + takeTelemetryRecord(record) { // We check for "data change" before appending the current sync to payloads, // as it is the current sync which has the data with the new data, and thus // must go in the *next* submission. this.maybeSubmitForDataChange(); if (this.payloads.length < this.maxPayloadCount) { - this.payloads.push(this.current.toJSON()); + this.payloads.push(record.toJSON()); } else { ++this.discarded; } - this.current = null; // If we are submitting due to timing, it's desirable that the most recent - // sync is included, so we check after appending `this.current`. + // sync is included, so we check after appending the record. this.maybeSubmitForInterval(); } diff --git a/services/sync/tests/unit/test_tab_quickwrite.js b/services/sync/tests/unit/test_tab_quickwrite.js new file mode 100644 index 000000000000..9dd71ec77034 --- /dev/null +++ b/services/sync/tests/unit/test_tab_quickwrite.js @@ -0,0 +1,137 @@ +/* Any copyright is dedicated to the Public Domain. + http://creativecommons.org/publicdomain/zero/1.0/ */ + +ChromeUtils.import("resource://services-sync/engines/tabs.js"); +const { Service } = ChromeUtils.import("resource://services-sync/service.js"); + +const { TabEngine } = ChromeUtils.import( + "resource://services-sync/engines/tabs.js" +); + +async function getMockedEngine() { + let engine = new TabEngine(Service); + await engine.initialize(); + let store = engine._store; + store.getTabState = mockGetTabState; + store.shouldSkipWindow = mockShouldSkipWindow; + return engine; +} + +async function prepareServer() { + _("Setting up Sync server"); + Service.serverConfiguration = { + max_post_records: 100, + }; + + let server = new SyncServer(); + server.start(); + await SyncTestingInfrastructure(server, "username"); + server.registerUser("username"); + + let collection = server.createCollection("username", "tabs"); + await generateNewKeys(Service.collectionKeys); + return { server, collection }; +} + +async function withPatchedValue(object, name, patchedVal, fn) { + _(`patching ${name}=${patchedVal}`); + let old = object[name]; + object[name] = patchedVal; + try { + await fn(); + } finally { + object[name] = old; + } +} + +add_task(async function test_tab_quickwrite_works() { + _("Ensure a simple quickWrite works."); + let engine = await getMockedEngine(); + let { server, collection } = await prepareServer(); + + Assert.equal(collection.count(), 0, "starting with 0 tab records"); + await engine.quickWrite(); + Assert.equal(collection.count(), 1, "tab record was written"); + + await promiseStopServer(server); +}); + +add_task(async function test_tab_bad_status() { + _("Ensure quickWrite silently aborts when we aren't setup correctly."); + let engine = await getMockedEngine(); + let { server } = await prepareServer(); + + // Arrange for this test to fail if it tries to take the lock. + engine.lock = function() { + throw new Error("this test should abort syncing before locking"); + }; + let quickWrite = engine.quickWrite.bind(engine); // lol javascript. + + await withPatchedValue(engine, "enabled", false, quickWrite); + await withPatchedValue(Service, "serverConfiguration", null, quickWrite); + + Services.prefs.clearUserPref("services.sync.username"); + quickWrite(); + Service.status.resetSync(); + + await promiseStopServer(server); +}); + +add_task(async function test_tab_quickwrite_lock() { + _("Ensure we fail to quickWrite if the engine is locked."); + let engine = await getMockedEngine(); + let { server, collection } = await prepareServer(); + + Assert.equal(collection.count(), 0, "starting with 0 tab records"); + engine.lock(); + await engine.quickWrite(); + Assert.equal(collection.count(), 0, "didn't sync due to being locked"); + engine.unlock(); + + await promiseStopServer(server); +}); + +add_task(async function test_tab_lastSync() { + _("Ensure we restore the lastSync timestamp after a quick-write."); + let engine = await getMockedEngine(); + let { server, collection } = await prepareServer(); + + let origLastSync = engine.lastSync; + await engine.quickWrite(); + Assert.equal(engine.lastSync, origLastSync); + Assert.equal(collection.count(), 1, "successful sync"); + engine.unlock(); + + await promiseStopServer(server); +}); + +add_task(async function test_tab_quickWrite_telemetry() { + _("Ensure we record the telemetry we expect."); + // hook into telemetry + let telem = get_sync_test_telemetry(); + telem.payloads = []; + let oldSubmit = telem.submit; + let submitPromise = new Promise((resolve, reject) => { + telem.submit = function(ping) { + telem.submit = oldSubmit; + resolve(ping); + }; + }); + + let engine = await getMockedEngine(); + let { server, collection } = await prepareServer(); + + Assert.equal(collection.count(), 0, "starting with 0 tab records"); + await engine.quickWrite(); + Assert.equal(collection.count(), 1, "tab record was written"); + + let ping = await submitPromise; + let syncs = ping.syncs; + Assert.equal(syncs.length, 1); + let sync = syncs[0]; + Assert.equal(sync.why, "quick-write"); + Assert.equal(sync.engines.length, 1); + Assert.equal(sync.engines[0].name, "tabs"); + + await promiseStopServer(server); +}); diff --git a/services/sync/tests/unit/test_tab_tracker.js b/services/sync/tests/unit/test_tab_tracker.js index f4b3d864ebb5..0f3e8beddbc5 100644 --- a/services/sync/tests/unit/test_tab_tracker.js +++ b/services/sync/tests/unit/test_tab_tracker.js @@ -284,8 +284,8 @@ add_task(async function run_sync_on_tab_change_test() { "about page triggers a modified after we changed the pref" ); Assert.ok( - scheduler.nextSync - Date.now() <= testExperimentDelay, - "about page should trigger a sync soon after we changed the pref" + tracker.tabsQuickWriteTimer, + "about page should schedule a quickWrite sync soon after we changed the pref" ); _("Test no sync after tab change for accounts with <= 1 clients"); @@ -330,7 +330,7 @@ add_task(async function run_sync_on_tab_change_test() { // Ensure the tracker fired Assert.ok(tracker.modified); // We should be scheduling <= preference value - Assert.ok(scheduler.nextSync - Date.now() <= delayPref); + Assert.equal(tracker.tabsQuickWriteTimer.delay, delayPref); _("We should not have a sync if experiment if off and pref is 0"); diff --git a/services/sync/tests/unit/xpcshell.ini b/services/sync/tests/unit/xpcshell.ini index 721eb42713ad..5fdf807e07ae 100644 --- a/services/sync/tests/unit/xpcshell.ini +++ b/services/sync/tests/unit/xpcshell.ini @@ -156,6 +156,7 @@ run-sequentially = extension-storage migration happens only once, and must be te support-files = prefs_test_prefs_store.js [test_prefs_tracker.js] [test_tab_engine.js] +[test_tab_quickwrite.js] [test_tab_store.js] [test_tab_tracker.js]