Bug 1143714 - Throttle Telemetry environment changes. r=vladan,a=lmandel
authorGeorg Fritzsche <georg.fritzsche@googlemail.com>
Thu, 02 Apr 2015 21:33:46 +0200
changeset 267216 97b36b7bcf86b980076051162a41dc4a699378b3
parent 267215 9b2cd00d2ddc0d557fe3c1e3f1e99aa94a6b8b12
child 267217 25a86f3c31e124499484ae0e7f23f02c8dfe6541
push id830
push userraliiev@mozilla.com
push dateFri, 19 Jun 2015 19:24:37 +0000
treeherdermozilla-release@932614382a68 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersvladan, lmandel
bugs1143714
milestone39.0a2
Bug 1143714 - Throttle Telemetry environment changes. r=vladan,a=lmandel
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
@@ -21,33 +21,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";
@@ -182,20 +184,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 != "");
@@ -620,16 +618,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);
@@ -669,16 +669,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.
@@ -696,16 +699,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();
       }));
   };
 
@@ -745,16 +750,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) => {
@@ -775,16 +783,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();
@@ -803,16 +814,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();
     });
@@ -886,11 +900,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);