1168875 - add network panel timing markers for ServiceWorker interception

Status: RESOLVED FIXED

(DevTools :: Netmonitor, defect, P3)

Description

[Ben Kelly [:bkelly, not reviewing]]

It would be nice to add some network panel timing markers for certain events when the ServiceWorker does interception.  It seems this might be somewhat straightforward, although main-thread-only issues might create some problems.

Comment 1

[(no longer active)]

Panos, do you know how these markers work?

Comment 2

[Panos Astithas (he/him) [:past] (please ni?)]

What do you mean by markers in this case? Adding details that will appear in the Timings tab in the details view of a request?

If so, you probably want to handle the events in NM_observeActivity and perhaps even NM__setupHarTimings:

https://dxr.mozilla.org/mozilla-central/source/toolkit/devtools/webconsole/network-monitor.js#657
https://dxr.mozilla.org/mozilla-central/source/toolkit/devtools/webconsole/network-monitor.js#1080

Comment 3

[Ben Kelly [:bkelly, not reviewing]]

Note, it would also be nice to show the service worker start time.  Its spec'd for the performance API here:

https://w3c.github.io/navigation-timing/#PerformanceResourceTiming

We don't have that navigation timing spec implemented, but it would be nice to start tracking the value and showing it in devtools.

Comment 4

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

I like the idea.

We might want to implement this similarly to how Firebug implemented console.timeStamp() [1]. This API allowed the user to put a custom marker on Net panel's timeline. The result is new vertical line (similarly to how 'load' and 'DOMContentLoaded' events are rendered).

The ServiceWorker could be also able to call this API and produce markers in the Net panel's timeline any time the user wants to.

Apart from ServiceWorker start time. What other events should be rendered on the Network panel's timeline?

I am not sure what do you mean by "add some network panel timing markers for certain events when the ServiceWorker does interception."

Honza

[1] http://www.softwareishard.com/blog/firebug/firebug-1-8-console-timestamp/

Comment 5

[Ben Kelly [:bkelly, not reviewing]]

The main markers I would like are:

1) Time to start the service worker, if it needs to be started
2) Time to fire the FetchEvent in the service worker
3) Time when FetchEvent.respondWith() resolves, if its called
4) Maybe the time when FetchEvent handler ends without calling respondWith().  This will likely be nearly exactly the same as (2), though.

This will let us show the time over which the service worker is "controlling" the fetch interaction.  Large sites using service workers care a lot about (1) and (2) here.

Comment 6

[Ben Hsu [:HoPang]]

Hi Ben, 

Tom and I have reached some consensus on this issue. For the 4 time markers, we think they should inject the probes at the following places.

1. ServiceWorkerPrivate::SpawnWorkerIfNeeded
http://searchfox.org/mozilla-central/source/dom/workers/ServiceWorkerPrivate.cpp#1680

2. FetchEventRunnable::DispatchFetchEvent
http://searchfox.org/mozilla-central/source/dom/workers/ServiceWorkerPrivate.cpp#1576-1578

3. FinishResponse::Run
http://searchfox.org/mozilla-central/source/dom/workers/ServiceWorkerEvents.cpp#232

4) FetchEventRunnable::DispatchFetchEvent (serves both fail case and not involing respondWith())
http://searchfox.org/mozilla-central/source/dom/workers/ServiceWorkerPrivate.cpp#1580

OTOH, since there the time markers in nsITimedChannel are in the form of pairs, should we do that to those for service workers?

As to the topics, we think we are not going any in the bug, because we think there already are topics for notifying the network result no matter the network response has been intercepted and synthesized.

The last thing is that, for the testcase, we are planning to write a mochitest in which we add observers to ObserverService to check the result and status of each response.

Comment 7

[Ben Kelly [:bkelly, not reviewing]]

(In reply to Ben Hsu [:HoPang] from comment #6)
> 1. ServiceWorkerPrivate::SpawnWorkerIfNeeded
> http://searchfox.org/mozilla-central/source/dom/workers/ServiceWorkerPrivate.
> cpp#1680

This gets called for all kinds of things.  You might need to conditionally pass the info back to the fetch event caller in order to add it to the channel.

> OTOH, since there the time markers in nsITimedChannel are in the form of
> pairs, should we do that to those for service workers?

That might be challenging.  For example, a fetch event might trigger a worker startup in SpawnWorkerIfNeeded(), but you won't know the end time until the WorkerPrivate PrimaryWorkerRunnable loop is fully started on a different thread.  In the meantime you may get many more events asking to start the ServiceWorker.

Ideally I think you would just track worker spawn start and end for the first event that caused the worker to start.

In addition, we could track:

1) Start time when we decide to dispatch a FetchEvent
2) Time when we actually dispatch the event on the service worker thread

The difference could be near zero if the worker is already started or match the full worker startup time.  Or it could be a value in-between if the worker startup is in progress.

I think having separate "overhead time to dispatch event" and "worker startup time" would let us answer the questions we want, though.

1) How long does it actually take to dispatch?
2) Of that time to dispatch how much of it is explained by having to start the worker thread?

So I guess, yes, we could do start/end.  Spawn start/end and dispatch start/end.

For the others we could measure them as:

3) Dispatch time on worker thread starts fetch event handler time.  Return from fetch event handler is end of this measurement.
4) Synthesize time could be measured as starting when respondWith() is called and ending when the respondWith() body is complete.

To be honest, we might need to experiment a bit to see what makes sense in the tool on real sites.

I hope this helps.  I really only have a vague idea of how it should work unfortunately.

Comment 8

[Ben Hsu [:HoPang]]

Thanks for your response,

> That might be challenging.  For example, a fetch event might trigger a
> worker startup in SpawnWorkerIfNeeded(), but you won't know the end time
> until the WorkerPrivate PrimaryWorkerRunnable loop is fully started on a
> different thread.  In the meantime you may get many more events asking to
> start the ServiceWorker.

Yes, this is what I've been worried about...

> Ideally I think you would just track worker spawn start and end for the
> first event that caused the worker to start.
> 
> In addition, we could track:
> 
> 1) Start time when we decide to dispatch a FetchEvent
> 2) Time when we actually dispatch the event on the service worker thread
> 
> The difference could be near zero if the worker is already started or match
> the full worker startup time.  Or it could be a value in-between if the
> worker startup is in progress.
> 
> I think having separate "overhead time to dispatch event" and "worker
> startup time" would let us answer the questions we want, though.
> 
> 1) How long does it actually take to dispatch?
> 2) Of that time to dispatch how much of it is explained by having to start
> the worker thread?
> 
> So I guess, yes, we could do start/end.  Spawn start/end and dispatch
> start/end.

Okay, let's do it.

> For the others we could measure them as:
> 
> 3) Dispatch time on worker thread starts fetch event handler time.  Return
> from fetch event handler is end of this measurement.
> 4) Synthesize time could be measured as starting when respondWith() is
> called and ending when the respondWith() body is complete.
> 
> To be honest, we might need to experiment a bit to see what makes sense in
> the tool on real sites.

I believe there will be an overlap between (3) and (4), but I think we can make the values more meaningful after some testing with real sites as you said.

> I hope this helps.  I really only have a vague idea of how it should work
> unfortunately.

This does help, and thanks again.

Comment 9

[Ben Hsu [:HoPang]]

Attachment: P1: Extend nsITimedChannel for logging service worker interception related timestamps

Comment 10

[Ben Hsu [:HoPang]]

Attachment: P2: Add service worker interception timestamp logging APIs to nsIInterceptedChannel

Comment 11

[Ben Hsu [:HoPang]]

Attachment: P3: Insert the timestamp probes into service worker implementation

Comment 12

[Ben Hsu [:HoPang]]

Attachment: P4: Extended related IPDL and implementation to pass service worker interception timestamps

Comment 13

[Ben Hsu [:HoPang]]

Attachment: P5: Copy service worker interception timeStamps during HttpChannel redirection

Comment 14

[Ben Hsu [:HoPang]]

Attachment: P6: Create a chrome mochitest testcase

Comment 15

[Ben Hsu [:HoPang]]

Attachment: WIP.png

Comment 16

[Ben Kelly [:bkelly, not reviewing]]

Comment on attachment 8847900 [details] [diff] [review]
P1: Extend nsITimedChannel for logging service worker interception related timestamps

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

This looks good to me, but we need a network peer to sign off on it.  Valentin, can you take a look?

Comment 17

[Ben Kelly [:bkelly, not reviewing]]

Comment on attachment 8847901 [details] [diff] [review]
P2: Add service worker interception timestamp logging APIs to nsIInterceptedChannel

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

Looks good to me, but lets get a necko peer to review it.

Comment 18

[Ben Kelly [:bkelly, not reviewing]]

Comment on attachment 8847902 [details] [diff] [review]
P3: Insert the timestamp probes into service worker implementation

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

Looks good.  I think we just need to adjust the LaunchServiceWorkerEnd time a bit.  r=me with comments addressed.

::: dom/workers/ServiceWorkerEvents.cpp
@@ +235,5 @@
>        return NS_OK;
>      }
>  
> +    mChannel->SetHandleFetchEventEnd(TimeStamp::Now());
> +    mChannel->SaveTimeStampsToUnderlyingChannel();

If/when bug 1204254 is implemented this will need to move to the point where the body is complete and not when we synthesize the cache entry.  Maybe add a comment indicating this is trying to measure the body completion so that we don't miss it.

::: dom/workers/ServiceWorkerPrivate.cpp
@@ +1660,4 @@
>    nsresult rv = SpawnWorkerIfNeeded(FetchEvent, failRunnable, aLoadGroup);
>    NS_ENSURE_SUCCESS(rv, rv);
>  
> +  aChannel->SetLaunchServiceWorkerEnd(TimeStamp::Now());

So, we need to actually wait for the service worker to start before measuring the end time.  The best way to do this is in a WorkerRunnable dispatched to the new WorkerPrivate.  Conveniently, we are about to dispatch the FetchEventRunnable there.  So I propose we:

1. Modify SpawnWorkerIfNeeded() to surface a boolean or enum indicating if a new WorkerPrivate was created or not.
2. If it did not create a WorkerPrivate, then you can measure the end value immediately like you are doing here.
3. If it did create a WorkerPrivate, then set a flag on FetchEventRunnable indicating that.
4. FetchEventRunnable::WorkerRun() can then measure the LaunchServiceWorkerEnd time if that flag is set.

@@ +1670,4 @@
>  
>    RefPtr<KeepAliveToken> token = CreateEventKeepAliveToken();
>  
> +  aChannel->SetDispatchFetchEventStart(TimeStamp::Now());

Perhaps we should move this up to where we measure SetLaunchServiceWorkerStart?  That would make it clearer that we are measuring overlapping ranges with LaunchServiceWorker and DispatchFetchEvent.

Comment 19

[Ben Kelly [:bkelly, not reviewing]]

Comment on attachment 8847904 [details] [diff] [review]
P5: Copy service worker interception timeStamps during HttpChannel redirection

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

Do we want to do this for all redirects?

It seems to me we probably want to copy timing information for internal redirects.  We often do this after a service worker interception.

If the service worker responds with a 302 status code, though, should we have intercept timing information on the new channel?  I'm not sure.  If its a non-subresource request the further redirects can be intercepted again.

Comment 20

[Ben Kelly [:bkelly, not reviewing]]

Comment on attachment 8847906 [details] [diff] [review]
P6: Create a chrome mochitest testcase

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

::: dom/workers/test/serviceworkers/test_devtools_serviceworker_interception.html
@@ +103,5 @@
> +                                timedChannel.handleFetchEventStartTime,
> +                                timedChannel.handleFetchEventEndTime];
> +    if (aIntercepted) {
> +      serviceWorkerTimings.reduce((aPreviousTiming, aCurrentTiming) => {
> +        ok(aPreviousTiming < aCurrentTiming);

I'm not sure this will be valid once we fix the launchServiceWorkerEndTime.  If the SW is actually being started then it should fall after the dispatchFetchEventStartTime.

Comment 21

[Valentin Gosu [:valentin] (he/him)]

Comment on attachment 8847904 [details] [diff] [review]
P5: Copy service worker interception timeStamps during HttpChannel redirection

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

The code looks fine, but Ben's question about when we should copy the timestamps needs to be addressed.

Comment 22

[Ben Hsu [:HoPang]]

Attachment: P2: Add service worker interception timestamp logging APIs to nsIInterceptedChannel

Fix a warning.

Comment 23

[Ben Hsu [:HoPang]]

Attachment: P3: Insert the timestamp probes into service worker implementation

Address the comments.

Comment 24

[Ben Hsu [:HoPang]]

Attachment: P5: Copy service worker interception timeStamps during HttpChannel redirection

Address the comments.

Comment 25

[Ben Hsu [:HoPang]]

Attachment: P6: Create a chrome mochitest testcase

Update the testcase due to the behavior change.

Comment 26

[Ben Hsu [:HoPang]]

Attachment: P1: Extend nsITimedChannel for logging service worker interception related timestamps.

Update the commit message with reviewer.

Comment 27

[Ben Hsu [:HoPang]]

Attachment: (V2) P2: Add service worker interception timestamp logging APIs to nsIInterceptedChannel.

Update the commit message with reviewer, and fix a compilation warning.

Comment 28

[Ben Hsu [:HoPang]]

Attachment: (V2) P3: Insert the timestamp probes into service worker implementation.

1. Update the commit message with reviewer.
2. Address the comments in comment 18.

Comment 29

[Ben Hsu [:HoPang]]

Attachment: P4: Extended related IPDL and implementation to pass service worker interception timestamps.

Update the commit message with reviewer.

Comment 30

[Ben Hsu [:HoPang]]

Attachment: (V2) P5: Copy service worker interception timeStamps during HttpChannel redirection.

1. Update the commit message with reviewer.
2. Address the comments in comment 19.

Comment 31

[Ben Hsu [:HoPang]]

Attachment: (V2) P6: Create a chrome mochitest testcase.

1. Update the commit message with reviewer.
2. Update the testcase due to the implementation change.

Comment 32

[Ben Hsu [:HoPang]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=3569597f66d1d3786472400de7bf2ef1612c12c9

Comment 33

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/4e1b666a2f90
Part 1: Extend nsITimedChannel for logging service worker interception related timestamps. f=bkelly, r=valentin
https://hg.mozilla.org/integration/mozilla-inbound/rev/35b82c9a9788
Part 2: Add service worker interception timestamp logging APIs to nsIInterceptedChannel. f=bkelly, r=valentin
https://hg.mozilla.org/integration/mozilla-inbound/rev/58d054859d4c
Part 3: Insert the timestamp probes into service worker implementation. r=bkelly
https://hg.mozilla.org/integration/mozilla-inbound/rev/81e058af759d
Part 4: Extend related IPDL and implementation to pass service worker interception timestamps. f=bkelly, r=valentin
https://hg.mozilla.org/integration/mozilla-inbound/rev/4182a2d76893
Part 5: Copy service worker interception timeStamps during HttpChannel redirection. r=valentin
https://hg.mozilla.org/integration/mozilla-inbound/rev/9303577ac72b
Part 6: Create a chrome mochitest testcase. r=bkelly

Comment 34

[Iris Hsiao [:ihsiao]]

https://hg.mozilla.org/mozilla-central/rev/4e1b666a2f90
https://hg.mozilla.org/mozilla-central/rev/35b82c9a9788
https://hg.mozilla.org/mozilla-central/rev/58d054859d4c
https://hg.mozilla.org/mozilla-central/rev/81e058af759d
https://hg.mozilla.org/mozilla-central/rev/4182a2d76893
https://hg.mozilla.org/mozilla-central/rev/9303577ac72b

Comment 35

[Cătălin Badea (:catalinb)]

Are these values displayed in the network panel, like in the attached screenshot? For some reason, I don't see them in the latest nightly.

Comment 36

[Ben Kelly [:bkelly, not reviewing]]

I think that is being done in a follow-up, bug 1353798.