Bug 1143714 - Throttle Telemetry environment changes. r=vladan
☠☠ backed out by 6901a267f856 ☠ ☠
authorGeorg Fritzsche <georg.fritzsche@googlemail.com>
Wed, 01 Apr 2015 21:06:19 +0200
changeset 237242 fdf9d0174142501b063088fde6574851bd2377e9
parent 237241 18989d1ebd43519f9fa7b3149beba4150938203a
child 237243 7a6f6bdd6edf5d9f344ad06ea696c920bca17ea8
push id57898
push usercbook@mozilla.com
push dateThu, 02 Apr 2015 12:14:17 +0000
treeherdermozilla-inbound@63c87250946e [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersvladan
bugs1143714
milestone40.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1143714 - Throttle Telemetry environment changes. r=vladan
toolkit/components/telemetry/TelemetryEnvironment.jsm
toolkit/components/telemetry/tests/unit/head.js
toolkit/components/telemetry/tests/unit/test_TelemetryEnvironment.js
toolkit/components/telemetry/tests/unit/test_TelemetrySession.js
--- a/toolkit/components/telemetry/TelemetryEnvironment.jsm
+++ b/toolkit/components/telemetry/TelemetryEnvironment.jsm
@@ -26,16 +26,25 @@ XPCOMUtils.defineLazyModuleGetter(this, 
 XPCOMUtils.defineLazyModuleGetter(this, "LightweightThemeManager",
                                   "resource://gre/modules/LightweightThemeManager.jsm");
 #endif
 XPCOMUtils.defineLazyModuleGetter(this, "ProfileAge",
                                   "resource://gre/modules/ProfileAge.jsm");
 XPCOMUtils.defineLazyModuleGetter(this, "UpdateChannel",
                                   "resource://gre/modules/UpdateChannel.jsm");
 
+const CHANGE_THROTTLE_INTERVAL_MS = 5 * 60 * 1000;
+
+/**
+ * This is a policy object used to override behavior for testing.
+ */
+let Policy = {
+  now: () => new Date(),
+};
+
 var gGlobalEnvironment;
 function getGlobal() {
   if (!gGlobalEnvironment) {
     gGlobalEnvironment = new EnvironmentCache();
   }
   return gGlobalEnvironment;
 }
 
@@ -623,16 +632,19 @@ function EnvironmentCache() {
     LOGGER_NAME, "TelemetryEnvironment::");
   this._log.trace("constructor");
 
   this._shutdown = false;
 
   // A map of listeners that will be called on environment changes.
   this._changeListeners = new Map();
 
+  // The last change date for the environment, used to throttle environment changes.
+  this._lastEnvironmentChangeDate = null;
+
   // A map of watched preferences which trigger an Environment change when
   // modified. Every entry contains a recording policy (RECORD_PREF_*).
   this._watchedPrefs = DEFAULT_ENVIRONMENT_PREFS;
 
   this._currentEnvironment = {
     build: this._getBuild(),
     partner: this._getPartner(),
     system: this._getSystem(),
@@ -1060,17 +1072,26 @@ EnvironmentCache.prototype = {
   _onEnvironmentChange: function (what, oldEnvironment) {
     this._log.trace("_onEnvironmentChange for " + what);
     if (this._shutdown) {
       this._log.trace("_onEnvironmentChange - Already shut down.");
       return;
     }
 
     // We are already skipping change events in _checkChanges if there is a pending change task running.
-    // Further throttling is coming in bug 1143714.
+    let now = Policy.now();
+    if (this._lastEnvironmentChangeDate &&
+        (CHANGE_THROTTLE_INTERVAL_MS >=
+         (now.getTime() - this._lastEnvironmentChangeDate.getTime()))) {
+      this._log.trace("_onEnvironmentChange - throttling changes, now: " + now +
+                      ", last change: " + this._lastEnvironmentChangeDate);
+      return;
+    }
+
+    this._lastEnvironmentChangeDate = now;
 
     for (let [name, listener] of this._changeListeners) {
       try {
         this._log.debug("_onEnvironmentChange - calling " + name);
         listener(what, oldEnvironment);
       } catch (e) {
         this._log.error("_onEnvironmentChange - listener " + name + " caught error", e);
       }
--- a/toolkit/components/telemetry/tests/unit/head.js
+++ b/toolkit/components/telemetry/tests/unit/head.js
@@ -4,16 +4,20 @@
 Components.utils.import("resource://gre/modules/TelemetryPing.jsm", this);
 Components.utils.import("resource://gre/modules/Services.jsm", this);
 
 const gIsWindows = ("@mozilla.org/windows-registry-key;1" in Components.classes);
 const gIsMac = ("@mozilla.org/xpcom/mac-utils;1" in Components.classes);
 const gIsAndroid =  ("@mozilla.org/android/bridge;1" in Components.classes);
 const gIsGonk = ("@mozilla.org/cellbroadcast/gonkservice;1" in Components.classes);
 
+const MILLISECONDS_PER_MINUTE = 60 * 1000;
+const MILLISECONDS_PER_HOUR = 60 * MILLISECONDS_PER_MINUTE;
+const MILLISECONDS_PER_DAY = 24 * MILLISECONDS_PER_HOUR;
+
 const HAS_DATAREPORTINGSERVICE = "@mozilla.org/datareporting/service;1" in Components.classes;
 
 let gOldAppInfo = null;
 let gGlobalScope = this;
 
 function loadAddonManager(id, name, version, platformVersion) {
   let ns = {};
   Cu.import("resource://gre/modules/Services.jsm", ns);
@@ -82,15 +86,32 @@ function createAppInfo(id, name, version
 
 // Fake the timeout functions for the TelemetryScheduler.
 function fakeSchedulerTimer(set, clear) {
   let session = Components.utils.import("resource://gre/modules/TelemetrySession.jsm");
   session.Policy.setSchedulerTickTimeout = set;
   session.Policy.clearSchedulerTickTimeout = clear;
 }
 
+// Fake the current date.
+function fakeNow(date) {
+  let session = Cu.import("resource://gre/modules/TelemetrySession.jsm");
+  session.Policy.now = () => date;
+  let environment = Cu.import("resource://gre/modules/TelemetryEnvironment.jsm");
+  environment.Policy.now = () => date;
+}
+
+// Return a date that is |offset| ms in the future from |date|.
+function futureDate(date, offset) {
+  return new Date(date.getTime() + offset);
+}
+
+function truncateToDays(aMsec) {
+  return Math.floor(aMsec / MILLISECONDS_PER_DAY);
+}
+
 // Set logging preferences for all the tests.
 Services.prefs.setCharPref("toolkit.telemetry.log.level", "Trace");
 Services.prefs.setBoolPref("toolkit.telemetry.log.dump", true);
 TelemetryPing.initLogging();
 
 // Avoid timers interrupting test behavior.
 fakeSchedulerTimer(() => {}, () => {});
--- a/toolkit/components/telemetry/tests/unit/test_TelemetryEnvironment.js
+++ b/toolkit/components/telemetry/tests/unit/test_TelemetryEnvironment.js
@@ -22,33 +22,35 @@ XPCOMUtils.defineLazyModuleGetter(this, 
 
 // The webserver hosting the addons.
 let gHttpServer = null;
 // The URL of the webserver root.
 let gHttpRoot = null;
 // The URL of the data directory, on the webserver.
 let gDataRoot = null;
 
+let gNow = new Date(2010, 1, 1, 12, 0, 0);
+fakeNow(gNow);
+
 const PLATFORM_VERSION = "1.9.2";
 const APP_VERSION = "1";
 const APP_ID = "xpcshell@tests.mozilla.org";
 const APP_NAME = "XPCShell";
 const APP_HOTFIX_VERSION = "2.3.4a";
 
 const DISTRIBUTION_ID = "distributor-id";
 const DISTRIBUTION_VERSION = "4.5.6b";
 const DISTRIBUTOR_NAME = "Some Distributor";
 const DISTRIBUTOR_CHANNEL = "A Channel";
 const PARTNER_NAME = "test";
 const PARTNER_ID = "NicePartner-ID-3785";
 
 const GFX_VENDOR_ID = "0xabcd";
 const GFX_DEVICE_ID = "0x1234";
 
-const MILLISECONDS_PER_DAY = 24 * 60 * 60 * 1000;
 // The profile reset date, in milliseconds (Today)
 const PROFILE_RESET_DATE_MS = Date.now();
 // The profile creation date, in milliseconds (Yesterday).
 const PROFILE_CREATION_DATE_MS = PROFILE_RESET_DATE_MS - MILLISECONDS_PER_DAY;
 
 const FLASH_PLUGIN_NAME = "Shockwave Flash";
 const FLASH_PLUGIN_DESC = "A mock flash plugin";
 const FLASH_PLUGIN_VERSION = "\u201c1.1.1.1\u201d";
@@ -170,20 +172,16 @@ function spoofPartnerInfo() {
   prefsToSpoof["mozilla.partner.id"] = PARTNER_ID;
 
   // Spoof the preferences.
   for (let pref in prefsToSpoof) {
     Preferences.set(pref, prefsToSpoof[pref]);
   }
 }
 
-function truncateToDays(aMsec) {
-  return Math.floor(aMsec / MILLISECONDS_PER_DAY);
-}
-
 /**
  * Check that a value is a string and not empty.
  *
  * @param aValue The variable to check.
  * @return True if |aValue| has type "string" and is not empty, False otherwise.
  */
 function checkString(aValue) {
   return (typeof aValue == "string") && (aValue != "");
@@ -608,16 +606,18 @@ add_task(function* test_checkEnvironment
 
 add_task(function* test_prefWatchPolicies() {
   const PREF_TEST_1 = "toolkit.telemetry.test.pref_new";
   const PREF_TEST_2 = "toolkit.telemetry.test.pref1";
   const PREF_TEST_3 = "toolkit.telemetry.test.pref2";
   const PREF_TEST_4 = "toolkit.telemetry.test.pref_old";
 
   const expectedValue = "some-test-value";
+  gNow = futureDate(gNow, 10 * MILLISECONDS_PER_MINUTE);
+  fakeNow(gNow);
 
   let prefsToWatch = {};
   prefsToWatch[PREF_TEST_1] = TelemetryEnvironment.RECORD_PREF_VALUE;
   prefsToWatch[PREF_TEST_2] = TelemetryEnvironment.RECORD_PREF_STATE;
   prefsToWatch[PREF_TEST_3] = TelemetryEnvironment.RECORD_PREF_STATE;
   prefsToWatch[PREF_TEST_4] = TelemetryEnvironment.RECORD_PREF_VALUE;
 
   Preferences.set(PREF_TEST_4, expectedValue);
@@ -657,16 +657,19 @@ add_task(function* test_prefWatchPolicie
 add_task(function* test_prefWatch_prefReset() {
   const PREF_TEST = "toolkit.telemetry.test.pref1";
 
   let prefsToWatch = {};
   prefsToWatch[PREF_TEST] = TelemetryEnvironment.RECORD_PREF_STATE;
   // Set the preference to a non-default value.
   Preferences.set(PREF_TEST, false);
 
+  gNow = futureDate(gNow, 10 * MILLISECONDS_PER_MINUTE);
+  fakeNow(gNow);
+
   // Set the Environment preferences to watch.
   TelemetryEnvironment._watchPreferences(prefsToWatch);
   let deferred = PromiseUtils.defer();
   TelemetryEnvironment.registerChangeListener("testWatchPrefs_reset", deferred.resolve);
 
   Assert.strictEqual(TelemetryEnvironment.currentEnvironment.settings.userPrefs[PREF_TEST], "<user-set>");
 
   // Trigger a change in the watched preferences.
@@ -684,16 +687,18 @@ add_task(function* test_addonsWatch_Inte
   const ADDON_ID = "tel-restartless-xpi@tests.mozilla.org";
   // We only expect a single notification for each install, uninstall, enable, disable.
   const EXPECTED_NOTIFICATIONS = 4;
 
   let deferred = PromiseUtils.defer();
   let receivedNotifications = 0;
 
   let registerCheckpointPromise = (aExpected) => {
+    gNow = futureDate(gNow, 10 * MILLISECONDS_PER_MINUTE);
+    fakeNow(gNow);
     return new Promise(resolve => TelemetryEnvironment.registerChangeListener(
       "testWatchAddons_Changes" + aExpected, (reason, data) => {
         Assert.equal(reason, "addons-changed");
         receivedNotifications++;
         resolve();
       }));
   };
 
@@ -733,16 +738,19 @@ add_task(function* test_addonsWatch_Inte
 });
 
 add_task(function* test_pluginsWatch_Add() {
   if (gIsAndroid) {
     Assert.ok(true, "Skipping: there is no Plugin Manager on Android.");
     return;
   }
 
+  gNow = futureDate(gNow, 10 * MILLISECONDS_PER_MINUTE);
+  fakeNow(gNow);
+
   Assert.equal(TelemetryEnvironment.currentEnvironment.addons.activePlugins.length, 1);
 
   let newPlugin = new PluginTag(PLUGIN2_NAME, PLUGIN2_DESC, PLUGIN2_VERSION, true);
   gInstalledPlugins.push(newPlugin);
 
   let deferred = PromiseUtils.defer();
   let receivedNotifications = 0;
   let callback = (reason, data) => {
@@ -763,16 +771,19 @@ add_task(function* test_pluginsWatch_Add
 });
 
 add_task(function* test_pluginsWatch_Remove() {
   if (gIsAndroid) {
     Assert.ok(true, "Skipping: there is no Plugin Manager on Android.");
     return;
   }
 
+  gNow = futureDate(gNow, 10 * MILLISECONDS_PER_MINUTE);
+  fakeNow(gNow);
+
   // Find the test plugin.
   let plugin = gInstalledPlugins.find(plugin => (plugin.name == PLUGIN2_NAME));
   Assert.ok(plugin, "The test plugin must exist.");
 
   // Remove it from the PluginHost.
   gInstalledPlugins = gInstalledPlugins.filter(p => p != plugin);
 
   let deferred = PromiseUtils.defer();
@@ -791,16 +802,19 @@ add_task(function* test_pluginsWatch_Rem
   Assert.equal(receivedNotifications, 1, "We must only receive one notification.");
 });
 
 add_task(function* test_addonsWatch_NotInterestingChange() {
   // We are not interested to dictionary addons changes.
   const DICTIONARY_ADDON_INSTALL_URL = gDataRoot + "dictionary.xpi";
   const INTERESTING_ADDON_INSTALL_URL = gDataRoot + "restartless.xpi";
 
+  gNow = futureDate(gNow, 10 * MILLISECONDS_PER_MINUTE);
+  fakeNow(gNow);
+
   let receivedNotification = false;
   let deferred = PromiseUtils.defer();
   TelemetryEnvironment.registerChangeListener("testNotInteresting",
     () => {
       Assert.ok(!receivedNotification, "Should not receive multiple notifications");
       receivedNotification = true;
       deferred.resolve();
     });
@@ -874,11 +888,50 @@ add_task(function* test_addonsAndPlugins
   Assert.ok(targetPlugin.mimeTypes.find(m => m == PLUGIN_MIME_TYPE1));
   Assert.ok(targetPlugin.mimeTypes.find(m => m == PLUGIN_MIME_TYPE2));
   Assert.ok(!targetPlugin.mimeTypes.find(m => m == "Not There."));
 
   let personaId = (gIsGonk) ? null : PERSONA_ID;
   Assert.equal(data.addons.persona, personaId, "The correct Persona Id must be reported.");
 });
 
+add_task(function* test_changeThrottling() {
+  const PREF_TEST = "toolkit.telemetry.test.pref1";
+  let prefsToWatch = {};
+  prefsToWatch[PREF_TEST] = TelemetryEnvironment.RECORD_PREF_STATE;
+  Preferences.reset(PREF_TEST);
+
+  gNow = futureDate(gNow, 10 * MILLISECONDS_PER_MINUTE);
+  fakeNow(gNow);
+
+  // Set the Environment preferences to watch.
+  TelemetryEnvironment._watchPreferences(prefsToWatch);
+  let deferred = PromiseUtils.defer();
+  let changeCount = 0;
+  TelemetryEnvironment.registerChangeListener("testWatchPrefs_throttling", () => {
+    ++changeCount;
+    deferred.resolve();
+  });
+
+  // The first pref change should trigger a notification.
+  Preferences.set(PREF_TEST, 1);
+  yield deferred.promise;
+  Assert.equal(changeCount, 1);
+
+  // We should only get a change notification for second of the following changes.
+  deferred = PromiseUtils.defer();
+  gNow = futureDate(gNow, MILLISECONDS_PER_MINUTE);
+  fakeNow(gNow);
+  Preferences.set(PREF_TEST, 2);
+  gNow = futureDate(gNow, 5 * MILLISECONDS_PER_MINUTE);
+  fakeNow(gNow);
+  Preferences.set(PREF_TEST, 3);
+  yield deferred.promise;
+
+  Assert.equal(changeCount, 2);
+
+  // Unregister the listener.
+  TelemetryEnvironment.unregisterChangeListener("testWatchPrefs_throttling");
+});
+
 add_task(function*() {
   do_test_finished();
 });
--- a/toolkit/components/telemetry/tests/unit/test_TelemetrySession.js
+++ b/toolkit/components/telemetry/tests/unit/test_TelemetrySession.js
@@ -94,16 +94,23 @@ XPCOMUtils.defineLazyGetter(this, "gData
           .wrappedJSObject);
 
 function generateUUID() {
   let str = Cc["@mozilla.org/uuid-generator;1"].getService(Ci.nsIUUIDGenerator).generateUUID().toString();
   // strip {}
   return str.substring(1, str.length - 1);
 }
 
+function truncateDateToDays(date) {
+  return new Date(date.getFullYear(),
+                  date.getMonth(),
+                  date.getDate(),
+                  0, 0, 0, 0);
+}
+
 function sendPing() {
   TelemetrySession.gatherStartup();
   if (gServerStarted) {
     TelemetryPing.setServer("http://localhost:" + gHttpServer.identity.primaryPort);
     return TelemetrySession.testPing();
   } else {
     TelemetryPing.setServer("http://doesnotexist");
     return TelemetrySession.testPing();
@@ -118,25 +125,16 @@ function wrapWithExceptionHandler(f) {
       dump("Caught exception: " + ex.message + "\n");
       dump(ex.stack);
       do_test_finished();
     }
   }
   return wrapper;
 }
 
-function futureDate(date, offset) {
-  return new Date(date.getTime() + offset);
-}
-
-function fakeNow(date) {
-  let session = Cu.import("resource://gre/modules/TelemetrySession.jsm");
-  session.Policy.now = () => date;
-}
-
 function fakeGenerateUUID(sessionFunc, subsessionFunc) {
   let session = Cu.import("resource://gre/modules/TelemetrySession.jsm");
   session.Policy.generateSessionUUID = sessionFunc;
   session.Policy.generateSubsessionUUID = subsessionFunc;
 }
 
 function registerPingHandler(handler) {
   gHttpServer.registerPrefixHandler("/submit/telemetry/",
@@ -1108,17 +1106,16 @@ add_task(function* test_dailyOverdue() {
 
 add_task(function* test_environmentChange() {
   if (gIsAndroid) {
     // We don't split subsessions on environment changes yet on Android.
     return;
   }
 
   let now = new Date(2040, 1, 1, 12, 0, 0);
-  let nowDay = new Date(2040, 1, 1, 0, 0, 0);
   let timerCallback = null;
   let timerDelay = null;
 
   gRequestIterator = Iterator(new Request());
 
   fakeNow(now);
 
   const PREF_TEST = "toolkit.telemetry.test.pref1";
@@ -1139,41 +1136,49 @@ add_task(function* test_environmentChang
 
   count.clear();
   keyed.clear();
   count.add(1);
   keyed.add("a", 1);
   keyed.add("b", 1);
 
   // Trigger and collect environment-change ping.
+  let startDay = truncateDateToDays(now);
+  now = futureDate(now, 10 * MILLISECONDS_PER_MINUTE);
+  fakeNow(now);
+
   Preferences.set(PREF_TEST, 1);
   let request = yield gRequestIterator.next();
   Assert.ok(!!request);
   let ping = decodeRequestPayload(request);
 
   Assert.equal(ping.type, PING_TYPE_MAIN);
   Assert.equal(ping.environment.settings.userPrefs[PREF_TEST], undefined);
   Assert.equal(ping.payload.info.reason, REASON_ENVIRONMENT_CHANGE);
   let subsessionStartDate = new Date(ping.payload.info.subsessionStartDate);
-  Assert.equal(subsessionStartDate.toISOString(), nowDay.toISOString());
+  Assert.equal(subsessionStartDate.toISOString(), startDay.toISOString());
 
   Assert.equal(ping.payload.histograms[COUNT_ID].sum, 1);
   Assert.equal(ping.payload.keyedHistograms[KEYED_ID]["a"].sum, 1);
 
   // Trigger and collect another ping. The histograms should be reset.
+  startDay = truncateDateToDays(now);
+  now = futureDate(now, 10 * MILLISECONDS_PER_MINUTE);
+  fakeNow(now);
+
   Preferences.set(PREF_TEST, 2);
   request = yield gRequestIterator.next();
   Assert.ok(!!request);
   ping = decodeRequestPayload(request);
 
   Assert.equal(ping.type, PING_TYPE_MAIN);
   Assert.equal(ping.environment.settings.userPrefs[PREF_TEST], 1);
   Assert.equal(ping.payload.info.reason, REASON_ENVIRONMENT_CHANGE);
   subsessionStartDate = new Date(ping.payload.info.subsessionStartDate);
-  Assert.equal(subsessionStartDate.toISOString(), nowDay.toISOString());
+  Assert.equal(subsessionStartDate.toISOString(), startDay.toISOString());
 
   Assert.equal(ping.payload.histograms[COUNT_ID].sum, 0);
   Assert.deepEqual(ping.payload.keyedHistograms[KEYED_ID], {});
 });
 
 // Checks that an expired histogram file is deleted when loaded.
 add_task(function* test_runOldPingFile() {
   let histogramsFile = getSavedPingFile("old-histograms.dat");
@@ -1243,16 +1248,17 @@ add_task(function* test_savedSessionData
     return;
   }
 
   // Start TelemetrySession so that it loads the session data file.
   yield TelemetrySession.reset();
   // Watch a test preference, trigger and environment change and wait for it to propagate.
 
   // _watchPreferences triggers a subsession notification
+  fakeNow(new Date(2050, 1, 1, 12, 0, 0));
   TelemetryEnvironment._watchPreferences(prefsToWatch);
   let changePromise = new Promise(resolve =>
     TelemetryEnvironment.registerChangeListener("test_fake_change", resolve));
   Preferences.set(PREF_TEST, 1);
   yield changePromise;
   TelemetryEnvironment.unregisterChangeListener("test_fake_change");
 
   let payload = TelemetrySession.getPayload();
@@ -1482,17 +1488,17 @@ add_task(function* test_schedulerEnviron
   const PREF_TEST = "toolkit.telemetry.test.pref1";
   Preferences.reset(PREF_TEST);
   let prefsToWatch = {};
   prefsToWatch[PREF_TEST] = TelemetryEnvironment.RECORD_PREF_VALUE;
 
   gRequestIterator = Iterator(new Request());
 
   // Set a fake current date and start Telemetry.
-  let nowDate = new Date(2009, 10, 18, 0, 00, 0);
+  let nowDate = new Date(2060, 10, 18, 0, 00, 0);
   fakeNow(nowDate);
   let schedulerTickCallback = null;
   fakeSchedulerTimer(callback => schedulerTickCallback = callback, () => {});
   yield TelemetrySession.reset();
   TelemetryEnvironment._watchPreferences(prefsToWatch);
 
   // Set the current time at midnight.
   let future = futureDate(nowDate, MS_IN_ONE_DAY);