Bug 1107329 - Add locks tasks queue vivacity checking. r=qdot

To help diagnosing further issues with the Settings API getting blocked,
we add some tracking of the tasks and locks queue vivacity. We ensure to
keep track of the last lock id at the head of the queue, and we verify
whether it does not stays on top of it for too long.

dom/settings/SettingsManager.js

@@ -69,7 +69,8 @@ function SettingsLock(aSettingsManager) {
   let createLockPayload = {
     lockID: this._id,
     isServiceLock: false,
-    windowID: this._settingsManager.innerWindowID
+    windowID: this._settingsManager.innerWindowID,
+    lockStack: (new Error).stack
   };
   this.sendMessage("Settings:CreateLock", createLockPayload);
   Services.tm.currentThread.dispatch(this._closeHelper.bind(this), Ci.nsIThread.DISPATCH_NORMAL);

dom/settings/SettingsRequestManager.jsm

@@ -52,6 +52,8 @@ const kAllSettingsWritePermission      = "settings" + kSettingsWriteSuffix;
 // will be allowed depends on the exact permissions the app has.
 const kSomeSettingsReadPermission      = "settings-api" + kSettingsReadSuffix;
 const kSomeSettingsWritePermission     = "settings-api" + kSettingsWriteSuffix;
+// Time, in seconds, to consider the API is starting to jam
+const kSoftLockupDelta                 = 30;
 
 XPCOMUtils.defineLazyServiceGetter(this, "mrm",
                                    "@mozilla.org/memory-reporter-manager;1",
@@ -99,7 +101,7 @@ let SettingsPermissions = {
 };
 
 
-function SettingsLockInfo(aDB, aMsgMgr, aPrincipal, aLockID, aIsServiceLock, aWindowID) {
+function SettingsLockInfo(aDB, aMsgMgr, aPrincipal, aLockID, aIsServiceLock, aWindowID, aLockStack) {
   return {
     // ID Shared with the object on the child side
     lockID: aLockID,
@@ -107,6 +109,8 @@ function SettingsLockInfo(aDB, aMsgMgr, aPrincipal, aLockID, aIsServiceLock, aWi
     isServiceLock: aIsServiceLock,
     // Which inner window ID
     windowID: aWindowID,
+    // Where does this lock comes from
+    lockStack: aLockStack,
     // Tasks to be run once the lock is at the head of the queue
     tasks: [],
     // This is set to true once a transaction is ready to run, but is not at the
@@ -200,6 +204,11 @@ let SettingsRequestManager = {
              "Settings:CreateLock", "Settings:RegisterForMessages"],
   // Map of LockID to SettingsLockInfo objects
   lockInfo: {},
+  // Storing soft lockup detection infos
+  softLockup: {
+    lockId: null, // last lock dealt with
+    lockTs: null  // last time of dealing with
+  },
   // Queue of LockIDs. The LockID on the front of the queue is the only lock
   // that will have requests processed, all other locks will queue requests
   // until they hit the front of the queue.
@@ -742,6 +751,7 @@ let SettingsRequestManager = {
     this.ensureConnection().then(
       function(task) {
         this.runTasks(lockID);
+        this.updateSoftLockup(lockID);
       }.bind(this), function(ret) {
         dump("-*- SettingsRequestManager: SETTINGS DATABASE ERROR: Cannot make DB connection!\n");
     });
@@ -906,20 +916,20 @@ let SettingsRequestManager = {
   removeLock: function(aLockID) {
     if (VERBOSE) debug("Removing lock " + aLockID);
     if (this.lockInfo[aLockID]) {
-    let transaction = this.lockInfo[aLockID]._transaction;
-    if (transaction) {
-      try {
-        transaction.abort();
-      } catch (e) {
-        if (e.name == "InvalidStateError") {
-          if (VERBOSE) debug("Transaction for " + aLockID + " closed already");
-        } else {
-          if (DEBUG) debug("Unexpected exception, throwing: " + e);
-          throw e;
+      let transaction = this.lockInfo[aLockID]._transaction;
+      if (transaction) {
+        try {
+          transaction.abort();
+        } catch (e) {
+          if (e.name == "InvalidStateError") {
+            if (VERBOSE) debug("Transaction for " + aLockID + " closed already");
+          } else {
+            if (DEBUG) debug("Unexpected exception, throwing: " + e);
+            throw e;
+          }
         }
       }
-    }
-    delete this.lockInfo[aLockID];
+      delete this.lockInfo[aLockID];
     }
     let index = this.settingsLockQueue.indexOf(aLockID);
     if (index > -1) {
@@ -983,6 +993,42 @@ let SettingsRequestManager = {
     }
   },
 
+  updateSoftLockup: function(aLockId) {
+    if (VERBOSE) debug("Treating lock " + aLockId + ", so updating soft lockup infos ...");
+
+    this.softLockup = {
+      lockId: aLockId,
+      lockTs: new Date()
+    };
+  },
+
+  checkSoftLockup: function() {
+    if (VERBOSE) debug("Checking for soft lockup ...");
+
+    if (this.settingsLockQueue.length === 0) {
+      if (VERBOSE) debug("Empty settings lock queue, no soft lockup ...");
+      return;
+    }
+
+    let head = this.settingsLockQueue[0];
+    if (head !== this.softLockup.lockId) {
+      if (VERBOSE) debug("Non matching head of settings lock queue, no soft lockup ...");
+      return;
+    }
+
+    let delta = (new Date() - this.softLockup.lockTs) / 1000;
+    if (delta < kSoftLockupDelta) {
+      if (VERBOSE) debug("Matching head of settings lock queue, but delta (" + delta + ") < 30 secs, no soft lockup ...");
+      return;
+    }
+
+    let msgBlocked = "Settings queue head blocked at " + head +
+                     " for " + delta + " secs, Settings API may be soft lockup. Lock from: " +
+                     this.lockInfo[head].lockStack;
+    Cu.reportError(msgBlocked);
+    if (DEBUG) debug(msgBlocked);
+  },
+
   receiveMessage: function(aMessage) {
     if (VERBOSE) debug("receiveMessage " + aMessage.name + ": " + JSON.stringify(aMessage.data));
 
@@ -1008,6 +1054,7 @@ let SettingsRequestManager = {
       case "Settings:Clear":
       case "Settings:Run":
       case "Settings:Finalize":
+        this.checkSoftLockup();
         let kill_process = false;
         if (!msg.lockID) {
           Cu.reportError("Process sending request for lock that does not exist. Killing.");
@@ -1061,13 +1108,19 @@ let SettingsRequestManager = {
           aMessage.target.assertPermission("lock-id-duplicate-kill");
           return;
         }
+
+        if (this.softLockup.lockId === null) {
+          this.updateSoftLockup(msg.lockID);
+        }
+
         this.settingsLockQueue.push(msg.lockID);
         this.lockInfo[msg.lockID] = SettingsLockInfo(this.settingsDB,
                                                      mm,
                                                      aMessage.principal,
                                                      msg.lockID,
                                                      msg.isServiceLock,
-                                                     msg.windowID);
+                                                     msg.windowID,
+                                                     msg.lockStack);
         break;
       case "Settings:Get":
         if (VERBOSE) debug("Received getRequest from " + msg.lockID);

dom/settings/SettingsService.js

@@ -73,10 +73,14 @@ function SettingsServiceLock(aSettingsService, aTransactionCallback) {
     cpmm.addMessageListener(msgs[msg], this);
   }
 
+  let createLockPayload = {
+    lockID: this._id,
+    isServiceLock: true,
+    windowID: undefined,
+    lockStack: (new Error).stack
+  };
   cpmm.sendAsyncMessage("Settings:CreateLock",
-                        { lockID: this._id,
-                          isServiceLock: true,
-                          windowID: undefined },
+                        createLockPayload,
                         undefined,
                         Services.scriptSecurityManager.getSystemPrincipal());
   Services.tm.currentThread.dispatch(closeHelper, Ci.nsIThread.DISPATCH_NORMAL);