Closed Bug 848278 Opened 10 years ago Closed 10 years ago

[OS.File] Add a way to measure duration of an off main thread operation

Categories

(Toolkit :: OS.File, defect)

Product:
Toolkit
Component:
OS.File
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla22

People

(Reporter: Yoric, Assigned: yzen)

References

Details

(Keywords: dev-doc-needed)

Attachments

(1 file, 4 obsolete files)

Added |outExecutionDuration|. Final changes inlcuded.
13.74 KB, patch
Details | Diff | Splinter Review 
Whenever attempting to measure the duration of some operation with OS.File, the method that comes to mind is the following:

(assuming Task.jsm)

 let start = Date.now();
 yield OS.File.myOperation(...);
 let stop = Date.now();
 let duration = stop - start;

(or some Telemetry variant).

However, the information given by |duration| is generally not interesting, as it measures not only how long |OS.File.myOperation| has lasted but also how long it took for the main thread to get to handle the message informing that the operation was complete. For many operations, this is much longer than the duration of |OS.File.myOperation|.

What we need to do is measure on the OS.File thread the duration of the operation and somehow send this information back to the main thread.
Assignee: nobody → yura.zenevich
The main change in the patch is the addition of Scheduler.postWithProbe method that does the same thing as Scheduler.post except for the fact that the first argument is expected to be a histogram name to add a measurement to (I will further comment that as well).

This lets anyone to, in case they want to start measuring telemetry on specific osfile off main thread operations, switch from post to postWithProbe.

I will add the tests shortly, if you like this approach.

Let me know what you think and thanks :)
Attachment #722043 - Flags: feedback?(dteller)
Comment on attachment 722043 [details] [diff] [review]
First pass at adding support for off main thread osfile operations.

Review of attachment 722043 [details] [diff] [review]:
-----------------------------------------------------------------

Generally, it looks good, but I would not hard-code telemetry. Let me suggest an alternative.

Given that all functions of OS.File accept an optional argument |option|, we could use this object to return the duration of the operation.
For instance, for any function, if there is an |option| argument and this object has a field |outDuration|, replace this field with the duration of the operation.
Attachment #722043 - Flags: feedback?(dteller) → feedback+
Hi David,

I noticed that, even if the platform specific (actual) implementation of the operation takes options, it's not necessarily passed down from the main thread (hence it's not mentioned in the API docs).

Should I leave it as is or should I make sure that for all operations that can make use of options the options are actually propagated ?

Thanks.
Flags: needinfo?(dteller)
Since the data is not shared but rather cloned between the controller and the agent, altering the options Object that the worker gets has no effect. In order to update the options' outDuration, the override should happen in the main thread (if we want the user of the method to see the difference). I'm guessing it is still better than hard-coding telemetry, but perhaps you have another suggestion ? Thanks!
I can think of a hack. It might not work, or it might be too subtle for the sake of any reviewer, so don't take for granted that it is the best way to do this.

The key idea is that some functions/methods of osfile_async_front.jsm can be labelled as "benchmarkable". For the moment, I would say |OS.File.writeAtomic| and |OS.File.read| are sufficient.

1. Add a boolean field |benchmark| to the messages sent to the worker.
2. Upon reception of a message with |benchmark: true|, osfile_async_worker.js measures the duration and returns |{durationMs: ..., result:...}| instead if just the result (I don't know what we should do in case of exception);
3. Whenever a user calls |OS.File.foo.benchmark| instead of OS.File.foo, the function/method sets |benchmark: true|. Otherwise, |benchmark: false|.

Still pretty rough, but it might be nice. What do you think?
Flags: needinfo?(dteller)
Comment on attachment 722043 [details] [diff] [review]
First pass at adding support for off main thread osfile operations.

Review of attachment 722043 [details] [diff] [review]:
-----------------------------------------------------------------

Cancelling f? until we have come up with a good strategy.
Attachment #722043 - Flags: feedback+
Hi David,

Basically this patch is a combination of some of the ideas from comments both yours and mine. I liked the |outDuration| idea so I went ahead and added support for it, it is updated in the main thread after worker sends the message back based on |durationMs| field from the message data.

Given that your latest comment implied that there would still be some processing of the worker's message needed, I thought it would be ok to use the |options| and the |outDuration| field for that matter.

Note that the |outDuration| will not be updated if the method resulted in exception, this is to be consistent with the way telemetry stopwatch is used, where if the method fails, the measurement is cancelled rather that stopped.

Let me know.
Attachment #722043 - Attachment is obsolete: true
Attachment #723145 - Flags: feedback?(dteller)
Comment on attachment 723145 [details] [diff] [review]
Added support for |outDuration| option on osfile methods.

Review of attachment 723145 [details] [diff] [review]:
-----------------------------------------------------------------

I like it.

::: toolkit/components/osfile/osfile_async_front.jsm
@@ +94,5 @@
> + *
> + * @param {JSON} - message returned by the worker.
> + * @postArgs {Array} - arguments supplied to PromiseWorker's post method.
> + */
> +let updateDuration = function updateDuration(data, postArgs) {

Given that this function is used only once – and in a two-liner function – I would suggest inlining it.

::: toolkit/components/osfile/osfile_async_worker.js
@@ +42,5 @@
> +           options = data.args[data.args.length - 1];
> +         }
> +         // If |outDuration| option was supplied, start measuring the duration
> +         // of the operation.
> +         if (options && typeof options.outDuration !== "undefined") {

I suspect that you should check whether |typeof options == "object"|.
Attachment #723145 - Flags: feedback?(dteller) → feedback+
Comment on attachment 724392 [details] [diff] [review]
Updated to check for options' type and flattened duration check function.

Nathan, it would be great to have a second opinion on this.
Attachment #724392 - Flags: review?(nfroyd)
Comment on attachment 724392 [details] [diff] [review]
Updated to check for options' type and flattened duration check function.

Review of attachment 724392 [details] [diff] [review]:
-----------------------------------------------------------------

Communicating through |options| seems a bit sketchy.  We freely clone() options to add internal-specific fields.  If I'm reading this right, we'll modify the copied options, not the original options that the user passed.  So there should be something to transfer |outDuration| back from the cloned options to the user's options, right?

Documentation should be added to osfile_async_front.jsm, too.

::: toolkit/components/osfile/osfile_async_front.jsm
@@ +102,5 @@
> +        }
> +        let options = methodArgs[methodArgs.length - 1];
> +        // Check for options.outDuration.
> +        if (typeof options !== "object" ||
> +          typeof options.outDuration === "undefined") {

Nit: indentation is wrong here.

Why not just !("options" in outDuration) ?
Attachment #724392 - Flags: review?(nfroyd)
(In reply to Nathan Froyd (:froydnj) from comment #11)
> Communicating through |options| seems a bit sketchy.  We freely clone()
> options to add internal-specific fields.  If I'm reading this right, we'll
> modify the copied options, not the original options that the user passed. 
> So there should be something to transfer |outDuration| back from the cloned
> options to the user's options, right?

I should clarify: for copying files, we don't modify |options|.  For other cases (possibly the more interesting cases), we do.
(In reply to Nathan Froyd (:froydnj) from comment #11)
> Comment on attachment 724392 [details] [diff] [review]
> Updated to check for options' type and flattened duration check function.
> 
> Review of attachment 724392 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Communicating through |options| seems a bit sketchy.  We freely clone()
> options to add internal-specific fields.  If I'm reading this right, we'll
> modify the copied options, not the original options that the user passed. 
> So there should be something to transfer |outDuration| back from the cloned
> options to the user's options, right?

We only read from options on the worker's side and then optionally return |durationMs| back along with result. Wen only modify the original options in the osfile_async_front.jsm once we get a message back from the worker.

> 
> Documentation should be added to osfile_async_front.jsm, too.
> 
> ::: toolkit/components/osfile/osfile_async_front.jsm
> @@ +102,5 @@
> > +        }
> > +        let options = methodArgs[methodArgs.length - 1];
> > +        // Check for options.outDuration.
> > +        if (typeof options !== "object" ||
> > +          typeof options.outDuration === "undefined") {
> 
> Nit: indentation is wrong here.
> 
> Why not just !("options" in outDuration) ?

In this case outDuration is in options. We can't really do the other way around, because if options is not an object "in" statement will result in an error.
(In reply to Yura Zenevich [:yzen] from comment #13)
> > Communicating through |options| seems a bit sketchy.  We freely clone()
> > options to add internal-specific fields.  If I'm reading this right, we'll
> > modify the copied options, not the original options that the user passed. 
> > So there should be something to transfer |outDuration| back from the cloned
> > options to the user's options, right?
> 
> We only read from options on the worker's side and then optionally return
> |durationMs| back along with result. Wen only modify the original options in
> the osfile_async_front.jsm once we get a message back from the worker.

Nathan has a good remark. A few functions call |clone(options)| because they themselves may have side-effects on the options. These functions should copy |outDuration| back in the original argument |options|.
(In reply to Yura Zenevich [:yzen] from comment #13)
> (In reply to Nathan Froyd (:froydnj) from comment #11)
> > ::: toolkit/components/osfile/osfile_async_front.jsm
> > @@ +102,5 @@
> > > +        }
> > > +        let options = methodArgs[methodArgs.length - 1];
> > > +        // Check for options.outDuration.
> > > +        if (typeof options !== "object" ||
> > > +          typeof options.outDuration === "undefined") {
> > 
> > Why not just !("options" in outDuration) ?
> 
> In this case outDuration is in options. We can't really do the other way
> around, because if options is not an object "in" statement will result in an
> error.

Sorry, I reversed the bits in my comment!  For clarity, I was wondering why you didn't write this as:

  if (typeof options !== "object" || !("outDuration" in options))
Ya that makes a lot of sense.(In reply to Nathan Froyd (:froydnj) from comment #15)
> (In reply to Yura Zenevich [:yzen] from comment #13)
> > (In reply to Nathan Froyd (:froydnj) from comment #11)
> > > ::: toolkit/components/osfile/osfile_async_front.jsm
> > > @@ +102,5 @@
> > > > +        }
> > > > +        let options = methodArgs[methodArgs.length - 1];
> > > > +        // Check for options.outDuration.
> > > > +        if (typeof options !== "object" ||
> > > > +          typeof options.outDuration === "undefined") {
> > > 
> > > Why not just !("options" in outDuration) ?
> > 
> > In this case outDuration is in options. We can't really do the other way
> > around, because if options is not an object "in" statement will result in an
> > error.
> 
> Sorry, I reversed the bits in my comment!  For clarity, I was wondering why
> you didn't write this as:
> 
>   if (typeof options !== "object" || !("outDuration" in options))

Ya that makes a lot of sense.
So to summarize:

I need to update the following:

* Handle all cases where user options are cloned
* Update a check for "outDuration" in the worker

Is there anything else?
(In reply to Yura Zenevich [:yzen] from comment #17)
> So to summarize:
> 
> I need to update the following:
> 
> * Handle all cases where user options are cloned
Probably add some documentation around function |clone| o ensure that nobody forgets them.

> * Update a check for "outDuration" in the worker

> Is there anything else?
Not that I can think of.
* Updated clone utility to optionally handle references (inspired by worker's transferList option when posting messages - https://developer.mozilla.org/en-US/docs/DOM/Worker)
* Updated some of the if statements as per :froydnj
* Added more tests.
Attachment #724392 - Attachment is obsolete: true
Attachment #724392 - Flags: review?(dteller)
Attachment #724806 - Flags: review?(dteller)
Comment on attachment 724806 [details] [diff] [review]
Patch is now updated to comments.

Review of attachment 724806 [details] [diff] [review]:
-----------------------------------------------------------------

r=me with a few minor changes.

::: toolkit/components/osfile/_PromiseWorker.jsm
@@ +115,5 @@
>       * Messages may also contain a field |id| to help
>       * with debugging.
>       *
> +     * If an |outDuration| option was posted to the worker and msg.data
> +     * contains |ok|, durationMs field will be sent back to the main thread .

Nit: "message will also contain a field |durationMs|, holding the duration of the function call in milliseconds."

::: toolkit/components/osfile/osfile_async_front.jsm
@@ +75,5 @@
>   * changes to an option object. The copy ensures that we do not modify
>   * a client-provided object by accident.
> + *
> + * Note: if we want to reference and not copy specific fields, we can
> + * provide an optional |keys| argument containing their names.

Good idea.
Nit: don't use "we".

@@ +84,2 @@
>   */
> +let clone = function clone(object, keys) {

I would suggest |function clone(object, keys = noKeys)|, where |noKeys| has been defined globally as |[]|.
Also, |keys| is a little ambiguous – perhaps |refs|?

@@ +86,5 @@
>    let result = {};
> +  // Make a reference between result[key] and object[key].
> +  let refer = function refer(result, key, object) {
> +    Object.defineProperty(result, key, {
> +        configurable: true,

Are you sure about |configurable|?

@@ +130,5 @@
> +        if (typeof options !== "object" || !("outDuration" in options)) {
> +          return data.ok;
> +        }
> +        // If data.durationMs is not present, return data.ok (there was an
> +        // exception applying the method).

Can that happen?

::: toolkit/components/osfile/tests/mochi/main_test_osfile_async.js
@@ +873,5 @@
> +    let pathDest = OS.Path.join(OS.Constants.Path.tmpDir,
> +      "osfile async test read writeAtomic.tmp");
> +    let tmpPath = pathDest + ".tmp";
> +    let currentDir = yield OS.File.getCurrentDirectory();
> +    let pathSource = OS.Path.join(currentDir, EXISTING_FILE);

You probably should use |pathSource| instead of |EXISTING_FILE| at line 868.
Attachment #724806 - Flags: review?(dteller) → review+
Oh, one last thing: |outDuration| is probably ambiguous (bug 850636 will introduce another measurement for duration). Perhaps |outExecutionDuration| would be clearer?
carrying forward r+ from Yoric.
https://hg.mozilla.org/mozilla-central/rev/3196b8bf8142
Status: NEW → RESOLVED
Closed: 10 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla22
You need to log in before you can comment on or make changes to this bug.