Bug 850636 - add an option `outSerializationDuration` to measure the time for message serialization,r=Yoric draft
authormilindl <i.milind.luthra@gmail.com>
Sat, 03 Jun 2017 21:44:37 +0530
changeset 595612 caa281e6ad9cee1a39a7196c7253cae782c771db
parent 588564 43039280fe464869428f03b047bb7c762784f44b
child 633749 d64150c436f3a3ea6b84efe4da3144a247804872
push id64386
push userbmo:i.milind.luthra@gmail.com
push dateFri, 16 Jun 2017 14:09:17 +0000
reviewersYoric
bugs850636
milestone55.0a1
Bug 850636 - add an option `outSerializationDuration` to measure the time for message serialization,r=Yoric This changes the `Scheduler.post` method to check for options in the `args`, and accordingly update it with the time it takes for running `Scheduler.worker.post`. This also changes the `test_duration.js` to add another duration (serialization duration) for the operations where `Scheduler.post` is called. MozReview-Commit-ID: EGPeHfMYI1U
toolkit/components/osfile/modules/osfile_async_front.jsm
toolkit/components/osfile/tests/xpcshell/test_duration.js
--- a/toolkit/components/osfile/modules/osfile_async_front.jsm
+++ b/toolkit/components/osfile/modules/osfile_async_front.jsm
@@ -380,16 +380,20 @@ var Scheduler = this.Scheduler = {
   },
 
   /**
    * Post a message to the worker thread.
    *
    * @param {string} method The name of the method to call.
    * @param {...} args The arguments to pass to the method. These arguments
    * must be clonable.
+   * The last argument by convention may be an object `options`, with some of
+   * the following fields:
+   *   - {number|null} outSerializationDuration A parameter to be filled with
+   *     duration of the `this.worker.post` method.
    * @return {Promise} A promise conveying the result/error caused by
    * calling |method| with arguments |args|.
    */
   post: function post(method, args = undefined, closure = undefined) {
     if (this.shutdown) {
       LOG("OS.File is not available anymore. The following request has been rejected.",
         method, args);
       return Promise.reject(new Error("OS.File has been shut down. Rejecting post to " + method));
@@ -414,24 +418,43 @@ var Scheduler = this.Scheduler = {
       // 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(args)];
 
       // Don't kill the worker just yet
       Scheduler.restartTimer();
 
+      // The last object inside the args may be an options object.
+      let options = null;
+      if (args && args.length >= 1 && typeof args[args.length-1] === "object") {
+        options = args[args.length - 1];
+      }
 
       let reply;
       try {
         try {
           Scheduler.Debugging.messagesSent++;
           Scheduler.Debugging.latestSent = Scheduler.Debugging.latestSent.slice(0, 2);
+          let serializationStartTimeMs = Date.now();
           reply = await this.worker.post(method, args, closure);
+          let serializationEndTimeMs = Date.now();
           Scheduler.Debugging.latestReceived = [Date.now(), summarizeObject(reply)];
+
+          // There were no options for recording the serialization duration.
+          if (options && "outSerializationDuration" in options) {
+            // The difference might be negative for very fast operations, since Date.now() may not be monotonic.
+            let serializationDurationMs = Math.max(0, serializationEndTimeMs - serializationStartTimeMs);
+
+            if (typeof options.outSerializationDuration === "number") {
+              options.outSerializationDuration += serializationDurationMs;
+            } else {
+              options.outSerializationDuration = serializationDurationMs;
+            }
+          }
           return reply;
         } finally {
           Scheduler.Debugging.messagesReceived++;
         }
       } catch (error) {
         Scheduler.Debugging.latestReceived = [Date.now(), error.message, error.fileName, error.lineNumber];
         throw error;
       } finally {
@@ -635,18 +658,18 @@ File.prototype = {
    */
   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.
     // Options might be a nullish value, so better check for that before using
     // the |in| operator.
     if (isTypedArray(buffer) && !(options && "bytes" in options)) {
-      // Preserve reference to option |outExecutionDuration|, if it is passed.
-      options = clone(options, ["outExecutionDuration"]);
+      // Preserve reference to option |outExecutionDuration|, |outSerializationDuration|, if it is passed.
+      options = clone(options, ["outExecutionDuration", "outSerializationDuration"]);
       options.bytes = buffer.byteLength;
     }
     return Scheduler.post("File_prototype_write",
       [this._fdmsg,
        Type.void_t.in_ptr.toMsg(buffer),
        options],
        buffer/*Ensure that |buffer| is not gc-ed*/);
   },
@@ -1065,17 +1088,17 @@ File.makeDir = function makeDir(path, op
  * read from the file.
  */
 File.read = function read(path, bytes, options = {}) {
   if (typeof bytes == "object") {
     // Passing |bytes| as an argument is deprecated.
     // We should now be passing it as a field of |options|.
     options = bytes || {};
   } else {
-    options = clone(options, ["outExecutionDuration"]);
+    options = clone(options, ["outExecutionDuration", "outSerializationDuration"]);
     if (typeof bytes != "undefined") {
       options.bytes = bytes;
     }
   }
 
   if (options.compression || !nativeWheneverAvailable) {
     // We need to use the JS implementation.
     let promise = Scheduler.post("read",
@@ -1146,18 +1169,18 @@ File.exists = function exists(path) {
  * during the short window between these operations,
  * the destination file will have been moved to its backup.
  *
  * @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 but preserve the
-  // reference to |outExecutionDuration| option if it is passed.
-  options = clone(options, ["outExecutionDuration"]);
+  // reference to |outExecutionDuration|, |outSerializationDuration| option if it is passed.
+  options = clone(options, ["outExecutionDuration", "outSerializationDuration"]);
   // 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;
   };
   let refObj = {};
--- a/toolkit/components/osfile/tests/xpcshell/test_duration.js
+++ b/toolkit/components/osfile/tests/xpcshell/test_duration.js
@@ -1,88 +1,103 @@
 var {OS} = Components.utils.import("resource://gre/modules/osfile.jsm", {});
 var {Services} = Components.utils.import("resource://gre/modules/Services.jsm", {});
 
 /**
  * Test optional duration reporting that can be used for telemetry.
  */
 add_task(async function duration() {
+  const availableDurations = ["outSerializationDuration", "outExecutionDuration"];
   Services.prefs.setBoolPref("toolkit.osfile.log", true);
   // Options structure passed to a OS.File copy method.
   let copyOptions = {
-    // This field should be overridden with the actual duration
-    // measurement.
+    // These fields should be overwritten with the actual duration
+    // measurements.
+    outSerializationDuration: null,
     outExecutionDuration: null
   };
   let currentDir = await OS.File.getCurrentDirectory();
   let pathSource = OS.Path.join(currentDir, "test_duration.js");
   let copyFile = pathSource + ".bak";
-  function testOptions(options, name) {
-    do_print("Checking outExecutionDuration for operation: " + name);
-    do_print(name + ": Gathered method duration time: " +
-      options.outExecutionDuration + "ms");
-    // Making sure that duration was updated.
-    do_check_eq(typeof options.outExecutionDuration, "number");
-    do_check_true(options.outExecutionDuration >= 0);
-  };
+  function testOptions(options, name, durations = availableDurations) {
+    for (let duration of durations) {
+      do_print(`Checking ${duration} for operation: ${name}`);
+      do_print(`${name}: Gathered method duration time: ${options[duration]} ms`);
+      // Making sure that duration was updated.
+      do_check_eq(typeof options[duration], "number");
+      do_check_true(options[duration] >= 0);
+    }
+  }
+
+  function testOptionIncrements(options, name, backupDuration, durations = availableDurations) {
+    for (let duration of durations) {
+      do_print(`Checking ${duration} increment for operation: ${name}`);
+      do_print(`${name}: Gathered method duration time: ${options[duration]} ms`);
+      do_print(`${name}: Previous duration: ${backupDuration[duration]} ms`);
+      // Making sure that duration was incremented.
+      do_check_true(options[duration] >= backupDuration[duration]);
+    }
+  }
+
   // Testing duration of OS.File.copy.
   await OS.File.copy(pathSource, copyFile, copyOptions);
   testOptions(copyOptions, "OS.File.copy");
   await 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 readOptions = {
+    // We do not check for |outSerializationDuration| since |Scheduler.post|
+    // may not be called whenever |read| is called.
     outExecutionDuration: null
   };
   let contents = await OS.File.read(pathSource, undefined, readOptions);
-  testOptions(readOptions, "OS.File.read");
+  testOptions(readOptions, "OS.File.read", ["outExecutionDuration"]);
   // Options structure passed to a OS.File writeAtomic method.
   let writeAtomicOptions = {
     // This field should be first initialized with the actual
     // duration measurement then progressively incremented.
+    outSerializationDuration: null,
     outExecutionDuration: null,
     tmpPath: tmpPath
   };
   await OS.File.writeAtomic(pathDest, contents, writeAtomicOptions);
   testOptions(writeAtomicOptions, "OS.File.writeAtomic");
   await OS.File.remove(pathDest);
 
-  do_print("Ensuring that we can use outExecutionDuration to accumulate durations");
+  do_print(`Ensuring that we can use ${availableDurations.join(", ")} to accumulate durations`);
 
   let ARBITRARY_BASE_DURATION = 5;
   copyOptions = {
     // This field should now be incremented with the actual duration
     // measurement.
+    outSerializationDuration: ARBITRARY_BASE_DURATION,
     outExecutionDuration: ARBITRARY_BASE_DURATION
   };
-  let backupDuration = ARBITRARY_BASE_DURATION;
+
+  // We need to copy the object, since having a reference would make this pointless.
+  let backupDuration = Object.assign({}, copyOptions);
+
   // Testing duration of OS.File.copy.
   await OS.File.copy(pathSource, copyFile, copyOptions);
-
-  do_check_true(copyOptions.outExecutionDuration >= backupDuration);
+  testOptionIncrements(copyOptions, "copy", backupDuration);
 
-  backupDuration = copyOptions.outExecutionDuration;
+  backupDuration = Object.assign({}, copyOptions);
   await OS.File.remove(copyFile, copyOptions);
-  do_check_true(copyOptions.outExecutionDuration >= backupDuration);
+  testOptionIncrements(copyOptions, "remove", backupDuration);
 
   // Trying an operation where options are cloned.
   // Options structure passed to a OS.File writeAtomic method.
-  writeAtomicOptions = {
-    // This field should be overridden with the actual duration
-    // measurement.
-    outExecutionDuration: copyOptions.outExecutionDuration,
-    tmpPath: tmpPath
-  };
-  backupDuration = writeAtomicOptions.outExecutionDuration;
-
+  writeAtomicOptions = copyOptions;
+  writeAtomicOptions.tmpPath = tmpPath;
+  backupDuration = Object.assign({}, copyOptions);
   await OS.File.writeAtomic(pathDest, contents, writeAtomicOptions);
-  do_check_true(copyOptions.outExecutionDuration >= backupDuration);
+  testOptionIncrements(writeAtomicOptions, "writeAtomicOptions", backupDuration);
   OS.File.remove(pathDest);
 
   // Testing an operation that doesn't take arguments at all
   let file = await OS.File.open(pathSource);
   await file.stat();
   await file.close();
 });