Bug 850636 - add an option `outSerializationDuration` to measure the time for message serialization,r=Yoric
authormilindl <i.milind.luthra@gmail.com>
Sat, 03 Jun 2017 21:44:37 +0530
changeset 364446 68f8468766e7b15e5eeb94d1031940e34a8df29d
parent 364445 0c3542cbd56f4f57ddda029ad06f4418385e5dd9
child 364447 943dc0fef2638e9fe70b8328e2b67e057210358f
push id32042
push userarchaeopteryx@coole-files.de
push dateSat, 17 Jun 2017 19:33:32 +0000
treeherdermozilla-central@24012764504b [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersYoric
bugs850636
milestone56.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 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();
 });