bug 1460595 - Implement the 'event' ping r=Dexter,janerik
authorChris H-C <chutten@mozilla.com>
Mon, 14 May 2018 09:57:30 -0400
changeset 423720 e2242d1730a3
parent 423719 f9ce3e37a291
child 423721 23936736c3b4
push id34191
push userrgurzau@mozilla.com
push dateTue, 26 Jun 2018 21:53:37 +0000
treeherdermozilla-central@1c235a552c32 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersDexter, janerik
bugs1460595
milestone63.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 1460595 - Implement the 'event' ping r=Dexter,janerik 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',