bug 1460595 - Implement the 'event' ping r=Dexter,janerik a=lizzard
authorChris H-C <chutten@mozilla.com>
Mon, 14 May 2018 09:57:30 -0400
changeset 477871 0abaa980b795
parent 477870 7168e116a406
child 477872 602dd78381af
push id9448
push userarchaeopteryx@coole-files.de
push dateMon, 09 Jul 2018 17:22:41 +0000
treeherdermozilla-beta@32cde6cdb297 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersDexter, janerik, lizzard
bugs1460595
milestone62.0
bug 1460595 - Implement the 'event' ping r=Dexter,janerik a=lizzard MozReview-Commit-ID: HQAk8jmouyI
toolkit/components/telemetry/TelemetryController.jsm
toolkit/components/telemetry/TelemetryEventPing.jsm
toolkit/components/telemetry/moz.build
--- a/toolkit/components/telemetry/TelemetryController.jsm
+++ b/toolkit/components/telemetry/TelemetryController.jsm
@@ -58,16 +58,17 @@ XPCOMUtils.defineLazyModuleGetters(this,
   UpdateUtils: "resource://gre/modules/UpdateUtils.jsm",
   TelemetryArchive: "resource://gre/modules/TelemetryArchive.jsm",
   TelemetrySession: "resource://gre/modules/TelemetrySession.jsm",
   TelemetrySend: "resource://gre/modules/TelemetrySend.jsm",
   TelemetryReportingPolicy: "resource://gre/modules/TelemetryReportingPolicy.jsm",
   TelemetryModules: "resource://gre/modules/TelemetryModules.jsm",
   UpdatePing: "resource://gre/modules/UpdatePing.jsm",
   TelemetryHealthPing: "resource://gre/modules/TelemetryHealthPing.jsm",
+  TelemetryEventPing: "resource://gre/modules/TelemetryEventPing.jsm",
   OS: "resource://gre/modules/osfile.jsm",
 });
 
 /**
  * Setup Telemetry logging. This function also gets called when loggin related
  * preferences change.
  */
 var gLogger = null;
@@ -688,16 +689,18 @@ var Impl = {
 
         // The init sequence is forced to run on shutdown for short sessions and
         // we don't want to start TelemetryModules as the timer registration will fail.
         if (!this._shuttingDown) {
           // Report the modules loaded in the Firefox process.
           TelemetryModules.start();
         }
 
+        TelemetryEventPing.startup();
+
         this._delayedInitTaskDeferred.resolve();
       } catch (e) {
         this._delayedInitTaskDeferred.reject(e);
       } finally {
         this._delayedInitTask = null;
       }
     }, this._testMode ? TELEMETRY_TEST_DELAY : TELEMETRY_DELAY,
        this._testMode ? 0 : undefined);
@@ -738,16 +741,18 @@ var Impl = {
     // Now do an orderly shutdown.
     try {
       if (this._delayedNewPingTask) {
         await this._delayedNewPingTask.finalize();
       }
 
       UpdatePing.shutdown();
 
+      TelemetryEventPing.shutdown();
+
       // Stop the datachoices infobar display.
       TelemetryReportingPolicy.shutdown();
       TelemetryEnvironment.shutdown();
 
       // Stop any ping sending.
       await TelemetrySend.shutdown();
 
       // Send latest data.
new file mode 100644
--- /dev/null
+++ b/toolkit/components/telemetry/TelemetryEventPing.jsm
@@ -0,0 +1,216 @@
+/* This Source Code Form is subject to the terms of the Mozilla Public
+ * License, v. 2.0. If a copy of the MPL was not distributed with this
+ * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
+
+/*
+ * This module sends Telemetry Events periodically:
+ * https://firefox-source-docs.mozilla.org/toolkit/components/telemetry/telemetry/data/event-ping.html
+ */
+
+"use strict";
+
+var EXPORTED_SYMBOLS = [
+  "TelemetryEventPing",
+];
+
+ChromeUtils.import("resource://gre/modules/XPCOMUtils.jsm", this);
+
+XPCOMUtils.defineLazyModuleGetters(this, {
+  TelemetrySession: "resource://gre/modules/TelemetrySession.jsm",
+  TelemetryController: "resource://gre/modules/TelemetryController.jsm",
+  Log: "resource://gre/modules/Log.jsm",
+});
+
+XPCOMUtils.defineLazyServiceGetters(this, {
+  Telemetry: ["@mozilla.org/base/telemetry;1", "nsITelemetry"],
+});
+
+ChromeUtils.defineModuleGetter(this, "setTimeout", "resource://gre/modules/Timer.jsm");
+ChromeUtils.defineModuleGetter(this, "clearTimeout", "resource://gre/modules/Timer.jsm");
+ChromeUtils.defineModuleGetter(this, "TelemetryUtils", "resource://gre/modules/TelemetryUtils.jsm");
+ChromeUtils.defineModuleGetter(this, "Services", "resource://gre/modules/Services.jsm");
+
+const Utils = TelemetryUtils;
+
+const MS_IN_A_MINUTE = 60 * 1000;
+
+const DEFAULT_EVENT_LIMIT = 1000;
+const DEFAULT_MIN_FREQUENCY_MS = 60 * MS_IN_A_MINUTE;
+const DEFAULT_MAX_FREQUENCY_MS = 10 * MS_IN_A_MINUTE;
+
+const LOGGER_NAME = "Toolkit.Telemetry";
+const LOGGER_PREFIX = "TelemetryEventPing::";
+
+const EVENT_LIMIT_REACHED_TOPIC = "event-telemetry-storage-limit-reached";
+const PROFILE_BEFORE_CHANGE_TOPIC = "profile-before-change";
+
+var Policy = {
+  setTimeout: (callback, delayMs) => setTimeout(callback, delayMs),
+  clearTimeout: (id) => clearTimeout(id),
+  sendPing: (type, payload, options) => TelemetryController.submitExternalPing(type, payload, options),
+};
+
+var TelemetryEventPing = {
+  Reason: Object.freeze({
+    PERIODIC: "periodic", // Sent the ping containing events from the past periodic interval (default one hour).
+    MAX: "max",           // Sent the ping containing the maximum number (default 1000) of event records, earlier than the periodic interval.
+    SHUTDOWN: "shutdown", // Recorded data was sent on shutdown.
+  }),
+
+  EVENT_PING_TYPE: "event",
+
+  _logger: null,
+
+  _testing: false,
+
+  // So that if we quickly reach the max limit we can immediately send.
+  _lastSendTime: -DEFAULT_MIN_FREQUENCY_MS,
+
+  get dataset() {
+    return Telemetry.canRecordPrereleaseData ? Ci.nsITelemetry.DATASET_RELEASE_CHANNEL_OPTIN
+                                             : Ci.nsITelemetry.DATASET_RELEASE_CHANNEL_OPTOUT;
+  },
+
+  startup() {
+    Services.obs.addObserver(this, EVENT_LIMIT_REACHED_TOPIC);
+    Services.obs.addObserver(this, PROFILE_BEFORE_CHANGE_TOPIC);
+
+    XPCOMUtils.defineLazyPreferenceGetter(this, "maxEventsPerPing",
+                                          Utils.Preferences.EventPingEventLimit,
+                                          DEFAULT_EVENT_LIMIT);
+    XPCOMUtils.defineLazyPreferenceGetter(this, "maxFrequency",
+                                          Utils.Preferences.EventPingMaximumFrequency,
+                                          DEFAULT_MAX_FREQUENCY_MS);
+    XPCOMUtils.defineLazyPreferenceGetter(this, "minFrequency",
+                                          Utils.Preferences.EventPingMinimumFrequency,
+                                          DEFAULT_MIN_FREQUENCY_MS);
+
+    this._startTimer();
+  },
+
+  shutdown() {
+    // removeObserver may throw, which could interrupt shutdown.
+    try {
+      Services.obs.removeObserver(this, EVENT_LIMIT_REACHED_TOPIC);
+      Services.obs.removeObserver(this, PROFILE_BEFORE_CHANGE_TOPIC);
+    } catch (ex) {}
+
+    this._clearTimer();
+  },
+
+  observe(aSubject, aTopic, aData) {
+    switch (aTopic) {
+      case EVENT_LIMIT_REACHED_TOPIC:
+        this._log.trace("event limit reached");
+        let now = Utils.monotonicNow();
+        if ((now - this._lastSendTime) < this.maxFrequency) {
+          this._log.trace("can't submit ping immediately as it's too soon");
+          this._startTimer(this.maxFrequency - this._lastSendTime,
+                           this.Reason.MAX,
+                           true /* discardLeftovers*/);
+        } else {
+          this._log.trace("submitting ping immediately");
+          this._submitPing(this.Reason.MAX);
+        }
+        break;
+      case PROFILE_BEFORE_CHANGE_TOPIC:
+        this._log.trace("profile before change");
+        this._submitPing(this.Reason.SHUTDOWN, true /* discardLeftovers */);
+        break;
+    }
+  },
+
+  _startTimer(delay = this.minFrequency, reason = this.Reason.PERIODIC, discardLeftovers = false) {
+    this._clearTimer();
+    this._timeoutId =
+      Policy.setTimeout(() => TelemetryEventPing._submitPing(reason, discardLeftovers), delay);
+  },
+
+  _clearTimer() {
+    if (this._timeoutId) {
+      Policy.clearTimeout(this._timeoutId);
+      this._timeoutId = null;
+    }
+  },
+
+  /**
+   * Submits an "event" ping and restarts the timer for the next interval.
+   *
+   * @param {String} reason The reason we're sending the ping. One of TelemetryEventPing.Reason.
+   * @param {bool} discardLeftovers Whether to discard event records left over from a previous ping.
+   */
+  _submitPing(reason, discardLeftovers = false) {
+    this._log.trace("_submitPing");
+
+    if (reason !== this.Reason.SHUTDOWN) {
+      this._startTimer();
+    }
+
+    let snapshot = Telemetry.snapshotEvents(this.dataset,
+                                            true /* clear */,
+                                            this.maxEventsPerPing);
+
+    if (!this._testing) {
+      for (let process of Object.keys(snapshot)) {
+        snapshot[process] = snapshot[process].filter(([, category]) => !category.startsWith("telemetry.test"));
+      }
+    }
+
+    let eventCount = Object.values(snapshot).reduce((acc, val) => acc + val.length, 0);
+    if (eventCount === 0) {
+      // Don't send a ping if we haven't any events.
+      this._log.trace("not sending event ping due to lack of events");
+      return;
+    }
+
+    // The reason doesn't matter as it will just be echo'd back.
+    let sessionMeta = TelemetrySession.getMetadata(reason);
+
+    let processStartTimestamp = Math.round((Date.now() - TelemetryUtils.monotonicNow()) / MS_IN_A_MINUTE) * MS_IN_A_MINUTE;
+
+    let payload = {
+      reason,
+      processStartTimestamp,
+      sessionId: sessionMeta.sessionId,
+      subsessionId: sessionMeta.subsessionId,
+      lostEventsCount: 0,
+      events: snapshot,
+    };
+
+    if (discardLeftovers) {
+      // Any leftovers must be discarded, the count submitted in the ping.
+      // This can happen on shutdown or if our max was reached before faster
+      // than our maxFrequency.
+      let leftovers = Telemetry.snapshotEvents(this.dataset,
+                                               true /* clear */);
+      let leftoverCount = Object.values(leftovers).reduce((acc, val) => acc + val.length, 0);
+      payload.lostEventsCount = leftoverCount;
+    }
+
+    const options = {
+      addClientId: true,
+      addEnvironment: true,
+      usePingSender: reason == this.Reason.SHUTDOWN,
+    };
+
+    this._lastSendTime = Utils.monotonicNow();
+    Policy.sendPing(this.EVENT_PING_TYPE, payload, options);
+  },
+
+  /**
+   * Test-only, restore to initial state.
+   */
+  testReset() {
+    this._lastSendTime = -DEFAULT_MIN_FREQUENCY_MS;
+    this._clearTimer();
+    this._testing = true;
+  },
+
+  get _log() {
+    if (!this._logger) {
+      this._logger = Log.repository.getLoggerWithMessagePrefix(LOGGER_NAME, LOGGER_PREFIX + "::");
+    }
+
+    return this._logger;
+  },
+};
--- a/toolkit/components/telemetry/moz.build
+++ b/toolkit/components/telemetry/moz.build
@@ -87,16 +87,17 @@ EXTRA_COMPONENTS += [
     'TelemetryStartup.manifest'
 ]
 
 EXTRA_JS_MODULES += [
     'GCTelemetry.jsm',
     'TelemetryArchive.jsm',
     'TelemetryController.jsm',
     'TelemetryEnvironment.jsm',
+    'TelemetryEventPing.jsm',
     'TelemetryHealthPing.jsm',
     'TelemetryModules.jsm',
     'TelemetryReportingPolicy.jsm',
     'TelemetrySend.jsm',
     'TelemetrySession.jsm',
     'TelemetryStopwatch.jsm',
     'TelemetryStorage.jsm',
     'TelemetryTimestamps.jsm',