Closed
Bug 1168875
Opened 10 years ago
Closed 8 years ago
add network panel timing markers for ServiceWorker interception
Categories
(DevTools :: Netmonitor, defect, P3)
DevTools
Netmonitor
Tracking
(firefox55 fixed)
RESOLVED
FIXED
Firefox 55
Tracking | Status | |
---|---|---|
firefox55 | --- | fixed |
People
(Reporter: bkelly, Assigned: bhsu)
References
(Blocks 2 open bugs)
Details
(Whiteboard: [swdev-m1])
Attachments
(7 files, 10 obsolete files)
(deleted),
image/png
|
Details | |
(deleted),
patch
|
bhsu
:
review+
|
Details | Diff | Splinter Review |
(deleted),
patch
|
bhsu
:
review+
|
Details | Diff | Splinter Review |
(deleted),
patch
|
bhsu
:
review+
|
Details | Diff | Splinter Review |
(deleted),
patch
|
bhsu
:
review+
|
Details | Diff | Splinter Review |
(deleted),
patch
|
bhsu
:
review+
|
Details | Diff | Splinter Review |
(deleted),
patch
|
bhsu
:
review+
|
Details | Diff | Splinter Review |
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 2•10 years ago
|
||
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•8 years ago
|
Blocks: dt-service-worker
Reporter | ||
Comment 3•8 years 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.
Updated•8 years ago
|
Priority: -- → P3
Assignee | ||
Updated•8 years ago
|
Assignee: nobody → bhsu
Comment 4•8 years ago
|
||
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 years 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 years 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 years 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 years 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 years ago
|
Whiteboard: [swdev-m1]
Assignee | ||
Comment 9•8 years ago
|
||
Assignee | ||
Comment 10•8 years ago
|
||
Assignee | ||
Comment 11•8 years ago
|
||
Assignee | ||
Comment 12•8 years ago
|
||
Assignee | ||
Comment 13•8 years ago
|
||
Assignee | ||
Comment 14•8 years ago
|
||
Assignee | ||
Comment 15•8 years ago
|
||
Assignee | ||
Updated•8 years ago
|
Flags: needinfo?(bkelly)
Reporter | ||
Comment 16•8 years 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•8 years 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+
Updated•8 years ago
|
Attachment #8847900 -
Flags: review?(valentin.gosu) → review+
Updated•8 years ago
|
Attachment #8847901 -
Flags: review?(valentin.gosu) → review+
Reporter | ||
Comment 18•8 years 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•8 years ago
|
Attachment #8847903 -
Flags: review?(valentin.gosu)
Attachment #8847903 -
Flags: feedback+
Updated•8 years ago
|
Attachment #8847903 -
Flags: review?(valentin.gosu) → review+
Reporter | ||
Comment 19•8 years 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•8 years 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•8 years ago
|
Flags: needinfo?(bkelly)
Comment 21•8 years ago
|
||
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 | ||
Comment 22•8 years ago
|
||
Fix a warning.
Assignee | ||
Comment 23•8 years ago
|
||
Address the comments.
Assignee | ||
Comment 24•8 years ago
|
||
Address the comments.
Assignee | ||
Comment 25•8 years ago
|
||
Update the testcase due to the behavior change.
Assignee | ||
Updated•8 years ago
|
Attachment #8856441 -
Attachment is obsolete: true
Assignee | ||
Updated•8 years ago
|
Attachment #8856442 -
Attachment is obsolete: true
Assignee | ||
Updated•8 years ago
|
Attachment #8856443 -
Attachment is obsolete: true
Assignee | ||
Updated•8 years ago
|
Attachment #8856445 -
Attachment is obsolete: true
Assignee | ||
Comment 26•8 years ago
|
||
Update the commit message with reviewer.
Assignee | ||
Comment 27•8 years ago
|
||
Update the commit message with reviewer, and fix a compilation warning.
Assignee | ||
Comment 28•8 years ago
|
||
1. Update the commit message with reviewer.
2. Address the comments in comment 18.
Assignee | ||
Comment 29•8 years ago
|
||
Update the commit message with reviewer.
Assignee | ||
Comment 30•8 years ago
|
||
1. Update the commit message with reviewer.
2. Address the comments in comment 19.
Assignee | ||
Comment 31•8 years ago
|
||
1. Update the commit message with reviewer.
2. Update the testcase due to the implementation change.
Assignee | ||
Updated•8 years ago
|
Attachment #8847900 -
Attachment is obsolete: true
Assignee | ||
Updated•8 years ago
|
Attachment #8847901 -
Attachment is obsolete: true
Assignee | ||
Updated•8 years ago
|
Attachment #8847902 -
Attachment is obsolete: true
Assignee | ||
Updated•8 years ago
|
Attachment #8847903 -
Attachment is obsolete: true
Assignee | ||
Updated•8 years ago
|
Attachment #8847904 -
Attachment is obsolete: true
Assignee | ||
Updated•8 years ago
|
Attachment #8847906 -
Attachment is obsolete: true
Assignee | ||
Updated•8 years ago
|
Attachment #8856879 -
Flags: review+
Assignee | ||
Updated•8 years ago
|
Attachment #8856880 -
Flags: review+
Assignee | ||
Updated•8 years ago
|
Attachment #8856883 -
Flags: review+
Assignee | ||
Updated•8 years ago
|
Attachment #8856885 -
Flags: review+
Assignee | ||
Updated•8 years ago
|
Attachment #8856887 -
Flags: review+
Assignee | ||
Updated•8 years ago
|
Attachment #8856888 -
Flags: review+
Assignee | ||
Comment 32•8 years ago
|
||
Keywords: checkin-needed
Comment 33•8 years 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•8 years 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
Closed: 8 years ago
status-firefox55:
--- → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 55
Comment 35•8 years ago
|
||
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•8 years ago
|
||
I think that is being done in a follow-up, bug 1353798.
Updated•6 years ago
|
Product: Firefox → DevTools
You need to log in
before you can comment on or make changes to this bug.
Description
•