Bug 848278 - Add an |outExecutionDuration| option to all osfile operations that support options argument. It will be udpated with the actual time it took to perform the operation off the main thread. r=yoric
authorYura Zenevich <yura.zenevich@gmail.com>
Tue, 19 Mar 2013 09:23:59 -0400
changeset 125396 3196b8bf8142ef3128981e3a6d8cfe090eb603cf
parent 125395 de2a0438c81bb9dbed05849386c1bf24e9571f82
child 125397 5c85be98a0a07568cad5ac0ec72e3511154aed0d
push id24910
push userryanvm@gmail.com
push dateTue, 19 Mar 2013 13:23:57 +0000
treeherdermozilla-inbound@63fe98eac1b2 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersyoric
bugs848278
milestone22.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 848278 - Add an |outExecutionDuration| option to all osfile operations that support options argument. It will be udpated with the actual time it took to perform the operation off the main thread. r=yoric
toolkit/components/osfile/_PromiseWorker.jsm
toolkit/components/osfile/osfile_async_front.jsm
toolkit/components/osfile/osfile_async_worker.js
toolkit/components/osfile/tests/mochi/main_test_osfile_async.js
--- a/toolkit/components/osfile/_PromiseWorker.jsm
+++ b/toolkit/components/osfile/_PromiseWorker.jsm
@@ -110,29 +110,33 @@ PromiseWorker.prototype = {
      * Messages must have one of the following shapes:
      * - {ok: some_value} in case of success
      * - {fail: some_error} in case of error, where
      *    some_error is an instance of |PromiseWorker.WorkerError|
      *
      * Messages may also contain a field |id| to help
      * with debugging.
      *
+     * Messages may also optionally contain a field |durationMs|, holding
+     * the duration of the function call in milliseconds.
+     *
      * @param {*} msg The message received from the worker.
      */
     worker.onmessage = function onmessage(msg) {
       self._log("Received message from worker", msg.data);
       let handler = self._queue.pop();
       let deferred = handler.deferred;
       let data = msg.data;
       if (data.id != handler.id) {
         throw new Error("Internal error: expecting msg " + handler.id + ", " +
                         " got " + data.id + ": " + JSON.stringify(msg.data));
       }
       if ("ok" in data) {
-        deferred.resolve(data.ok);
+        // Pass the data to the listeners.
+        deferred.resolve(data);
       } else if ("StopIteration" in data) {
         // We have received a StopIteration error
         deferred.reject(StopIteration);
       } if ("fail" in data) {
         // We have received an error that was serialized by the
         // worker.
         deferred.reject(new PromiseWorker.WorkerError(data.fail));
       }
--- a/toolkit/components/osfile/osfile_async_front.jsm
+++ b/toolkit/components/osfile/osfile_async_front.jsm
@@ -64,43 +64,89 @@ if (!("profileDir" in OS.Constants.Path)
 
     let localProfileDir = Services.dirsvc.get("ProfLD", Components.interfaces.nsIFile).path;
     OS.Constants.Path.localProfileDir = localProfileDir;
   };
   Services.obs.addObserver(observer, "profile-do-change", false);
 }
 
 /**
+ * A global constant used as a default refs parameter value when cloning.
+ */
+const noRefs = [];
+
+/**
  * Return a shallow clone of the enumerable properties of an object.
  *
- * We use this whenever normalizing options requires making (shallow)
+ * Utility used whenever normalizing options requires making (shallow)
  * changes to an option object. The copy ensures that we do not modify
  * a client-provided object by accident.
+ *
+ * Note: to reference and not copy specific fields, provide an optional
+ * |refs| argument containing their names.
+ *
+ * @param {JSON} object Options to be cloned.
+ * @param {Array} refs An optional array of field names to be passed by
+ * reference instead of copying.
  */
-let clone = function clone(object) {
+let clone = function clone(object, refs = noRefs) {
   let result = {};
+  // Make a reference between result[key] and object[key].
+  let refer = function refer(result, key, object) {
+    Object.defineProperty(result, key, {
+        enumerable: true,
+        get: function() {
+            return object[key];
+        },
+        set: function(value) {
+            object[key] = value;
+        }
+    });
+  };
   for (let k in object) {
-    result[k] = object[k];
+    if (refs.indexOf(k) < 0) {
+      result[k] = object[k];
+    } else {
+      refer(result, k, object);
+    }
   }
   return result;
 };
 
 /**
  * A shared constant used to normalize a set of options to nothing.
  */
 const noOptions = {};
 
-
 let worker = new PromiseWorker(
   "resource://gre/modules/osfile/osfile_async_worker.js", LOG);
 let Scheduler = {
   post: function post(...args) {
     let promise = worker.post.apply(worker, args);
     return promise.then(
-      null,
+      function onSuccess(data) {
+        // Check for duration and return result.
+        let methodArgs = args[1];
+        if (!methodArgs) {
+          return data.ok;
+        }
+        let options = methodArgs[methodArgs.length - 1];
+        // Check for options.outExecutionDuration.
+        if (typeof options !== "object" ||
+          !("outExecutionDuration" in options)) {
+          return data.ok;
+        }
+        // If data.durationMs is not present, return data.ok (there was an
+        // exception applying the method).
+        if (!("durationMs" in data)) {
+          return data.ok;
+        }
+        options.outExecutionDuration = data.durationMs;
+        return data.ok;
+      },
       function onError(error) {
         // Decode any serialized error
         if (error instanceof PromiseWorker.WorkerError) {
           throw OS.File.Error.fromMsg(error.data);
         } else {
           throw error;
         }
       }
@@ -222,17 +268,19 @@ File.prototype = {
    * @resolves {number} The number of bytes effectively read.
    * @rejects {OS.File.Error}
    */
   readTo: function readTo(buffer, options) {
     // If |buffer| is a typed array and there is no |bytes| options, we
     // need to extract the |byteLength| now, as it will be lost by
     // communication
     if (isTypedArray(buffer) && (!options || !"bytes" in options)) {
-      options = clone(options || noOptions);
+      // Preserve the reference to |outExecutionDuration| option if it is
+      // passed.
+      options = clone(options || noOptions, ["outExecutionDuration"]);
       options.bytes = buffer.byteLength;
     }
     // Note: Type.void_t.out_ptr.toMsg ensures that
     // - the buffer is effectively shared (not neutered) between both
     //   threads;
     // - we take care of any |byteOffset|.
     return Scheduler.post("File_prototype_readTo",
       [this._fdmsg,
@@ -258,17 +306,19 @@ File.prototype = {
    *
    * @return {number} The number of bytes actually written.
    */
   write: function write(buffer, options) {
     // If |buffer| is a typed array and there is no |bytes| options,
     // we need to extract the |byteLength| now, as it will be lost
     // by communication
     if (isTypedArray(buffer) && (!options || !"bytes" in options)) {
-      options = clone(options || noOptions);
+      // Preserve the reference to |outExecutionDuration| option if it is
+      // passed.
+      options = clone(options || noOptions, ["outExecutionDuration"]);
       options.bytes = buffer.byteLength;
     }
     // Note: Type.void_t.out_ptr.toMsg ensures that
     // - the buffer is effectively shared (not neutered) between both
     //   threads;
     // - we take care of any |byteOffset|.
     return Scheduler.post("File_prototype_write",
       [this._fdmsg,
@@ -552,18 +602,19 @@ File.exists = function exists(path) {
  * device is disconnected or removed before the buffer is flushed, the
  * file may be corrupted.
  *
  *
  * @return {promise}
  * @resolves {number} The number of bytes actually written.
  */
 File.writeAtomic = function writeAtomic(path, buffer, options) {
-  // Copy |options| to avoid modifying the original object
-  options = clone(options || noOptions);
+  // Copy |options| to avoid modifying the original object but preserve the
+  // reference to |outExecutionDuration| option if it is passed.
+  options = clone(options || noOptions, ["outExecutionDuration"]);
   // As options.tmpPath is a path, we need to encode it as |Type.path| message
   if ("tmpPath" in options) {
     options.tmpPath = Type.path.toMsg(options.tmpPath);
   };
   if (isTypedArray(buffer) && (!("bytes" in options))) {
     options.bytes = buffer.byteLength;
   };
   // Note: Type.void_t.out_ptr.toMsg ensures that
--- a/toolkit/components/osfile/osfile_async_worker.js
+++ b/toolkit/components/osfile/osfile_async_worker.js
@@ -27,36 +27,53 @@ if (this.Components) {
       * {ok: result, id:id} / {fail: serialized_form_of_OS.File.Error, id:id}
       */
      self.onmessage = function onmessage(msg) {
        let data = msg.data;
        LOG("Received message", data);
        let id = data.id;
        let result;
        let exn;
+       let durationMs;
        try {
          let method = data.fun;
          LOG("Calling method", method);
+         let start;
+         let options;
+         if (data.args) {
+           options = data.args[data.args.length - 1];
+         }
+         // If |outExecutionDuration| option was supplied, start measuring the
+         // duration of the operation.
+         if (typeof options === "object" && "outExecutionDuration" in options) {
+           start = Date.now();
+         }
          result = Agent[method].apply(Agent, data.args);
+         if (start) {
+           // Only record duration if the method succeeds.
+           durationMs = Date.now() - start;
+           LOG("Method took", durationMs, "MS");
+         }
          LOG("Method", method, "succeeded");
        } catch (ex) {
          exn = ex;
          LOG("Error while calling agent method", exn, exn.stack);
        }
        // Now, post a reply, possibly as an uncaught error.
        // We post this message from outside the |try ... catch| block
        // to avoid capturing errors that take place during |postMessage| and
        // built-in serialization.
        if (!exn) {
          LOG("Sending positive reply", result, "id is", id);
          if (result instanceof Transfer) {
            // Take advantage of zero-copy transfers
-           self.postMessage({ok: result.data, id: id}, result.transfers);
+           self.postMessage({ok: result.data, id: id, durationMs: durationMs},
+             result.transfers);
          } else {
-           self.postMessage({ok: result, id:id});
+           self.postMessage({ok: result, id:id, durationMs: durationMs});
          }
        } else if (exn == StopIteration) {
          // StopIteration cannot be serialized automatically
          LOG("Sending back StopIteration");
          self.postMessage({StopIteration: true, id: id});
        } else if (exn instanceof exports.OS.File.Error) {
          LOG("Sending back OS.File error", exn, "id is", id);
          // Instances of OS.File.Error know how to serialize themselves
--- a/toolkit/components/osfile/tests/mochi/main_test_osfile_async.js
+++ b/toolkit/components/osfile/tests/mochi/main_test_osfile_async.js
@@ -147,16 +147,17 @@ let test = maketest("Main", function mai
     yield test_read_write_all();
     yield test_position();
     yield test_copy();
     yield test_mkdir();
     yield test_iter();
     yield test_exists();
     yield test_debug_test();
     yield test_system_shutdown();
+    yield test_duration();
     info("Test is over");
     SimpleTest.finish();
   });
 });
 
 /**
  * A file that we know exists and that can be used for reading.
  */
@@ -838,9 +839,54 @@ let test_system_shutdown = maketest("sys
     yield iterator.close();
 
     let openedFile = yield OS.File.open(EXISTING_FILE);
     toggleDebugTest(true, EXISTING_FILE);
     Services.obs.notifyObservers(null, "test.osfile.web-workers-shutdown",
       null);
     yield openedFile.close();
   });
+});
+
+/**
+ * Test optional duration reporting that can be used for telemetry.
+ */
+let test_duration = maketest("duration", function duration(test) {
+  return Task.spawn(function() {
+    // Options structure passed to a OS.File copy method.
+    let copyOptions = {
+      // This field should be overridden with the actual duration
+      // measurement.
+      outExecutionDuration: null
+    };
+    let currentDir = yield OS.File.getCurrentDirectory();
+    let pathSource = OS.Path.join(currentDir, EXISTING_FILE);
+    let copyFile = pathSource + ".bak";
+    let testOptions = function testOptions(options) {
+      test.info("Gathered method duration time: " +
+        options.outExecutionDuration + " MS");
+      // Making sure that duration was updated.
+      test.ok(typeof options.outExecutionDuration === "number" &&
+        options.outExecutionDuration >= 0,
+        "Operation duration time was updated correctly with a numeric value.");
+    };
+    // Testing duration of OS.File.copy.
+    yield OS.File.copy(pathSource, copyFile, copyOptions);
+    testOptions(copyOptions);
+    yield OS.File.remove(copyFile);
+
+    // Trying an operation where options are cloned.
+    let pathDest = OS.Path.join(OS.Constants.Path.tmpDir,
+      "osfile async test read writeAtomic.tmp");
+    let tmpPath = pathDest + ".tmp";
+    let contents = yield OS.File.read(pathSource);
+    // Options structure passed to a OS.File writeAtomic method.
+    let writeAtomicOptions = {
+      // This field should be overridden with the actual duration
+      // measurement.
+      outExecutionDuration: null,
+      tmpPath: tmpPath
+    };
+    yield OS.File.writeAtomic(pathDest, contents, writeAtomicOptions);
+    testOptions(writeAtomicOptions);
+    OS.File.remove(pathDest);
+  });
 });
\ No newline at end of file