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
--- 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();
});