850636 - [OS.File] Add a way to measure duration of message serialization

Status: RESOLVED FIXED

(Toolkit Graveyard :: OS.File, defect)

Description

[David Teller [:Yoric] - still alive but not very active]

I have run a few experiments at http://yoric.github.com/Bugzilla-832664/ to determine whether message serialization could suck performances and, to sum it up, for huge messages, it can.

At some point, we will probably want to be able to measure the cost of serialization.

Comment 1

[David Teller [:Yoric] - still alive but not very active]

Rescoping because I can't think of any non-very-expensive way to measure speed of deserialization.

Comment 2

[David Teller [:Yoric] - still alive but not very active]

Nice mentored bug, for someone familiar with workers or willing to become familiar with workers.

Comment 3

[Rahul Gandhi]

Sir
I want to handle this bug,it will be great opportunity for me to work on this bug.i am well equipped with the knowledge of c/c++, java, javascript, html/css.

Comment 4

[David Teller [:Yoric] - still alive but not very active]

Waiting until you have completed bug 857077.

Comment 5

[Anup Kumar [:reznord]]

Hi, 

I am willing to work on this bug. So please I request you to assign it to me.

Thanks in Advance,

Regards,
A. Anup

Comment 6

[David Teller [:Yoric] - still alive but not very active]

The changes that need to be done are in osfile_async_front.jsm, in method Scheduler.post.

If |options| is not |null|, if it is an object and if it contains a field named |outSerializationDuration|, we want to measure the duration of operation |worker.post.apply(...)| and use this value to augment |options.outSerializationDuration| or initialize it if this field is not a number.

Comment 7

[David Teller [:Yoric] - still alive but not very active]

Any progress Anup? Do you need assistance?

Comment 8

[David Teller [:Yoric] - still alive but not very active]

Sankha, are you actually working on this?

Comment 9

[Sankha Narayan Guria [:sankha]]

No I am not working on this.

Anup, why did you assign the bug to me out of nowhere?

Comment 10

[Milind L (:milindl)]

Attachment: Bug 850636 - add an option `outSerializationDuration` to measure the time for message serialization,

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.

Review commit: https://reviewboard.mozilla.org/r/145578/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/145578/

Comment 11

[Milind L (:milindl)]

Hello, I wanted to work on this, since I web workers seemed interesting; and one of the other OS.File bugs seemed interesting to me so it made sense to start with a more basic one.

In any case, I made a patch for this bug, trying to implement what I understood. I also updated the test_duration. Please tell me if I'm doing it correctly.

Thanks!

Comment 12

[David Teller [:Yoric] - still alive but not very active]

Sorry for the delay, I'll try and review this by tomorrow.

Comment 13

[David Teller [:Yoric] - still alive but not very active]

Comment on attachment 8874133 [details]
Bug 850636 - add an option `outSerializationDuration` to measure the time for message serialization,

https://reviewboard.mozilla.org/r/145578/#review152430

Apologies for the delay, I had unexpected stuff to do.

Thanks for the patch, ot looks good, could you make the minor changes below?

::: toolkit/components/osfile/modules/osfile_async_front.jsm:429
(Diff revision 1)
>        Scheduler.restartTimer();
>  
> +      // The last object inside the args may be an options object.
> +      let options = null;
> +      if (args) {
> +        options = args[args.length - 1];

I would check if `args[args.length - 1]` has type `"object"` first. This would simplify a bit the code below.

::: toolkit/components/osfile/modules/osfile_async_front.jsm:445
(Diff revision 1)
>            Scheduler.Debugging.latestReceived = [Date.now(), summarizeObject(reply)];
> +
> +          // There were no options for recording the serialization duration.
> +          if (!options || typeof options !== "object" ||
> +              !("outSerializationDuration" in options)) {
> +            return reply;

This `return` in the middle here scares me a bit, as we are bound to extend this function later. So, while your code follows our general guidelines of returning early to avoid staying in an `if` too long, I would suggest breaking this guideline here and do

```js
if (options && "outSerializationDuration" in options) {
 ...
}
return reply;
```

::: toolkit/components/osfile/tests/xpcshell/test_duration.js:42
(Diff revision 1)
>    let tmpPath = pathDest + ".tmp";
>    let readOptions = {
>      outExecutionDuration: null
>    };
>    let contents = await OS.File.read(pathSource, undefined, readOptions);
> -  testOptions(readOptions, "OS.File.read");
> +  testOptions(readOptions, "OS.File.read", ["outExecutionDuration"]);

Why do you only check `outExecutionDuration` here and below?

::: toolkit/components/osfile/tests/xpcshell/test_duration.js:73
(Diff revision 1)
> +  do_check_true(copyOptions.outSerializationDuration >= backupDuration);
>  
>    backupDuration = copyOptions.outExecutionDuration;
>    await OS.File.remove(copyFile, copyOptions);
>    do_check_true(copyOptions.outExecutionDuration >= backupDuration);
> +  do_check_true(copyOptions.outSerializationDuration >= backupDuration);

This doesn't work, we need a different `backupDuration` for `outExecutionDuration` and `outSerializationDuration`. Perhaps make it an object?

Comment 14

[Milind L (:milindl)]

Comment on attachment 8874133 [details]
Bug 850636 - add an option `outSerializationDuration` to measure the time for message serialization,

https://reviewboard.mozilla.org/r/145578/#review152430

> Why do you only check `outExecutionDuration` here and below?

For `read`, `Scheduler.post` may never be called. From what I can tell, this is when we decide to use the native implementation instead of the JS implementation in `File.read` (around line 1100). Using console.log statements, I have ascertained that even though that `read` method is called, it never enters the `if` clause which calls `post` on my PC - so it didn't make sense to check this.

For `writeAtomic` I was making a mistake (I assumed same reasoning as above), I am fixing it along with other comments.

Comment 15

[Milind L (:milindl)]

Comment on attachment 8874133 [details]
Bug 850636 - add an option `outSerializationDuration` to measure the time for message serialization,

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/145578/diff/1-2/

Comment 16

[Milind L (:milindl)]

I've submitted a changeset updated with the comments. 

To get `writeAtomic` to work, I had to make a few changes to the osfile_async_front. I also restructured the test a bit for checking the duration aggregation (made it more like the first part) since it was getting quite repetitive and would get even more so when we add other timing methods.

PS: I was thinking if it's possible to use `performance.now` in this context to avoid the whole 'less than zero' issue we get from `Date.now`? 

Thanks

Comment 17

[David Teller [:Yoric] - still alive but not very active]

Comment on attachment 8874133 [details]
Bug 850636 - add an option `outSerializationDuration` to measure the time for message serialization,

https://reviewboard.mozilla.org/r/145578/#review153854

Looks good to me. You have my r+, can you just fix the two trivial bits below?

Do you need help to land this patch?

::: toolkit/components/osfile/modules/osfile_async_front.jsm:428
(Diff revision 2)
>        // 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 && typeof args[args.length-1] === "object") {

I realize that we probably want to check that `args.length >= 1`.

::: toolkit/components/osfile/tests/xpcshell/test_duration.js:12
(Diff revision 2)
>  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
> +    // These fields should be overridden with the actual duration

While you're at it, could you fix my typo? It should have read `overwritten`, not `overridden`.

Comment 18

[David Teller [:Yoric] - still alive but not very active]

Comment on attachment 8874133 [details]
Bug 850636 - add an option `outSerializationDuration` to measure the time for message serialization,

https://reviewboard.mozilla.org/r/145578/#review152430

> For `read`, `Scheduler.post` may never be called. From what I can tell, this is when we decide to use the native implementation instead of the JS implementation in `File.read` (around line 1100). Using console.log statements, I have ascertained that even though that `read` method is called, it never enters the `if` clause which calls `post` on my PC - so it didn't make sense to check this.
> 
> For `writeAtomic` I was making a mistake (I assumed same reasoning as above), I am fixing it along with other comments.

Makes sense + thanks for fixing the mistake.
Could you add a comment explaining why you don't check it?

Comment 19

[Milind L (:milindl)]

> Do you need help to land this patch?

I can trigger a try run myself, if that is needed (I'll do it after applying the comments below). However to get this to autoland I would need help.

> PS: I was thinking if it's possible to use `performance.now` in this context to 
> avoid the whole 'less than zero' issue we get from `Date.now`?

I wanted to ask this thing, I guess I should've needinfo'd you on the previous comment as well :)

Comment 20

[Milind L (:milindl)]

Comment on attachment 8874133 [details]
Bug 850636 - add an option `outSerializationDuration` to measure the time for message serialization,

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/145578/diff/2-3/

Comment 21

[Milind L (:milindl)]

Comment on attachment 8874133 [details]
Bug 850636 - add an option `outSerializationDuration` to measure the time for message serialization,

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/145578/diff/3-4/

Comment 22

[David Teller [:Yoric] - still alive but not very active]

Sorry, I forgot to answer that.

If it works, that would indeed be better. OS.File was written before `performance.now`, so I had to do with what was available at the time :) However, let's keep this for a followup bug.

Comment 23

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/68f8468766e7
add an option `outSerializationDuration` to measure the time for message serialization,r=Yoric

Comment 24

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

https://hg.mozilla.org/mozilla-central/rev/68f8468766e7

Comment 25

[David Teller [:Yoric] - still alive but not very active]

Thanks for the patch, milindl!