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

@@ -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) {
@@ -441,12 +580,31 @@ TabTracker.prototype = {
       delayInMs > 0 &&
       scheduler.numClients > 1 // Don't constantly schedule syncs for single client users
     ) {
+      if (this.tabsQuickWriteTimer) {
         this._log.debug(
-        "Detected a tab change: scheduling a sync in " + delayInMs + "ms"
+          "Detected a tab change, but a quick-write is already scheduled"
         );
-      scheduler.scheduleNextSync(delayInMs, {
-        why: "tabschanged",
+        return;
+      }
+      this._log.debug(
+        "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"
+      );
     } else if (scoreIncrement) {
       this.score += scoreIncrement;
     }

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();
   }
 

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);
+});

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");
 

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]