Bug 1033860 - Add probes for time needed to load pending & archived pings from disk. r=chutten data-r=bsmedberg
authorVedant Sareen <vedantsareen@gmail.com>
Mon, 29 May 2017 17:25:39 +0530
changeset 409378 c45dd304a93949f3f1ddbf4ecf60690e349c42b6
parent 409377 b5c3bb245c4e770eb128b0e2e803321d17e5239f
child 409379 895d9a8826a3f0f609b4d604638a7b2471a0a2aa
push id7391
push usermtabara@mozilla.com
push dateMon, 12 Jun 2017 13:08:53 +0000
treeherdermozilla-beta@2191d7f87e2e [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewerschutten
bugs1033860
milestone55.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 1033860 - Add probes for time needed to load pending & archived pings from disk. r=chutten data-r=bsmedberg Added "TELEMETRY_PENDING_LOAD_MS" & "TELEMETRY_ARCHIVE_LOAD_MS" as exponential histograms. Added the functionality to save in these histograms the time it takes to load pending/archived pings respectively. Added the file |test_TelemetryStorage.js| with tests for the added functionality.
toolkit/components/telemetry/Histograms.json
toolkit/components/telemetry/TelemetryController.jsm
toolkit/components/telemetry/TelemetryStorage.jsm
toolkit/components/telemetry/tests/unit/test_TelemetryStorage.js
toolkit/components/telemetry/tests/unit/xpcshell.ini
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@@ -7140,16 +7140,36 @@
     "record_in_processes": ["main", "content"],
     "alert_emails": ["telemetry-client-dev@mozilla.com"],
     "expires_in_version": "never",
     "kind": "exponential",
     "high": 300000,
     "n_buckets": 20,
     "description": "Time (ms) it takes for checking if the pending pings are over-quota"
   },
+  "TELEMETRY_PENDING_LOAD_MS": {
+    "record_in_processes": ["main"],
+    "alert_emails": ["telemetry-client-dev@mozilla.com", "chutten@mozilla.com"],
+    "expires_in_version": "never",
+    "kind": "exponential",
+    "high": 2000,
+    "n_buckets": 20,
+    "bug_numbers": [1033860],
+    "description": "Time (ms) it takes for loading pending pings from disk"
+  },
+  "TELEMETRY_ARCHIVE_LOAD_MS": {
+    "record_in_processes": ["main"],
+    "alert_emails": ["telemetry-client-dev@mozilla.com", "chutten@mozilla.com"],
+    "expires_in_version": "never",
+    "kind": "exponential",
+    "high": 2000,
+    "n_buckets": 20,
+    "bug_numbers": [1033860],
+    "description": "Time (ms) it takes for loading archived pings from disk"
+  },
   "TELEMETRY_PING_SIZE_EXCEEDED_SEND": {
     "record_in_processes": ["main", "content"],
     "alert_emails": ["telemetry-client-dev@mozilla.com"],
     "expires_in_version": "never",
     "kind": "count",
     "description": "Number of Telemetry pings discarded before sending because they exceeded the maximum size"
   },
   "TELEMETRY_PING_SIZE_EXCEEDED_PENDING": {
--- a/toolkit/components/telemetry/TelemetryController.jsm
+++ b/toolkit/components/telemetry/TelemetryController.jsm
@@ -135,16 +135,23 @@ this.TelemetryController = Object.freeze
     PREF_LOG_LEVEL,
     PREF_LOG_DUMP,
     PREF_SERVER,
   }),
 
   /**
    * Used only for testing purposes.
    */
+  testAssemblePing(aType, aPayload, aOptions) {
+    return Impl.assemblePing(aType, aPayload, aOptions);
+  },
+
+  /**
+   * Used only for testing purposes.
+   */
   testInitLogging() {
     configureLogging();
   },
 
   /**
    * Used only for testing purposes.
    */
   testReset() {
--- a/toolkit/components/telemetry/TelemetryStorage.jsm
+++ b/toolkit/components/telemetry/TelemetryStorage.jsm
@@ -12,16 +12,17 @@ const Ci = Components.interfaces;
 const Cr = Components.results;
 const Cu = Components.utils;
 
 Cu.import("resource://gre/modules/AppConstants.jsm", this);
 Cu.import("resource://gre/modules/Log.jsm");
 Cu.import("resource://gre/modules/Services.jsm", this);
 Cu.import("resource://gre/modules/XPCOMUtils.jsm", this);
 Cu.import("resource://gre/modules/osfile.jsm", this);
+Cu.import("resource://gre/modules/TelemetryStopwatch.jsm", this);
 Cu.import("resource://gre/modules/TelemetryUtils.jsm", this);
 Cu.import("resource://gre/modules/Promise.jsm", this);
 Cu.import("resource://gre/modules/Preferences.jsm", this);
 
 const LOGGER_NAME = "Toolkit.Telemetry";
 const LOGGER_PREFIX = "TelemetryStorage::";
 
 const Telemetry = Services.telemetry;
@@ -165,16 +166,28 @@ this.TelemetryStorage = {
    * @param {string} id The pings id.
    * @return {promise<object>} Promise that is resolved with the ping data.
    */
   loadArchivedPing(id) {
     return TelemetryStorageImpl.loadArchivedPing(id);
   },
 
   /**
+   * Remove an archived ping from disk.
+   *
+   * @param {string} id The ping's id.
+   * @param {number} timestampCreated The ping's creation timestamp.
+   * @param {string} type The ping's type.
+   * @return {promise<object>} Promise that is resolved when the ping is removed.
+   */
+  removeArchivedPing(id, timestampCreated, type) {
+    return TelemetryStorageImpl._removeArchivedPing(id, timestampCreated, type);
+  },
+
+  /**
    * Get a list of info on the archived pings.
    * This will scan the archive directory and grab basic data about the existing
    * pings out of their filename.
    *
    * @return {promise<sequence<object>>}
    */
   loadArchivedPingList() {
     return TelemetryStorageImpl.loadArchivedPingList();
@@ -684,51 +697,59 @@ var TelemetryStorageImpl = {
 
   /**
    * Load an archived ping from disk.
    *
    * @param {string} id The pings id.
    * @return {promise<object>} Promise that is resolved with the ping data.
    */
   async loadArchivedPing(id) {
+    TelemetryStopwatch.start("TELEMETRY_ARCHIVE_LOAD_MS");
     const data = this._archivedPings.get(id);
     if (!data) {
+      TelemetryStopwatch.cancel("TELEMETRY_ARCHIVE_LOAD_MS");
       this._log.trace("loadArchivedPing - no ping with id: " + id);
       return Promise.reject(new Error("TelemetryStorage.loadArchivedPing - no ping with id " + id));
     }
 
     const path = getArchivedPingPath(id, new Date(data.timestampCreated), data.type);
     const pathCompressed = path + "lz4";
 
     // Purge pings which are too big.
     let checkSize = async function(path) {
       const fileSize = (await OS.File.stat(path)).size;
       if (fileSize > PING_FILE_MAXIMUM_SIZE_BYTES) {
         Telemetry.getHistogramById("TELEMETRY_DISCARDED_ARCHIVED_PINGS_SIZE_MB")
                  .add(Math.floor(fileSize / 1024 / 1024));
         Telemetry.getHistogramById("TELEMETRY_PING_SIZE_EXCEEDED_ARCHIVED").add();
+        TelemetryStopwatch.cancel("TELEMETRY_ARCHIVE_LOAD_MS");
         await OS.File.remove(path, {ignoreAbsent: true});
         throw new Error("loadArchivedPing - exceeded the maximum ping size: " + fileSize);
       }
     };
 
+    let ping;
     try {
       // Try to load a compressed version of the archived ping first.
       this._log.trace("loadArchivedPing - loading ping from: " + pathCompressed);
       await checkSize(pathCompressed);
-      return await this.loadPingFile(pathCompressed, /* compressed*/ true);
+      ping = await this.loadPingFile(pathCompressed, /* compressed*/ true);
     } catch (ex) {
       if (!ex.becauseNoSuchFile) {
+        TelemetryStopwatch.cancel("TELEMETRY_ARCHIVE_LOAD_MS");
         throw ex;
       }
       // If that fails, look for the uncompressed version.
       this._log.trace("loadArchivedPing - compressed ping not found, loading: " + path);
       await checkSize(path);
-      return await this.loadPingFile(path, /* compressed*/ false);
+      ping = await this.loadPingFile(path, /* compressed*/ false);
     }
+
+    TelemetryStopwatch.finish("TELEMETRY_ARCHIVE_LOAD_MS");
+    return ping;
   },
 
   /**
    * Saves session data to disk.
    */
   saveSessionData(sessionData) {
     return this._stateSaveSerializer.enqueueTask(() => this._saveSessionData(sessionData));
   },
@@ -1313,59 +1334,66 @@ var TelemetryStorageImpl = {
       this._log.trace("savePendingPing - saved ping with id " + ping.id);
     });
     this._trackPendingPingSaveTask(p);
     return p;
   },
 
   async loadPendingPing(id) {
     this._log.trace("loadPendingPing - id: " + id);
+    TelemetryStopwatch.start("TELEMETRY_PENDING_LOAD_MS");
     let info = this._pendingPings.get(id);
     if (!info) {
+      TelemetryStopwatch.cancel("TELEMETRY_PENDING_LOAD_MS");
       this._log.trace("loadPendingPing - unknown id " + id);
       throw new Error("TelemetryStorage.loadPendingPing - no ping with id " + id);
     }
 
     // Try to get the dimension of the ping. If that fails, update the histograms.
     let fileSize = 0;
     try {
       fileSize = (await OS.File.stat(info.path)).size;
     } catch (e) {
       if (!(e instanceof OS.File.Error) || !e.becauseNoSuchFile) {
+        TelemetryStopwatch.cancel("TELEMETRY_PENDING_LOAD_MS");
         throw e;
       }
       // Fall through and let |loadPingFile| report the error.
     }
 
     // Purge pings which are too big.
     if (fileSize > PING_FILE_MAXIMUM_SIZE_BYTES) {
       await this.removePendingPing(id);
       Telemetry.getHistogramById("TELEMETRY_DISCARDED_PENDING_PINGS_SIZE_MB")
                .add(Math.floor(fileSize / 1024 / 1024));
       Telemetry.getHistogramById("TELEMETRY_PING_SIZE_EXCEEDED_PENDING").add();
+      TelemetryStopwatch.cancel("TELEMETRY_PENDING_LOAD_MS");
       throw new Error("loadPendingPing - exceeded the maximum ping size: " + fileSize);
     }
 
     // Try to load the ping file. Update the related histograms on failure.
     let ping;
     try {
       ping = await this.loadPingFile(info.path, false);
     } catch (e) {
       // If we failed to load the ping, check what happened and update the histogram.
       if (e instanceof PingReadError) {
         Telemetry.getHistogramById("TELEMETRY_PENDING_LOAD_FAILURE_READ").add();
       } else if (e instanceof PingParseError) {
         Telemetry.getHistogramById("TELEMETRY_PENDING_LOAD_FAILURE_PARSE").add();
       }
+      TelemetryStopwatch.cancel("TELEMETRY_PENDING_LOAD_MS");
+
       // Remove the ping from the cache, so we don't try to load it again.
       this._pendingPings.delete(id);
       // Then propagate the rejection.
       throw e;
     }
 
+    TelemetryStopwatch.finish("TELEMETRY_PENDING_LOAD_MS");
     return ping;
   },
 
   removePendingPing(id) {
     let info = this._pendingPings.get(id);
     if (!info) {
       this._log.trace("removePendingPing - unknown id " + id);
       return Promise.resolve();
new file mode 100644
--- /dev/null
+++ b/toolkit/components/telemetry/tests/unit/test_TelemetryStorage.js
@@ -0,0 +1,65 @@
+/* Any copyright is dedicated to the Public Domain.
+ * http://creativecommons.org/publicdomain/zero/1.0/ */
+
+Cu.import("resource://gre/modules/TelemetryController.jsm", this);
+Cu.import("resource://gre/modules/TelemetrySession.jsm", this);
+Cu.import("resource://gre/modules/TelemetryStorage.jsm", this);
+Cu.import("resource://gre/modules/Services.jsm", this);
+Cu.import("resource://gre/modules/TelemetryUtils.jsm", this);
+
+const PING_TYPE_MAIN = "main";
+const REASON_GATHER_PAYLOAD = "gather-payload";
+
+function getPing() {
+  TelemetrySession.earlyInit(true);
+
+  const payload = TelemetrySession.getPayload(REASON_GATHER_PAYLOAD);
+  const options = {addClientId: true, addEnvironment: true};
+  return TelemetryController.testAssemblePing(PING_TYPE_MAIN, payload, options);
+}
+
+// Setting up test environment.
+
+add_task(function* test_setup() {
+  do_get_profile();
+});
+
+// Testing whether correct values are being recorded in
+// "TELEMETRY_PENDING_LOAD_MS" histogram.
+
+add_task(function* test_pendingLoadTime() {
+  TelemetryStorage.reset();
+  var ping = getPing();
+
+  var h = Telemetry.getHistogramById("TELEMETRY_PENDING_LOAD_MS");
+  var initialSum = h.snapshot().sum;
+
+  TelemetryStorage.addPendingPing(ping).then(() => {
+    TelemetryStorage.loadPendingPing(ping.id).then(() => {
+      TelemetryStorage.removePendingPing(ping.id);
+      Assert.ok(h.snapshot().sum - initialSum > 0,
+                "Value must be inserted into the histogram.");
+    });
+  });
+});
+
+// Testing whether correct values are being recorded in
+// "TELEMETRY_ARCHIVE_LOAD_MS" histogram.
+
+add_task(function* test_archiveLoadTime() {
+  TelemetryStorage.reset();
+
+  var ping = getPing();
+  var creationDate = new Date(ping.creationDate);
+
+  var h = Telemetry.getHistogramById("TELEMETRY_ARCHIVE_LOAD_MS");
+  var initialSum = h.snapshot().sum;
+
+  TelemetryStorage.saveArchivedPing(ping).then(() => {
+    TelemetryStorage.loadArchivedPing(ping.id).then(() => {
+      TelemetryStorage.removeArchivedPing(ping.id, creationDate, ping.type);
+      Assert.ok(h.snapshot().sum - initialSum > 0,
+                "Value must be inserted into the histogram.");
+    });
+  });
+});
--- a/toolkit/components/telemetry/tests/unit/xpcshell.ini
+++ b/toolkit/components/telemetry/tests/unit/xpcshell.ini
@@ -25,16 +25,17 @@ generated-files =
   extension.xpi
   extension-2.xpi
   system.xpi
   restartless.xpi
   theme.xpi
 
 [test_MigratePendingPings.js]
 [test_TelemetryHistograms.js]
+[test_TelemetryStorage.js]
 [test_SubsessionChaining.js]
 tags = addons
 [test_TelemetryEnvironment.js]
 skip-if = os == "android"
 tags = addons
 [test_PingAPI.js]
 skip-if = os == "android"
 [test_TelemetryFlagClear.js]