Bug 1255745 - Make Experiments AsyncShutdown state data more useful. r=dexter, a=lizzard
authorGeorg Fritzsche <georg.fritzsche@googlemail.com>
Thu, 17 Mar 2016 14:03:49 +0100
changeset 323737 d6e5c2d3afe9105fabb817744788dbc08f13543a
parent 323736 c9d25791f8219540e527c3d18aa919418fff4061
child 323738 c8d83343c57b7c139b449d3ba106f741d60ce650
push id5913
push userjlund@mozilla.com
push dateMon, 25 Apr 2016 16:57:49 +0000
treeherdermozilla-beta@dcaf0a6fa115 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersdexter, lizzard
bugs1255745
milestone47.0a2
Bug 1255745 - Make Experiments AsyncShutdown state data more useful. r=dexter, a=lizzard * Make Experiments AsyncShutdown state add the time to the log entries. * Fix other AsyncShutdown state issues. * We were not adding forensic log entries of ExperimentEntry before, added that to be able to narrow this down more. * This also increases the forensic log a bit to account for the additional entries and removes some unneeded big data addition to the logging.
browser/experiments/Experiments.jsm
--- a/browser/experiments/Experiments.jsm
+++ b/browser/experiments/Experiments.jsm
@@ -318,21 +318,20 @@ Experiments.Experiments = function (poli
   let log = Log.repository.getLoggerWithMessagePrefix(
       "Browser.Experiments.Experiments",
       "Experiments #" + gExperimentsCounter++ + "::");
 
   // At the time of this writing, Experiments.jsm has severe
   // crashes. For forensics purposes, keep the last few log
   // messages in memory and upload them in case of crash.
   this._forensicsLogs = [];
-  this._forensicsLogs.length = 20;
+  this._forensicsLogs.length = 30;
   this._log = Object.create(log);
   this._log.log = (level, string, params) => {
-    this._forensicsLogs.shift();
-    this._forensicsLogs.push(level + ": " + string);
+    this._addToForensicsLog("Experiments", string);
     log.log(level, string, params);
   };
 
   this._log.trace("constructor");
 
   // Capture the latest error, for forensics purposes.
   this._latestError = null;
 
@@ -459,55 +458,64 @@ Experiments.Experiments.prototype = {
 	  // pass
 	}
       }
       try {
         this._log.trace("uninit: waiting on _mainTask");
         yield this._mainTask;
       } catch (e) {
         // We error out of tasks after shutdown via this exception.
+        this._log.trace(`uninit: caught error - ${e}`);
         if (!(e instanceof AlreadyShutdownError)) {
           this._latestError = e;
           throw e;
         }
       }
     }
 
     this._log.info("Completed uninitialization.");
   }),
 
   // Return state information, for debugging purposes.
   _getState: function() {
+    let activeExperiment = this._getActiveExperiment();
     let state = {
       isShutdown: this._shutdown,
       isEnabled: gExperimentsEnabled,
       isRefresh: this._refresh,
       isDirty: this._dirty,
       isFirstEvaluate: this._firstEvaluate,
       hasLoadTask: !!this._loadTask,
       hasMainTask: !!this._mainTask,
       hasTimer: !!this._hasTimer,
       hasAddonProvider: !!gAddonProvider,
       latestLogs: this._forensicsLogs,
-      experiments: this._experiments ? this._experiments.keys() : null,
+      experiments: this._experiments ? [...this._experiments.keys()] : null,
       terminateReason: this._terminateReason,
+      activeExperiment: !!activeExperiment ? activeExperiment.id : null,
     };
     if (this._latestError) {
       if (typeof this._latestError == "object") {
         state.latestError = {
           message: this._latestError.message,
           stack: this._latestError.stack
         };
       } else {
         state.latestError = "" + this._latestError;
       }
     }
     return state;
   },
 
+  _addToForensicsLog: function (what, string) {
+    this._forensicsLogs.shift();
+    let timeInSec = Math.floor(Services.telemetry.msSinceProcessStart() / 1000);
+    this._forensicsLogs.push(`${timeInSec}: ${what} - ${string}`);
+  },
+
   _registerWithAddonManager: function (previousExperimentsProvider) {
     this._log.trace("Registering instance with Addon Manager.");
 
     AddonManager.addAddonListener(this);
     AddonManager.addInstallListener(this);
 
     if (!gAddonProvider) {
       // The properties of this AddonType should be kept in sync with the
@@ -1351,19 +1359,26 @@ Experiments.Experiments.prototype = {
 
 
 /*
  * Represents a single experiment.
  */
 
 Experiments.ExperimentEntry = function (policy) {
   this._policy = policy || new Experiments.Policy();
-  this._log = Log.repository.getLoggerWithMessagePrefix(
+  let log = Log.repository.getLoggerWithMessagePrefix(
     "Browser.Experiments.Experiments",
     "ExperimentEntry #" + gExperimentEntryCounter++ + "::");
+  this._log = Object.create(log);
+  this._log.log = (level, string, params) => {
+    if (gExperiments) {
+      gExperiments._addToForensicsLog("ExperimentEntry", string);
+    }
+    log.log(level, string, params);
+  };
 
   // Is the experiment supposed to be running.
   this._enabled = false;
   // When this experiment was started, if ever.
   this._startDate = null;
   // When this experiment was ended, if ever.
   this._endDate = null;
   // The condition data from the manifest.
@@ -1620,18 +1635,17 @@ Experiments.ExperimentEntry.prototype = 
     let data = this._manifestData;
 
     let now = this._policy.now() / 1000; // The manifest times are in seconds.
     let minActive = MIN_EXPERIMENT_ACTIVE_SECONDS;
     let maxActive = data.maxActiveSeconds || 0;
     let startSec = (this.startDate || 0) / 1000;
 
     this._log.trace("isApplicable() - now=" + now
-                    + ", randomValue=" + this._randomValue
-                    + ", data=" + JSON.stringify(this._manifestData));
+                    + ", randomValue=" + this._randomValue);
 
     // Not applicable if it already ran.
 
     if (!this.enabled && this._endDate) {
       return Promise.reject(["was-active"]);
     }
 
     // Define and run the condition checks.