Bug 1164886 - Add optional logging for async shutdown barriers. r=Yoric
authorOliver Henshaw <oliver.henshaw@gmail.com>
Thu, 04 Jun 2015 07:01:00 -0400
changeset 248024 68e277743ff810d09a0998b8f1915e87c6909eb2
parent 248023 d7ed7208e7f432758f5d3cff1b158417744fcfaa
child 248025 080dc5cf291050ba86a0294802bdc86b064af915
push id60888
push userkwierso@gmail.com
push dateThu, 11 Jun 2015 01:38:38 +0000
treeherdermozilla-inbound@39e638ed06bf [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersYoric
bugs1164886
milestone41.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 1164886 - Add optional logging for async shutdown barriers. r=Yoric
modules/libpref/init/all.js
toolkit/components/asyncshutdown/AsyncShutdown.jsm
--- a/modules/libpref/init/all.js
+++ b/modules/libpref/init/all.js
@@ -787,16 +787,18 @@ pref("toolkit.telemetry.debugSlowSql", f
 pref("toolkit.telemetry.unified", true);
 
 // Identity module
 pref("toolkit.identity.enabled", false);
 pref("toolkit.identity.debug", false);
 
 // AsyncShutdown delay before crashing in case of shutdown freeze
 pref("toolkit.asyncshutdown.timeout.crash", 60000);
+// Extra logging for AsyncShutdown barriers and phases
+pref("toolkit.asyncshutdown.log", false);
 
 // Enable deprecation warnings.
 pref("devtools.errorconsole.deprecation_warnings", true);
 
 // Disable debugging chrome
 #ifdef MOZ_DEV_EDITION
 sticky_pref("devtools.chrome.enabled", true);
 #else
--- a/toolkit/components/asyncshutdown/AsyncShutdown.jsm
+++ b/toolkit/components/asyncshutdown/AsyncShutdown.jsm
@@ -191,16 +191,32 @@ function log(msg, prefix = "", error = n
   dump(prefix + msg + "\n");
   if (error) {
     dump(prefix + error + "\n");
     if (typeof error == "object" && "stack" in error) {
       dump(prefix + error.stack + "\n");
     }
   }
 }
+const PREF_DEBUG_LOG = "toolkit.asyncshutdown.log";
+let DEBUG_LOG = false;
+try {
+  DEBUG_LOG = Services.prefs.getBoolPref(PREF_DEBUG_LOG);
+} catch (ex) {
+  // Ignore errors
+}
+Services.prefs.addObserver(PREF_DEBUG_LOG, function() {
+  DEBUG_LOG = Services.prefs.getBoolPref(PREF_DEBUG_LOG);
+}, false);
+
+function debug(msg, error=null) {
+  if (DEBUG_LOG) {
+    return log(msg, "DEBUG: ", error);
+  }
+}
 function warn(msg, error = null) {
   return log(msg, "WARNING: ", error);
 }
 function fatalerr(msg, error = null) {
   return log(msg, "FATAL ERROR: ", error);
 }
 
 // Utility function designed to get the current state of execution
@@ -506,16 +522,17 @@ Spinner.prototype = {
       try {
         thread.processNextEvent(true);
       } catch (ex) {
         // An uncaught error should not stop us, but it should still
         // be reported and cause tests to fail.
         Promise.reject(ex);
       }
     }
+    debug(`Finished phase ${ topic }`);
   }
 };
 
 /**
  * A mechanism used to register blockers that prevent some action from
  * happening.
  *
  * An instance of |Barrier| provides a capability |client| that
@@ -639,16 +656,17 @@ function Barrier(name) {
         details = {};
       }
       if (typeof details != "object") {
         throw new TypeError("Expected an object as third argument to `addBlocker`, got " + details);
       }
       if (!this._waitForMe) {
         throw new Error(`Phase "${ this._name } is finished, it is too late to register completion condition "${ name }"`);
       }
+      debug(`Adding blocker ${ name } for phase ${ this._name }`);
 
       // Normalize the details
 
       let fetchState = details.fetchState || null;
       let filename = details.filename || null;
       let lineNumber = details.lineNumber || null;
       let stack = details.stack || null;
 
@@ -706,19 +724,20 @@ function Barrier(name) {
 
       this._waitForMe.add(promise);
       this._promiseToBlocker.set(promise, blocker);
       this._conditionToPromise.set(condition, promise);
 
       // As conditions may hold lots of memory, we attempt to cleanup
       // as soon as we are done (which might be in the next tick, if
       // we have been passed a resolved promise).
-      promise = promise.then(() =>
-        this._removeBlocker(condition)
-      );
+      promise = promise.then(() => {
+        debug(`Completed blocker ${ name } for phase ${ this._name }`);
+        this._removeBlocker(condition);
+      });
 
       if (this._isStarted) {
         // The wait has already started. The blocker should be
         // notified asap. We do it out of band as clients probably
         // expect `addBlocker` to return immediately.
         Promise.resolve().then(trigger);
       }
     },