Bug 717105: add TelemetryTimestamps module to collect arbitrary timestamps with telemetry, and start using it for browser startup and sessionstore, r=zpao, r=taras
authorGavin Sharp <gavin@gavinsharp.com>
Tue, 10 Jan 2012 16:19:06 -0800
changeset 86508 383712b389bca5328f0c662e18d5afe49e2bd9ac
parent 86507 7030a479b0e3680993b5690352350f05ca7f7372
child 86509 680991750088895c293927b5c208a067ec20a984
push id805
push userakeybl@mozilla.com
push dateWed, 01 Feb 2012 18:17:35 +0000
treeherdermozilla-aurora@6fb3bf232436 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewerszpao, taras
bugs717105
milestone12.0a1
Bug 717105: add TelemetryTimestamps module to collect arbitrary timestamps with telemetry, and start using it for browser startup and sessionstore, r=zpao, r=taras
browser/base/content/browser.js
browser/components/sessionstore/src/nsSessionStore.js
browser/modules/Makefile.in
browser/modules/TelemetryTimestamps.jsm
browser/modules/test/Makefile.in
browser/modules/test/browser_TelemetryTimestamps.js
toolkit/components/telemetry/TelemetryPing.js
--- a/browser/base/content/browser.js
+++ b/browser/base/content/browser.js
@@ -1496,16 +1496,18 @@ function prepareForStartup() {
   gBrowser.addEventListener("MozApplicationManifest",
                             OfflineApps, false);
 
   // setup simple gestures support
   gGestureSupport.init(true);
 }
 
 function delayedStartup(isLoadingBlank, mustLoadSidebar) {
+  Cu.import("resource:///modules/TelemetryTimestamps.jsm");
+  TelemetryTimestamps.add("delayedStartupStarted");
   gDelayedStartupTimeoutId = null;
 
   Services.obs.addObserver(gSessionHistoryObserver, "browser:purge-session-history", false);
   Services.obs.addObserver(gXPInstallObserver, "addon-install-disabled", false);
   Services.obs.addObserver(gXPInstallObserver, "addon-install-started", false);
   Services.obs.addObserver(gXPInstallObserver, "addon-install-blocked", false);
   Services.obs.addObserver(gXPInstallObserver, "addon-install-failed", false);
   Services.obs.addObserver(gXPInstallObserver, "addon-install-complete", false);
@@ -1760,16 +1762,17 @@ function delayedStartup(isLoadingBlank, 
                                              Ci.nsIPrefLocalizedString).data)
     document.getElementById("appmenu_charsetMenu").hidden = true;
 #endif
 
   window.addEventListener("mousemove", MousePosTracker, false);
   window.addEventListener("dragover", MousePosTracker, false);
 
   Services.obs.notifyObservers(window, "browser-delayed-startup-finished", "");
+  TelemetryTimestamps.add("delayedStartupFinished");
 }
 
 function BrowserShutdown() {
   // In certain scenarios it's possible for unload to be fired before onload,
   // (e.g. if the window is being closed after browser.js loads but before the
   // load completes). In that case, there's nothing to do here.
   if (!gStartupRan)
     return;
--- a/browser/components/sessionstore/src/nsSessionStore.js
+++ b/browser/components/sessionstore/src/nsSessionStore.js
@@ -125,16 +125,18 @@ const TAB_EVENTS = ["TabOpen", "TabClose
 #define BROKEN_WM_Z_ORDER
 #endif
 
 Cu.import("resource://gre/modules/XPCOMUtils.jsm");
 Cu.import("resource://gre/modules/Services.jsm");
 // debug.js adds NS_ASSERT. cf. bug 669196
 Cu.import("resource://gre/modules/debug.js");
 
+Cu.import("resource:///modules/TelemetryTimestamps.jsm");
+
 XPCOMUtils.defineLazyGetter(this, "NetUtil", function() {
   Cu.import("resource://gre/modules/NetUtil.jsm");
   return NetUtil;
 });
 
 XPCOMUtils.defineLazyGetter(this, "ScratchpadManager", function() {
   Cu.import("resource:///modules/devtools/scratchpad-manager.jsm");
   return ScratchpadManager;
@@ -289,16 +291,17 @@ SessionStoreService.prototype = {
   },
 
 /* ........ Global Event Handlers .............. */
 
   /**
    * Initialize the component
    */
   initService: function() {
+    TelemetryTimestamps.add("sessionRestoreInitialized");
     OBSERVING.forEach(function(aTopic) {
       Services.obs.addObserver(this, aTopic, true);
     }, this);
 
     var pbs = Cc["@mozilla.org/privatebrowsing;1"].
               getService(Ci.nsIPrivateBrowsingService);
     this._inPrivateBrowsing = pbs.privateBrowsingEnabled;
 
@@ -828,24 +831,25 @@ SessionStoreService.prototype = {
 
     // and create its internal data object
     this._internalWindows[aWindow.__SSi] = { hosts: {} }
 
     if (!this._isWindowLoaded(aWindow))
       this._windows[aWindow.__SSi]._restoring = true;
     if (!aWindow.toolbar.visible)
       this._windows[aWindow.__SSi].isPopup = true;
-    
+
     // perform additional initialization when the first window is loading
     if (this._loadState == STATE_STOPPED) {
       this._loadState = STATE_RUNNING;
       this._lastSaveTime = Date.now();
       
       // restore a crashed session resp. resume the last session if requested
       if (this._initialState) {
+        TelemetryTimestamps.add("sessionRestoreRestoring");
         // make sure that the restored tabs are first in the window
         this._initialState._firstTabs = true;
         this._restoreCount = this._initialState.windows ? this._initialState.windows.length : 0;
         this.restoreWindow(aWindow, this._initialState,
                            this._isCmdLineEmpty(aWindow, this._initialState));
         delete this._initialState;
         
         // _loadState changed from "stopped" to "running"
--- a/browser/modules/Makefile.in
+++ b/browser/modules/Makefile.in
@@ -47,16 +47,17 @@ include $(topsrcdir)/config/config.mk
 ifdef ENABLE_TESTS
 DIRS += test
 endif
 
 EXTRA_JS_MODULES = \
 	openLocationLastURL.jsm \
 	NetworkPrioritizer.jsm \
 	offlineAppCache.jsm \
+	TelemetryTimestamps.jsm \
 	$(NULL)
 
 ifeq ($(MOZ_WIDGET_TOOLKIT),windows) 
 EXTRA_JS_MODULES += \
 	WindowsPreviewPerTab.jsm \
 	WindowsJumpLists.jsm \
 	$(NULL)
 endif
new file mode 100644
--- /dev/null
+++ b/browser/modules/TelemetryTimestamps.jsm
@@ -0,0 +1,26 @@
+/* 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/. */
+
+let EXPORTED_SYMBOLS = ["TelemetryTimestamps"];
+
+let TelemetryTimestamps = {
+  timeStamps: {},
+  add: function TT_add(name, value) {
+    // Default to "now" if not specified
+    if (value == null)
+      value = Date.now();
+
+    if (isNaN(value))
+      throw new Error("Value must be a timestamp");
+
+    // If there's an existing value, just ignore the new value.
+    if (this.timeStamps.hasOwnProperty(name))
+      return;
+
+    this.timeStamps[name] = value;
+  },
+  get: function TT_get() {
+    return JSON.parse(JSON.stringify(this.timeStamps));
+  }
+};
--- a/browser/modules/test/Makefile.in
+++ b/browser/modules/test/Makefile.in
@@ -40,16 +40,17 @@ srcdir		= @srcdir@
 VPATH		= @srcdir@
 relativesrcdir  = browser/modules/test
 
 include $(DEPTH)/config/autoconf.mk
 include $(topsrcdir)/config/rules.mk
 
 _BROWSER_FILES = \
                  browser_NetworkPrioritizer.js \
+                 browser_TelemetryTimestamps.js \
                  $(NULL)
 
 ifeq ($(MOZ_WIDGET_TOOLKIT),windows) 
 _BROWSER_FILES += \
                  browser_taskbar_preview.js \
                  $(NULL)
 endif
 
new file mode 100644
--- /dev/null
+++ b/browser/modules/test/browser_TelemetryTimestamps.js
@@ -0,0 +1,62 @@
+/* Any copyright is dedicated to the Public Domain.
+ * http://creativecommons.org/publicdomain/zero/1.0/ */
+
+function getSimpleMeasurementsFromTelemetryPing() {
+  const TelemetryPing = Cc["@mozilla.org/base/telemetry-ping;1"].getService(Ci.nsIObserver);
+  let str = Cc['@mozilla.org/supports-string;1'].createInstance(Ci.nsISupportsString);
+  TelemetryPing.observe(str, "get-payload", "");
+
+  return JSON.parse(str.data).simpleMeasurements;
+}
+
+function test() {
+  // Test the module logic
+  Cu.import("resource:///modules/TelemetryTimestamps.jsm");
+  let now = Date.now();
+  TelemetryTimestamps.add("foo");
+  let fooValue = TelemetryTimestamps.get().foo;
+  ok(fooValue, "foo was added");
+  ok(fooValue >= now, "foo has a reasonable value");
+
+  // Add timestamp with value
+  TelemetryTimestamps.add("bar", 1);
+  ok(TelemetryTimestamps.get().bar, "bar was added");
+  is(TelemetryTimestamps.get().bar, 1, "bar has the right value");
+
+  // Can't add the same timestamp twice
+  TelemetryTimestamps.add("bar", 2);
+  is(TelemetryTimestamps.get().bar, 1, "bar wasn't overwritten");
+
+  let threw = false;
+  try {
+    TelemetryTimestamps.add("baz", "this isn't a number");
+  } catch (ex) {
+    threw = true;
+  }
+  ok(threw, "adding baz threw");
+  ok(!TelemetryTimestamps.get().baz, "no baz was added");
+
+  // Test that the data gets added to the telemetry ping properly
+  let simpleMeasurements = getSimpleMeasurementsFromTelemetryPing();
+  ok(simpleMeasurements, "got simple measurements from ping data");
+  is(simpleMeasurements.foo, fooValue, "foo was included");
+  is(simpleMeasurements.bar, 1, "bar was included");
+  ok(!simpleMeasurements.baz, "baz wasn't included since it wasn't added");
+
+  // Check browser timestamps that we add
+  let props = [
+    // These can't be reliably tested when the test is run alone
+    //"delayedStartupStarted",
+    //"delayedStartupFinished",
+    "sessionRestoreInitialized",
+    // This doesn't get hit in the testing profile
+    //"sessionRestoreRestoring"
+  ];
+
+  props.forEach(function (p) {
+    let value = simpleMeasurements[p];
+    ok(value, p + " exists");
+    ok(!isNaN(value), p + " is a number");
+    ok(value > 0 && value < Date.now(), p + " value is reasonable");
+  });
+}
--- a/toolkit/components/telemetry/TelemetryPing.js
+++ b/toolkit/components/telemetry/TelemetryPing.js
@@ -116,16 +116,29 @@ function getSimpleMeasurements() {
     }
   }
   ret.startupInterrupted = new Number(Services.startup.interrupted);
 
   ret.js = Cc["@mozilla.org/js/xpc/XPConnect;1"]
            .getService(Ci.nsIJSEngineTelemetryStats)
            .telemetryValue;
 
+  // Look for app-specific timestamps
+  var appTimestamps = {};
+  try {
+    let o = {};
+    Cu.import("resource:///modules/TelemetryTimestamps.jsm", o);
+    appTimestamps = o.TelemetryTimestamps.get();
+  } catch (ex) {}
+
+  for (let p in appTimestamps) {
+    if (!(p in ret) && appTimestamps[p])
+      ret[p] = appTimestamps[p];
+  }
+
   return ret;
 }
 
 function TelemetryPing() {}
 
 TelemetryPing.prototype = {
   _histograms: {},
   _initialized: false,
@@ -177,20 +190,20 @@ TelemetryPing.prototype = {
       // add an upper bound
       if (last && last < c.length)
         retgram.values[r[last]] = 0;
       ret[name] = retgram;
     };
 
     for (let name in hls) {
       if (info[name]) {
-	processHistogram(name, hls[name]);
-	let startup_name = "STARTUP_" + name;
-	if (hls[startup_name])
-	  processHistogram(startup_name, hls[startup_name]);
+        processHistogram(name, hls[name]);
+        let startup_name = "STARTUP_" + name;
+        if (hls[startup_name])
+          processHistogram(startup_name, hls[startup_name]);
       }
     }
 
     return ret;
   },
 
   addValue: function addValue(name, id, val) {
     let h = this._histograms[name];
@@ -368,30 +381,30 @@ TelemetryPing.prototype = {
     // Use a deterministic url for testing.
     let isTestPing = (reason == "test-ping");
     let havePreviousSession = !!this._prevSession;
     let slug = (isTestPing
                 ? reason
                 : (havePreviousSession
                    ? this._prevSession.uuid
                    : this._uuid));
-    let payload = {
+    let payloadObj = {
       ver: PAYLOAD_VERSION,
       // Send a different reason string for previous session data.
       info: this.getMetadata(havePreviousSession ? "saved-session" : reason),
     };
     if (havePreviousSession) {
-      payload.histograms = this.getHistograms(this._prevSession.snapshots);
+      payloadObj.histograms = this.getHistograms(this._prevSession.snapshots);
     }
     else {
-      payload.simpleMeasurements = getSimpleMeasurements();
-      payload.histograms = this.getHistograms(Telemetry.histogramSnapshots);
-      payload.slowSQL = Telemetry.slowSQL;
+      payloadObj.simpleMeasurements = getSimpleMeasurements();
+      payloadObj.histograms = this.getHistograms(Telemetry.histogramSnapshots);
+      payloadObj.slowSQL = Telemetry.slowSQL;
     }
-    return { previous: !!havePreviousSession, slug: slug, payload: payload };
+    return { previous: !!havePreviousSession, slug: slug, payload: JSON.stringify(payloadObj) };
   },
 
   doPing: function doPing(server, slug, payload, recordSuccess) {
     let submitPath = "/submit/telemetry/" + slug;
     let url = server + submitPath;
     let request = Cc["@mozilla.org/xmlextras/xmlhttprequest;1"]
                   .createInstance(Ci.nsIXMLHttpRequest);
     request.mozBackgroundRequest = true;
@@ -419,17 +432,17 @@ TelemetryPing.prototype = {
         file.remove(true);
       }
       if (slug == "test-ping")
         Services.obs.notifyObservers(null, "telemetry-test-xhr-complete", null);
     }
     request.addEventListener("error", function(aEvent) finishRequest(request.channel), false);
     request.addEventListener("load", function(aEvent) finishRequest(request.channel), false);
 
-    request.send(JSON.stringify(payload));
+    request.send(payload);
   },
   
   attachObservers: function attachObservers() {
     if (!this._initialized)
       return;
     Services.obs.addObserver(this, "cycle-collector-begin", false);
     Services.obs.addObserver(this, "idle-daily", false);
   },
@@ -559,16 +572,22 @@ TelemetryPing.prototype = {
       Services.tm.mainThread.dispatch((function() {
         // Notify that data should be gathered now, since ping will happen soon.
         Services.obs.notifyObservers(null, "gather-telemetry", null);
         // The ping happens at the first idle of length IDLE_TIMEOUT_SECONDS.
         idleService.addIdleObserver(this, IDLE_TIMEOUT_SECONDS);
         this._isIdleObserver = true;
       }).bind(this), Ci.nsIThread.DISPATCH_NORMAL);
       break;
+    case "get-payload":
+      this.gatherMemory();
+      let data = this.getSessionPayloadAndSlug("gather-payload");
+
+      aSubject.QueryInterface(Ci.nsISupportsString).data = data.payload;
+      break;
     case "test-ping":
       server = aData;
       // fall through
     case "idle":
       if (this._isIdleObserver) {
         idleService.removeIdleObserver(this, IDLE_TIMEOUT_SECONDS);
         this._isIdleObserver = false;
       }