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 85264 383712b389bca5328f0c662e18d5afe49e2bd9ac
parent 85263 7030a479b0e3680993b5690352350f05ca7f7372
child 85265 680991750088895c293927b5c208a067ec20a984
push id5257
push usergsharp@mozilla.com
push dateTue, 24 Jan 2012 23:09:24 +0000
treeherdermozilla-inbound@383712b389bc [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewerszpao, taras
bugs717105
milestone12.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 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;
       }