Bug 965527 - More and more logging for OS.File AsyncShutdown. r=froydnj
☠☠ backed out by 6d0a341040a9 ☠ ☠
authorDavid Rajchenbach-Teller <dteller@mozilla.com>
Fri, 21 Mar 2014 08:57:08 -0400
changeset 174813 18f579c4308eab391b110a135678cef3764470f4
parent 174812 70ed331073017015d471a7a531a7da00cca6fc0f
child 174814 79617d6625f6a33d007092731886daa2c7136dff
push id1
push userroot
push dateMon, 20 Oct 2014 17:29:22 +0000
reviewersfroydnj
bugs965527
milestone31.0a1
Bug 965527 - More and more logging for OS.File AsyncShutdown. r=froydnj
toolkit/components/osfile/modules/osfile_async_front.jsm
--- a/toolkit/components/osfile/modules/osfile_async_front.jsm
+++ b/toolkit/components/osfile/modules/osfile_async_front.jsm
@@ -130,16 +130,57 @@ for (let [constProp, dirKey] of [
   });
 }
 
 /**
  * Return a shallow clone of the enumerable properties of an object.
  */
 let clone = SharedAll.clone;
 
+/**
+ * Extract a shortened version of an object, fit for logging.
+ *
+ * This function returns a copy of the original object in which all
+ * long strings, Arrays, TypedArrays, ArrayBuffers are removed and
+ * replaced with plceholders. Use this function to sanitize objects
+ * if you wish to log them or to keep them in memory.
+ *
+ * @param {*} obj The obj to shorten.
+ * @return {*} array A shorter object, fit for logging.
+ */
+function summarizeObject(obj) {
+  if (!obj) {
+    return null;
+  }
+  if (typeof obj == "string") {
+    if (obj.length > 1024) {
+      return {"Long string": obj.length};
+    }
+    return obj;
+  }
+  if (typeof obj == "object") {
+    if (Array.isArray(obj)) {
+      if (obj.length > 32) {
+        return {"Long array": obj.length};
+      }
+      return [summarizeObject(k) for (k of obj)];
+    }
+    if ("byteLength" in obj) {
+      // Assume TypedArray or ArrayBuffer
+      return {"Binary Data": obj.byteLength};
+    }
+    let result = {};
+    for (let k of Object.keys(obj)) {
+      result[k] = summarizeObject(obj[k]);
+    }
+    return result;
+  }
+  return obj;
+}
+
 let worker = null;
 let Scheduler = {
   /**
    * |true| once we have sent at least one message to the worker.
    * This field is unaffected by resetting the worker.
    */
   launched: false,
 
@@ -152,29 +193,51 @@ let Scheduler = {
   /**
    * A promise resolved once all operations are complete.
    *
    * This promise is never rejected and the result is always undefined.
    */
   queue: Promise.resolve(),
 
   /**
-   * The latest message sent and still waiting for a reply. In DEBUG
-   * builds, the entire message is stored, which may be memory-consuming.
-   * In non-DEBUG builds, only the method name is stored.
+   * Miscellaneous debugging information
    */
-  latestSent: undefined,
+  Debugging: {
+    /**
+     * The latest message sent and still waiting for a reply. In DEBUG
+     * builds, the entire message is stored, which may be memory-consuming.
+     * In non-DEBUG builds, only the method name is stored.
+     */
+    latestSent: undefined,
+
+    /**
+     * The latest reply received, or null if we are waiting for a reply.
+     * In DEBUG builds, the entire response is stored, which may be
+     * memory-consuming.  In non-DEBUG builds, only exceptions and
+     * method names are stored.
+     */
+    latestReceived: undefined,
 
-  /**
-   * The latest reply received, or null if we are waiting for a reply.
-   * In DEBUG builds, the entire response is stored, which may be
-   * memory-consuming.  In non-DEBUG builds, only exceptions and
-   * method names are stored.
-   */
-  latestReceived: undefined,
+    /**
+     * Number of messages sent to the worker. This includes the
+     * initial SET_DEBUG, if applicable.
+     */
+    messagesSent: 0,
+
+    /**
+     * Total number of messages ever queued, including the messages
+     * sent.
+     */
+    messagesQueued: 0,
+
+    /**
+     * Number of messages received from the worker.
+     */
+    messagesReceived: 0,
+  },
 
   /**
    * A timer used to automatically shut down the worker after some time.
    */
   resetTimer: null,
 
   restartTimer: function(arg) {
     let delay;
@@ -229,59 +292,62 @@ let Scheduler = {
         "resource://gre/modules/osfile/osfile_async_worker.js", LOG);
     }
     let firstLaunch = !this.launched;
     this.launched = true;
 
     if (firstLaunch && SharedAll.Config.DEBUG) {
       // If we have delayed sending SET_DEBUG, do it now.
       worker.post("SET_DEBUG", [true]);
+      Scheduler.Debugging.messagesSent++;
     }
 
     // By convention, the last argument of any message may be an |options| object.
     let options;
     let methodArgs = args[0];
     if (methodArgs) {
       options = methodArgs[methodArgs.length - 1];
     }
+    Scheduler.Debugging.messagesQueued++;
     return this.push(() => Task.spawn(function*() {
-      Scheduler.latestReceived = null;
-      if (OS.Constants.Sys.DEBUG) {
-        // Update possibly memory-expensive debugging information
-        Scheduler.latestSent = [Date.now(), method, ...args];
-      } else {
-        Scheduler.latestSent = [Date.now(), method];
-      }
+      // Update debugging information. As |args| may be quite
+      // expensive, we only keep a shortened version of it.
+      Scheduler.Debugging.latestReceived = null;
+      Scheduler.Debugging.latestSent = [Date.now(), method, summarizeObject(methodArgs)];
       let data;
       let reply;
       let isError = false;
       try {
-        data = yield worker.post(method, ...args);
+        try {
+          data = yield worker.post(method, ...args);
+        } finally {
+          Scheduler.Debugging.messagesReceived++;
+        }
         reply = data;
-      } catch (error if error instanceof PromiseWorker.WorkerError) {
+      } catch (error) {
         reply = error;
         isError = true;
-        throw EXCEPTION_CONSTRUCTORS[error.data.exn || "OSError"](error.data);
-      } catch (error if error instanceof ErrorEvent) {
-        reply = error;
-        let message = error.message;
-        if (message == "uncaught exception: [object StopIteration]") {
-          throw StopIteration;
+        if (error instanceof PromiseWorker.WorkerError) {
+          throw EXCEPTION_CONSTRUCTORS[error.data.exn || "OSError"](error.data);
         }
-        isError = true;
-        throw new Error(message, error.filename, error.lineno);
+        if (error instanceof ErrorEvent) {
+          let message = error.message;
+          if (message == "uncaught exception: [object StopIteration]") {
+            isError = false;
+            throw StopIteration;
+          }
+          throw new Error(message, error.filename, error.lineno);
+        }
+        throw ex;
       } finally {
-        Scheduler.latestSent = Scheduler.latestSent.slice(0, 2);
-        if (OS.Constants.Sys.DEBUG) {
-          // Update possibly memory-expensive debugging information
-          Scheduler.latestReceived = [Date.now(), reply];
-        } else if (isError) {
-          Scheduler.latestReceived = [Date.now(), reply.message, reply.fileName, reply.lineNumber];
+        Scheduler.Debugging.latestSent = Scheduler.Debugging.latestSent.slice(0, 2);
+        if (isError) {
+          Scheduler.Debugging.latestReceived = [Date.now(), reply.message, reply.fileName, reply.lineNumber];
         } else {
-          Scheduler.latestReceived = [Date.now()];
+          Scheduler.Debugging.latestReceived = [Date.now(), summarizeObject(reply)];
         }
         if (firstLaunch) {
           Scheduler._updateTelemetry();
         }
 
         // Don't restart the timer when reseting the worker, since that will
         // lead to an endless "resetWorker()" loop.
         if (method != "Meta_reset") {
@@ -1358,18 +1424,22 @@ AsyncShutdown.profileBeforeChange.addBlo
     }
   },
   function getDetails() {
     let result = {
       launched: Scheduler.launched,
       shutdown: Scheduler.shutdown,
       worker: !!worker,
       pendingReset: !!Scheduler.resetTimer,
-      latestSent: Scheduler.latestSent,
-      latestReceived: Scheduler.latestReceived
+      latestSent: Scheduler.Debugging.latestSent,
+      latestReceived: Scheduler.Debugging.latestReceived,
+      messagesSent: Scheduler.Debugging.messagesSent,
+      messagesReceived: Scheduler.Debugging.messagesReceived,
+      messagesQueued: Scheduler.Debugging.messagesQueued,
+      DEBUG: SharedAll.Config.DEBUG
     };
     // Convert dates to strings for better readability
     for (let key of ["latestSent", "latestReceived"]) {
       if (result[key] && typeof result[key][0] == "number") {
         result[key][0] = Date(result[key][0]);
       }
     }
     return result;