1353798 - Display timing markers for service worker interception in network panel correctly

Status: RESOLVED FIXED

(DevTools :: Netmonitor, enhancement, P3)

Description

[Ben Hsu [:HoPang]]

After landing of Bug 11168875, both devtools-server and devtools-client should be updated to display timing markers for service worker interception correctly.

Comment 1

[Ben Hsu [:HoPang]]

Sorry for the typo, the bug in the bug description should be bug 1168875...

Comment 2

[Ben Hsu [:HoPang]]

Attachment: P1: Create detailed timing information in devtools-server

Comment 3

[Ben Hsu [:HoPang]]

Attachment: P1: Create detailed timing information in devtools-server

Comment 4

[Ben Hsu [:HoPang]]

Attachment: P2: Make devtools-client use the newly added detailed timing information

Comment 5

[Ben Hsu [:HoPang]]

Attachment: P3: Adding new locale strings

Comment 6

[Ben Hsu [:HoPang]]

Attachment: sw-with-launch

Comment 7

[Ben Hsu [:HoPang]]

Attachment: sw-without-launch

Comment 8

[Ben Hsu [:HoPang]]

Attachment: network-normal

Comment 9

[Ben Hsu [:HoPang]]

Hi Honza and Ricky,

I've updated the related implementation, and I'd like to know how you think about the experience of the 3 pictures. Firstly, service worker related timing details are exposed. Then, the timing markers now can be overlapped with each other, and their precision is set to 10e-6 second. Last but not the least, now NA is displayed instead of 0 when an interval shouldn't exist such as when DNS is cached.

Comment 10

[Jan Honza Odvarko [:Honza] (always need-info? me)]

Attachment: sw-timings-chrome.png

Great progress, thanks for working on this!

Some comments:

1) The abbreviation for 'not applicable' should be 'n/a' (see https://en.wikipedia.org/wiki/N/a)

2) We might want to discuss whether n/a timings should be displayed at all. What if we just hide those timings?

3) I am not what's the reasoning between sw-with-launch and sw-withou-launch. Can you provide more details about the difference?

4) I was looking at how chrome is visualizing the data (see the attached screenshot). Being consistent here can be a benefit for the user. Could we get some inspiration?

Comment 11

[Ben Hsu [:HoPang]]

> 1) The abbreviation for 'not applicable' should be 'n/a' (see
> https://en.wikipedia.org/wiki/N/a)

I'll update it right away :P
 
> 2) We might want to discuss whether n/a timings should be displayed at all.an
> What if we just hide those timings?

This is a great point! Ricky also have this very same opinion when he look at the prototype for the first time.
 
> 3) I am not what's the reasoning between sw-with-launch and
> sw-withou-launch. Can you provide more details about the difference?

Sorry for not making things clear enough.

When intercepting a network request originated from a document controlled by a service worker, the service worker might now be running at that moment, and thus it takes some time to launch the service worker. On the other hand, if the service worker is already running, then we don't have to do much to prepare the service worker. Another interesting thing happened here is that, due to the implementation of service worker, the periods of launching service worker and dispatching fetch event can be overlapped with each other. 

> 4) I was looking at how chrome is visualizing the data (see the attached
> screenshot). Being consistent here can be a benefit for the user. Could we
> get some inspiration?

Wow, I've never thought of it! Thanks for bringing it up. I'll spend some time understanding what the blink terms mean, and see what we can do here.

Comment 12

[Ricky Chien [:rickychien] (inactive)]

(In reply to Jan Honza Odvarko [:Honza] from comment #10)
> 1) The abbreviation for 'not applicable' should be 'n/a' (see
> https://en.wikipedia.org/wiki/N/a)
> 
> 2) We might want to discuss whether n/a timings should be displayed at all.
> What if we just hide those timings?

I'm also in favor of hiding these N/A timing markers when running service worker.

> 3) I am not what's the reasoning between sw-with-launch and
> sw-withou-launch. Can you provide more details about the difference?
> 
> 4) I was looking at how chrome is visualizing the data (see the attached
> screenshot). Being consistent here can be a benefit for the user. Could we
> get some inspiration?

Yep, good point! Not sure my assumption is correct. I suspect that Chrome would prefer to display "waiting" or "content download" markers for representing instead of showing "dispatch fetch event" and "handle fetch event" things. I don't have too many experience of service worker but I think we should find out a tradeoff between exposing more service worker specific information (good for platform engineer) or providing easy to understand visualization (good for web developer).

For web developer perspective, if someone spots an issue that timing of "launch service worker" and "handle fetch event" are too long, so they can get some inspirations to improve their front-end code, and then I would say that is very helpful.

Ben, do you think above scenario is possible?

Thanks!

Comment 13

[Ben Hsu [:HoPang]]

Attachment: (V2) P2: Make devtools-client use the newly added detailed timing information

Comment 14

[Ben Hsu [:HoPang]]

Since I failed to find an elaboration for timing labels of Chrome devtools, I can only provide my guess based on my understanding of service workers here. 

1. "Launch Service Worker" <=> "ServiceWorker Preparation"
2. "Dispatch Fetch Event"  <=> "Request to ServiceWorker"
3. "Handle Fetch Event"    <=> "Waiting (TTFB)" + "Content Download"

The first thing is that I don't think we can provide the exactly same information as Chrome because of the difference between the two implementations, but I think we can still do our best here, such as adopting "ServiceWorker Preparation" and "Request to ServiceWorker". However, I cannot find a suitable label for "Handle Fetch Event", given the fact that responses synthesized by service worker aren't necessarily downloaded from the network, I prefer not using the word, "download here". The other thing is that, for requests that cannot be handled by service worker, they still go to the network and thus follow the ordinary network flows which included "download" phase.

> For web developer perspective, if someone spots an issue that timing of
> "launch service worker" and "handle fetch event" are too long, so they can
> get some inspirations to improve their front-end code, and then I would say
> that is very helpful.
> 
> Ben, do you think above scenario is possible?""

Basically, the existence of the service worker timings helps FE author knows that the document is currently controlled by a service worker. Back to your questions, if there it takes too much time serving a single request, FE author can know who is to blame. For example, if "handle fetch event" takes too much time, they would consider simplifying the interception code in SW. Similarly, if "launch service worker", they might want to make the service worker script run faster. However, there is no many things they can do for a long "dispatch fetch event", since it somewhat refers how busy the browser is at that moment.

After all, if my guess is correct, we are providing almost the same information as Chrome does, except for "Waiting (TTFB)", which is hard to provide at this moment. My proposal here is change the label to "ServiceWorker Preparation", "Request to ServiceWorker" and "Handled by ServiceWorker"(not quite sure we should name it this way).

Comment 15

[Ben Hsu [:HoPang]]

Attachment: sw-without-launch (no n/a entry)

Since there are two votes for not displaying n/a entries, I hid them up :P

Comment 16

[Ben Hsu [:HoPang]]

Hi Honza and Ricky, 

Do you mind giving some more input here?

Comment 17

[Jan Honza Odvarko [:Honza] (always need-info? me)]

(In reply to Ben Hsu [:HoPang] from comment #16)
> Do you mind giving some more input here?

Could the timing labels be rendered on one line only? Just like all the other existing timing labels.

So, instead of:

Launch Service
Worker

It should be:

Launch Service Worker:

---

All you need to do is increase width of the label (netmonitor.css, 974)

.timings-label {
    width: 10em;
}


Honza

Comment 18

[Ricky Chien [:rickychien] (inactive)]

(In reply to Ben Hsu [:HoPang] from comment #14)
> After all, if my guess is correct, we are providing almost the same
> information as Chrome does, except for "Waiting (TTFB)", which is hard to
> provide at this moment. My proposal here is change the label to
> "ServiceWorker Preparation", "Request to ServiceWorker" and "Handled by
> ServiceWorker"(not quite sure we should name it this way).

Cool! This idea sounds good to me. Moreover, we can put "Launch Service Worker", "Dispatch Fetch Event" and "Handle Fetch Event" as tooltip text (just add a `title` attribute to html element).

Comment 19

[Ben Hsu [:HoPang]]

Attachment: P1: Create detailed timing information in devtools-server

Comment 20

[Ben Hsu [:HoPang]]

Attachment: P2: Make devtools-client use the newly added detailed timing information

Comment 21

[Ben Hsu [:HoPang]]

Attachment: P3: Adding new locale strings

Comment 22

[Ben Hsu [:HoPang]]

Comment on attachment 8871221 [details] [diff] [review]
P1: Create detailed timing information in devtools-server

Hi Alexandre,

In the patch, I added a new set of timing markers, called `details`, for a HTTP event instead of updating the existing ones, since I am afraid of breaking other things unexpectedly. `details` includes more timing marker for service workers and has a higher resolution, and thus we can make the information in timing panel more useful like the attachments above suggest. Would you mind reviewing this patch?

Comment 23

[Ben Hsu [:HoPang]]

Comment on attachment 8871222 [details] [diff] [review]
P2: Make devtools-client use the newly added detailed timing information

Hi Ricky,

I slightly refactor timing-panel for displaying the SW related timing marker. In addition to that, I also hide the invalid timings from the panel. Do you mind reviewing them?

Comment 24

[Ben Hsu [:HoPang]]

Comment on attachment 8871224 [details] [diff] [review]
P3: Adding new locale strings

:)

Comment 25

[Ricky Chien [:rickychien] (inactive)]

Comment on attachment 8871222 [details] [diff] [review]
P2: Make devtools-client use the newly added detailed timing information

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

LGTM for overall changes. I can only point out few nits which can be improved, please see inline comments. I like the patch and please ensure following try is green.

try: -b o -p linux64,macosx64,win32 -u mochitest-clipboard,mochitest-dt,mochitest-e10s-devtools-chrome -t none --artifact

Thanks!

::: devtools/client/netmonitor/src/components/timings-panel.js
@@ +19,5 @@
> +               "dns",
> +               "connect",
> +               "send",
> +               "wait",
> +               "receive"];

nit: I'd prefer to format this snippet as below.

const types = [
  "serviceWorkerPreparation",
  "requestToServiceWorker",
  "handledByServiceWorker",
  "blocked",
  "dns",
  "connect",
  "send",
  "wait",
  "receive"
];

@@ +32,4 @@
>      return null;
>    }
>  
> +  const details = request.eventTimings.details;

nit: Let's embrace new ES6 feature. Destructuring assignment is pretty awesome.

const { details } = request.eventTimings;

@@ +44,2 @@
>  
> +  const timings = types.filter(t => details[t].valid).map(t => {

nit: We recommend that surround parenthesis on every arrow function parameter and choose a specific variable name for them.

Adding tailing comma is a good practice to prevent messing with VCS blame history.
https://github.com/airbnb/javascript#commas--leading-trailing

const timings = types.filter((type) => details[type].valid).map((type) => {
  return {
    type,
    string: (details[t].end - details[t].start) / 1000,
    timeline: (details[t].end - details[t].start) / totalTime,   << add tailing comma
  };
};

@@ +50,5 @@
> +      timeline: (details[t].end - details[t].start) / totalTime
> +    };
> +  });
> +
> +  const timelines = timings.map(timing => {

nit: Likewise above. Surround parenthesis on every arrow function parameter.

Comment 26

[Alexandre Poirot [:ochameau]]

Comment on attachment 8871221 [details] [diff] [review]
P1: Create detailed timing information in devtools-server

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

I'm bit concerned about the added footprint of these additional fields.
netmonitor is already known to be slow, so we should be careful about what we record for every request.
`valid` and `timings` look useless. Both could be computed on the client.
If there is no timing you may also just skip the entries in `details` dictionary.

Do you think you could refactor the client to compute them out of end/start?

Otherwise you miss a test to proceed.
Please either test the actor like this test:
http://searchfox.org/mozilla-central/source/devtools/shared/webconsole/test/test_network_post.html
Or test the final UI behavior with a test like this one:
http://searchfox.org/mozilla-central/source/devtools/client/netmonitor/test/browser_net_simple-request-data.js

::: devtools/shared/webconsole/network-monitor.js
@@ +913,5 @@
>        // There also is never any timing events, so we can fire this
>        // event with zeroed out values.
> +      let timings = this._setupHarTimings(httpActivity, channel, true);
> +      httpActivity.owner.addEventTimings(timings.total,
> +                                         timings.channel,

Shouldn't this be timings.timings instead of timings.channel?

@@ +1419,2 @@
>        // If it came from the browser cache, we have no timing
>        // information and these should all be 0

You could move this comment a few lines before.
Before `['blocked', ...`

@@ +1429,2 @@
>  
> +    // harTimings.blocked

I imagine you meant `details.blocked`

@@ +1468,3 @@
>      } else if (timings.REQUEST_HEADER && timings.REQUEST_BODY_SENT) {
> +      details.send = {valid: true,
> +                      start: timings.REQUEST_HEADER.frist,

s/frist/first/

@@ +1487,5 @@
> +    if (timings.RESPONSE_START && timings.RESPONSE_COMPLETE) {
> +      details.receive = {valid: true,
> +                         start: timings.RESPONSE_START.first,
> +                         end: timings.RESPONSE_COMPLETE.last};
> +      harTimings.receive = details.receive.end - details.receive.start;

Is it useful?
Isn't it done by "compute harTimings" code?

Comment 27

[Ben Hsu [:HoPang]]

Attachment: (V2) P1: Create detailed timing information in devtools-server

Comment 28

[Ben Hsu [:HoPang]]

Attachment: P2: Make devtools-client use the newly added detailed timing information

Comment 29

[Ben Hsu [:HoPang]]

Attachment: P3: Adding new locale strings

Comment 30

[Ben Hsu [:HoPang]]

Comment on attachment 8882223 [details] [diff] [review]
(V2) P1: Create detailed timing information in devtools-server

Hi Alexandre,

This version mainly fixes the stupid mistakes I've made in the previous patch, and addresses the performance concerns you've mentioned in comment 26. Since there are two values used n/a entries 0[0] and -1[1], I cannot compute them from the newly introduced details. As a result, I only removed the `valid` flags and only saved valid entries into `details` to minimize the overhead introduced by this patch.

However, for the long term plan, we think we can make the consumers using `timings` use  `details` and remove `timings` entirely in another bug.

[0] http://searchfox.org/mozilla-central/source/devtools/shared/webconsole/network-monitor.js#1392-1397
[1] http://searchfox.org/mozilla-central/source/devtools/shared/webconsole/network-monitor.js#1412

Comment 31

[Alexandre Poirot [:ochameau]]

Comment on attachment 8882223 [details] [diff] [review]
(V2) P1: Create detailed timing information in devtools-server

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

Sorry for the delayed review!

Code looks good now, but tests are not.
If existing tests are hard to modify, you can also fork one of the two in order to focus on testing your new codepath.

::: devtools/client/netmonitor/test/browser_net_simple-request-data.js
@@ +374,5 @@
> +      ok("undefined" === typeof details.receive ||
> +         "number" === typeof details.receive.start &&
> +         "number" === typeof details.receive.end,
> +         "The eventTimings details data has an incorrect |receive| property.");
> +

Same here, the test can't be generic like that,
you should assert only the value you are expecting here.

::: devtools/shared/webconsole/network-monitor.js
@@ +1398,5 @@
> +    let timedChannel = channel.QueryInterface(Ci.nsITimedChannel);
> +
> +    // details.launchServiceWorker
> +    if (0 !== timedChannel.launchServiceWorkerStartTime &&
> +        0 !== timedChannel.launchServiceWorkerEndTime) {

Do you have to be that strict?
Would it be enough to do:
if (timedChannel.launchServiceWorkerStartTime &&
    timedChannel.launchServiceWorkerEndTime) {
?

::: devtools/shared/webconsole/test/test_network_post.html
@@ +266,5 @@
> +         start: 0,
> +         end: 0
> +       };
> +     }
> +   });

You shouldn't do that for every field but only the one where it is undefined otherwise you are going to hide failures here.

Comment 32

[Hsin-Yi Tsai (she/her) [:hsinyi]]

Tom, could you please follow up from what Ho-Pang has done?

Comment 33

[Tom Tung [:tt, :ttung]]

Sure!

Comment 34

[Ben Hsu [:HoPang]]

Attachment: (V2) P2: Make devtools-client use the newly added detailed timing information

Comment 35

[Ben Hsu [:HoPang]]

Attachment: (V2) P3: Adding new locale strings

Comment 37

[Hubert Boma Manilla (:bomsy)]

Note from Bug 1710587 : Add detailed reason for whatever service worker timing is displayed.

Comment 38

[Hubert Boma Manilla (:bomsy)]

Attachment: Bug 1353798 - [devtools] Cleanup server timings r=#devtools-reviewers

Depends on D191568

Comment 39

[Hubert Boma Manilla (:bomsy)]

Attachment: WIP: Bug 1353798 - [devtools] Experimenting with listening for service worker content requests

Comment 40

[Hubert Boma Manilla (:bomsy)]

Attachment: Bug 1353798 - [devtools] Display service worker timings in the devtools UI r=#devtools-reviewers

Depends on D193429

Comment 41

[Hubert Boma Manilla (:bomsy)]

Attachment: Bug 1353798 - [devtools] Add documentation for service worker timings r=#devtools-reviewers

Depends on D195238

Comment 42

[Hubert Boma Manilla (:bomsy)]

Attachment: Bug 1353798 - [devtools] Cleanup the timing bar calculations r=#devtools-reviewers

Depends on D195238

Comment 43

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/0e4cb906d997
[devtools] Cleanup server timings r=devtools-reviewers,ochameau,webdriver-reviewers,whimboo
https://hg.mozilla.org/integration/autoland/rev/79d1341d90d1
[devtools] Display service worker timings in the devtools UI r=devtools-reviewers,webdriver-reviewers,perftest-reviewers,ochameau,sparky
https://hg.mozilla.org/integration/autoland/rev/a450d0d4e0b8
[devtools] Cleanup the timing bar calculations r=devtools-reviewers,nchevobbe
https://hg.mozilla.org/integration/autoland/rev/94a07cbcc6f9
[devtools] Add documentation for service worker timings r=devtools-reviewers,ochameau

Comment 44

[Cristina Horotan [:chorotan]]

https://hg.mozilla.org/mozilla-central/rev/0e4cb906d997
https://hg.mozilla.org/mozilla-central/rev/79d1341d90d1
https://hg.mozilla.org/mozilla-central/rev/a450d0d4e0b8
https://hg.mozilla.org/mozilla-central/rev/94a07cbcc6f9