If you think a bug might affect users in the 57 release, please set the correct tracking and status flags for Release Management.

add network panel timing markers for ServiceWorker interception

RESOLVED FIXED in Firefox 55

Status

()

Firefox
Developer Tools: Netmonitor
P3
normal
RESOLVED FIXED
2 years ago
6 months ago

People

(Reporter: bkelly, Assigned: HoPang)

Tracking

(Blocks: 3 bugs)

unspecified
Firefox 55
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox55 fixed)

Details

(Whiteboard: [swdev-m1])

Attachments

(7 attachments, 10 obsolete attachments)

438.04 KB, image/png
Details
8.08 KB, patch
HoPang
: review+
Details | Diff | Splinter Review
5.23 KB, patch
HoPang
: review+
Details | Diff | Splinter Review
6.87 KB, patch
HoPang
: review+
Details | Diff | Splinter Review
6.04 KB, patch
HoPang
: review+
Details | Diff | Splinter Review
1.24 KB, patch
HoPang
: review+
Details | Diff | Splinter Review
6.75 KB, patch
HoPang
: review+
Details | Diff | Splinter Review
(Reporter)

Description

2 years ago
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

2 years ago
Panos, do you know how these markers work?
Flags: needinfo?(past)
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
Flags: needinfo?(past)
(Reporter)

Updated

10 months ago
Blocks: 1262699
(Reporter)

Comment 3

10 months ago
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.
See Also: → bug 1043083
Priority: -- → P3
(Assignee)

Updated

8 months ago
Assignee: nobody → bhsu
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/
Flags: needinfo?(bkelly)
(Reporter)

Comment 5

8 months ago
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.
Flags: needinfo?(bkelly)
(Assignee)

Comment 6

8 months ago
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.
(Reporter)

Comment 7

8 months ago
(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.
(Assignee)

Comment 8

8 months ago
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.

Updated

8 months ago
Whiteboard: [swdev-m1]
(Assignee)

Comment 9

7 months ago
Created attachment 8847900 [details] [diff] [review]
P1: Extend nsITimedChannel for logging service worker interception related timestamps
(Assignee)

Comment 10

7 months ago
Created attachment 8847901 [details] [diff] [review]
P2: Add service worker interception timestamp logging APIs to nsIInterceptedChannel
(Assignee)

Comment 11

7 months ago
Created attachment 8847902 [details] [diff] [review]
P3: Insert the timestamp probes into service worker implementation
(Assignee)

Comment 12

7 months ago
Created attachment 8847903 [details] [diff] [review]
P4: Extended related IPDL and implementation to pass service worker interception timestamps
(Assignee)

Comment 13

7 months ago
Created attachment 8847904 [details] [diff] [review]
P5: Copy service worker interception timeStamps during HttpChannel redirection
(Assignee)

Comment 14

7 months ago
Created attachment 8847906 [details] [diff] [review]
P6: Create a chrome mochitest testcase
(Assignee)

Comment 15

7 months ago
Created attachment 8849042 [details]
WIP.png
(Assignee)

Updated

7 months ago
Flags: needinfo?(bkelly)
(Reporter)

Comment 16

7 months ago
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?
Attachment #8847900 - Flags: review?(valentin.gosu)
Attachment #8847900 - Flags: feedback+
(Reporter)

Comment 17

7 months ago
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.
Attachment #8847901 - Flags: review?(valentin.gosu)
Attachment #8847901 - Flags: feedback+
Attachment #8847900 - Flags: review?(valentin.gosu) → review+
Attachment #8847901 - Flags: review?(valentin.gosu) → review+
(Reporter)

Comment 18

7 months ago
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.
Attachment #8847902 - Flags: review+
(Reporter)

Updated

7 months ago
Attachment #8847903 - Flags: review?(valentin.gosu)
Attachment #8847903 - Flags: feedback+
Attachment #8847903 - Flags: review?(valentin.gosu) → review+
(Reporter)

Comment 19

7 months ago
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.
Attachment #8847904 - Flags: review?(valentin.gosu)
(Reporter)

Comment 20

7 months ago
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.
Attachment #8847906 - Flags: review+
(Reporter)

Updated

7 months ago
Flags: needinfo?(bkelly)
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.
Attachment #8847904 - Flags: review?(valentin.gosu) → review+
(Assignee)

Updated

7 months ago
Blocks: 1353798
(Assignee)

Comment 22

6 months ago
Created attachment 8856441 [details] [diff] [review]
P2: Add service worker interception timestamp logging APIs to nsIInterceptedChannel

Fix a warning.
(Assignee)

Comment 23

6 months ago
Created attachment 8856442 [details] [diff] [review]
P3: Insert the timestamp probes into service worker implementation

Address the comments.
(Assignee)

Comment 24

6 months ago
Created attachment 8856443 [details] [diff] [review]
P5: Copy service worker interception timeStamps during HttpChannel redirection

Address the comments.
(Assignee)

Comment 25

6 months ago
Created attachment 8856445 [details] [diff] [review]
P6: Create a chrome mochitest testcase

Update the testcase due to the behavior change.
(Assignee)

Updated

6 months ago
Attachment #8856441 - Attachment is obsolete: true
(Assignee)

Updated

6 months ago
Attachment #8856442 - Attachment is obsolete: true
(Assignee)

Updated

6 months ago
Attachment #8856443 - Attachment is obsolete: true
(Assignee)

Updated

6 months ago
Attachment #8856445 - Attachment is obsolete: true
(Assignee)

Comment 26

6 months ago
Created attachment 8856879 [details] [diff] [review]
P1: Extend nsITimedChannel for logging service worker interception related timestamps.

Update the commit message with reviewer.
(Assignee)

Comment 27

6 months ago
Created attachment 8856880 [details] [diff] [review]
(V2) P2: Add service worker interception timestamp logging APIs to nsIInterceptedChannel.

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

Comment 28

6 months ago
Created attachment 8856883 [details] [diff] [review]
(V2) P3: Insert the timestamp probes into service worker implementation.

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

Comment 29

6 months ago
Created attachment 8856885 [details] [diff] [review]
P4: Extended related IPDL and implementation to pass service worker interception timestamps.

Update the commit message with reviewer.
(Assignee)

Comment 30

6 months ago
Created attachment 8856887 [details] [diff] [review]
(V2) P5: Copy service worker interception timeStamps during HttpChannel redirection.

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

Comment 31

6 months ago
Created attachment 8856888 [details] [diff] [review]
(V2) P6: Create a chrome mochitest testcase.

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

Updated

6 months ago
Attachment #8847900 - Attachment is obsolete: true
(Assignee)

Updated

6 months ago
Attachment #8847901 - Attachment is obsolete: true
(Assignee)

Updated

6 months ago
Attachment #8847902 - Attachment is obsolete: true
(Assignee)

Updated

6 months ago
Attachment #8847903 - Attachment is obsolete: true
(Assignee)

Updated

6 months ago
Attachment #8847904 - Attachment is obsolete: true
(Assignee)

Updated

6 months ago
Attachment #8847906 - Attachment is obsolete: true
(Assignee)

Updated

6 months ago
Attachment #8856879 - Flags: review+
(Assignee)

Updated

6 months ago
Attachment #8856880 - Flags: review+
(Assignee)

Updated

6 months ago
Attachment #8856883 - Flags: review+
(Assignee)

Updated

6 months ago
Attachment #8856885 - Flags: review+
(Assignee)

Updated

6 months ago
Attachment #8856887 - Flags: review+
(Assignee)

Updated

6 months ago
Attachment #8856888 - Flags: review+
(Assignee)

Comment 32

6 months ago
https://treeherder.mozilla.org/#/jobs?repo=try&revision=3569597f66d1d3786472400de7bf2ef1612c12c9
Keywords: checkin-needed

Comment 33

6 months ago
Pushed by ryanvm@gmail.com:
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
Keywords: checkin-needed

Comment 34

6 months ago
bugherder
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
Status: NEW → RESOLVED
Last Resolved: 6 months ago
status-firefox55: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 55
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.
(Reporter)

Comment 36

6 months ago
I think that is being done in a follow-up, bug 1353798.
You need to log in before you can comment on or make changes to this bug.