New issue
Advanced search Search tips

Issue 782958 link

Starred by 4 users

Issue metadata

Status: Assigned
Owner:
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: ----
Pri: 3
Type: Bug

Blocked on:
issue 715640



Sign in to add a comment

Fix workerStart and fetchStart implementation and timing

Project Member Reported by falken@chromium.org, Nov 8 2017

Issue description

Update (2018-06-11, bashi@ on comment 21):
Let me leave some comments of current status and the next step:
- Currently PerformanceNavigationTiming#workerStart isn't set properly. It doesn't contain SW startup time. We need to fix it.
- We are going to fix it as a part of service worker servicification (S13nServiceWorker).

Original description:
This is for requests intercepted by a service worker. From code inspection and some reports, I think we've got some bugs here.
* (based on https://github.com/w3c/resource-timing/issues/119) workerStart should be <= than fetchStart, which we try to do, but seems sometimes we don't 
* we're not setting workerStart on network fallback
* we probably have fetchStart wrong on network fallback
 
This could be high P1 as sites are expecting to get useful data from workerStart/fetchStart.
 
Description: Show this description
I'm not quite familiar with that API, but fetchStart seems marked before starting network request which is possibly intercepted by a service worker.
https://cs.chromium.org/chromium/src/content/browser/frame_host/navigation_request.cc?type=cs&sq=package:chromium&l=1022

workerStart looks right.
https://cs.chromium.org/chromium/src/content/browser/service_worker/service_worker_url_request_job.cc?type=cs&l=1011


Although we set worker_start_time_, it's not actually used when the request falls back to network:
https://cs.chromium.org/chromium/src/content/browser/service_worker/service_worker_url_request_job.cc?l=941&rcl=516ae0d2cab5f33ddfbaef3c1199a239d6fdf9f5
Components: -Blink>PerformanceAPIs Blink>PerformanceAPIs>ResourceTiming

fetchStart may be different for PerformanceNavigationTiming vs PerformanceResourceTiming.

For resource timing, it comes from PerformanceResourceTiming::fetchStart:
https://cs.chromium.org/chromium/src/third_party/WebKit/Source/core/timing/PerformanceResourceTiming.cpp?l=185&rcl=cccda43345d0c7ff7fd680882a9478de8dd0ceec

We take worker_ready_time if it's available, which gets plumbed from ServiceWorkerURLRequestJob's |worker_ready_time| which is set right before dispatching the fetch event, but it's also not used when network fallback occurred.

Probably our behavior on redirects/fallback have to be examined more closely.

Comment 6 by falken@chromium.org, Feb 16 2018

Owner: bashi@chromium.org
Status: Assigned (was: Available)

Comment 7 by bashi@chromium.org, Feb 22 2018

I'm still understanding specs and our implementation but I have some updates.

Currently service-workers/service-worker/resource-timing.https.html is failing.
https://cs.chromium.org/chromium/src/third_party/WebKit/LayoutTests/external/wpt/service-workers/service-worker/resource-timing.https-expected.txt?l=1&rcl=692b8e57542917a11c5c6c5fb62a9787925e8ec7

I don't think this is failing because we aren't setting workerStart on NW fallback. I think the cause of the failure is that we don't add PerformanceResourceTiming object to the performance.getEntries() when a resource loading failed. In the test, we try to get a PerformanceResourceTiming for 'resources/missing.jpg', which turns out null, because we don't add entreis for resouces which failed to load. Probably we should fix the test to check there is an entry for the given url.

(Note: Firefox may be passing the test as they add PerformanceResourceTiming entries for resouces which failed to load. Either behavior should be fine as the spec says that "Resources for which the fetch was initiated, but was later aborted (e.g. due to a network error) MAY be included as PerformanceResourceTiming objects in the Performance Timeline." https://w3c.github.io/resource-timing/#resources-included-in-the-performanceresourcetiming-interface)


Regarding not setting workerStart on NW fallback, I think the current behavior is fine. We only fallback to NW when there is no SW.
https://cs.chromium.org/chromium/src/content/browser/service_worker/service_worker_controllee_request_handler.cc?l=49&rcl=8eaae0b1d1c61b848ef3e40a052c0ee90287ca08

The spec says that workerStart should be zero when there is no active SW. If no SW exists, there wouldn't be an active SW.


Regarding workerStart/fetchStart, I observed workerStart > fetchStart in PerformanceNavigationTiming when I opened a content_shell with SW installed. As described, I think it should always be workerStart <= fetchStart. I'm investigating why this is happening.

Comment 8 by bke...@mozilla.com, Feb 22 2018

In regards to the change to resource-timing.https.html, it seems like maybe the intent of the test was changed.

The checks being changed were described as "network fallback", not "failed load".  In particular I added this check to cover network fallback for cross-origin no-cors requests.  This is relevant because the spec blocks access to information on some of these values via the Timing-Allow-Origin header.  It should be allowed here.

It seems like the change to ignore the check basically loses the cross-origin no-cors network fallback test coverage on chromium.  Would it make sense to instead change the test to reference an existing image instead?

Comment 9 by falken@chromium.org, Feb 22 2018

bkelly: Thanks! Using an existing image is what we ended up decided to do in https://chromium-review.googlesource.com/c/chromium/src/+/930109 (not yet committed).

Comment 10 by bke...@mozilla.com, Feb 22 2018

Oh, great!  Sorry for my confusion.

I got a wpt-sync-bot bug over here based on the upstream PR:

https://bugzilla.mozilla.org/show_bug.cgi?id=1440225

I didn't see that it hadn't landed in upstream yet.  I'm still trying to get used to this brave new world of WPT sync'ing.

Thanks again.

Comment 11 by bke...@mozilla.com, Feb 22 2018

Also note, I think wpt.fyi might show firefox failing this test because of spectre-related timer resolution issues.  In our tree we have a pref override for the test and we expect to pass:

https://searchfox.org/mozilla-central/source/testing/web-platform/meta/service-workers/service-worker/resource-timing.https.html.ini
Project Member

Comment 12 by bugdroid1@chromium.org, Feb 23 2018

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/7afe9250f043d5a6f98260f28b3a245ccb566a42

commit 7afe9250f043d5a6f98260f28b3a245ccb566a42
Author: Kenichi Ishibashi <bashi@chromium.org>
Date: Fri Feb 23 01:09:30 2018

service worker: Update WPT test for resource timing

Before this CL, the test assumed that there should be a
PerformanceResourceTiming for fetching 'resources/missing.jpg'.
As the spec says [1], this assumption is not guaranteed. In fact,
Chromium doesn't add PerformanceResourceTiming for resouces which
failed to load. This CL updates the test to check there is a
corresponding PerformanceResourceTiming entry before doing
verifications.

[1] https://w3c.github.io/resource-timing/#resources-included-in-the-performanceresourcetiming-interface

Bug: 782958
Change-Id: I85e75a8dade9f6620d22a54eaf97468f00360023
Reviewed-on: https://chromium-review.googlesource.com/930109
Reviewed-by: Matt Falkenhagen <falken@chromium.org>
Commit-Queue: Kenichi Ishibashi <bashi@chromium.org>
Cr-Commit-Position: refs/heads/master@{#538648}
[delete] https://crrev.com/af6c8baf39fb6ad83d3ef23424f2f9863c310cc7/third_party/WebKit/LayoutTests/external/wpt/service-workers/service-worker/resource-timing.https-expected.txt
[modify] https://crrev.com/7afe9250f043d5a6f98260f28b3a245ccb566a42/third_party/WebKit/LayoutTests/external/wpt/service-workers/service-worker/resource-timing.https.html
[modify] https://crrev.com/7afe9250f043d5a6f98260f28b3a245ccb566a42/third_party/WebKit/LayoutTests/external/wpt/service-workers/service-worker/resources/resource-timing-iframe.sub.html

Sorry, yes it hasn't committed yet in the Chromium tree. It has to do that first then will be auto-synced upstream to WPT.
Ohh.. that was funny timing. It committed in Chromium one minute before I wrote comment c#13.
Project Member

Comment 15 by bugdroid1@chromium.org, Mar 27 2018

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/9fa2684557b49c27f72c7fc97c5ee0904c9d21d6

commit 9fa2684557b49c27f72c7fc97c5ee0904c9d21d6
Author: Kenichi Ishibashi <bashi@chromium.org>
Date: Tue Mar 27 03:10:15 2018

service_worker: Add tests for navigation timing

This CL adds some tests for PerformanceNavigationTiming
which are involved with service worker.
- SW intercepts a navigation
- SW falls back to network
- Redirect and SW intercepts a navigation

These tests check `workerStart <= fetchStart` because starting
a worker should happen before fetching a resource when service
worker is involved.

Bug: 782958
Change-Id: Idd3fa8f76a328e77ee531b81bd91ee3db223f12c
Reviewed-on: https://chromium-review.googlesource.com/979873
Commit-Queue: Kenichi Ishibashi <bashi@chromium.org>
Reviewed-by: Makoto Shimazu <shimazu@chromium.org>
Reviewed-by: Matt Falkenhagen <falken@chromium.org>
Cr-Commit-Position: refs/heads/master@{#545935}
[add] https://crrev.com/9fa2684557b49c27f72c7fc97c5ee0904c9d21d6/third_party/WebKit/LayoutTests/external/wpt/service-workers/service-worker/navigation-timing.https-expected.txt
[add] https://crrev.com/9fa2684557b49c27f72c7fc97c5ee0904c9d21d6/third_party/WebKit/LayoutTests/external/wpt/service-workers/service-worker/navigation-timing.https.html
[add] https://crrev.com/9fa2684557b49c27f72c7fc97c5ee0904c9d21d6/third_party/WebKit/LayoutTests/external/wpt/service-workers/service-worker/resources/navigation-timing-worker.js
[add] https://crrev.com/9fa2684557b49c27f72c7fc97c5ee0904c9d21d6/third_party/WebKit/LayoutTests/flag-specific/enable-features=NetworkService/external/wpt/service-workers/service-worker/navigation-timing.https-expected.txt

Project Member

Comment 18 by bugdroid1@chromium.org, Mar 29 2018

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/2ad71d138d55feab49fe8297bf5105bcbbcaa533

commit 2ad71d138d55feab49fe8297bf5105bcbbcaa533
Author: Kenichi Ishibashi <bashi@chromium.org>
Date: Thu Mar 29 09:18:08 2018

S13nSW: Update expectation for navigation-timing.https-expected.txt

Rebaseline after r546365.

Tbr: falken@chromium.org,kinuko@chromium.org
Bug: 782958
Change-Id: I751ba813b526fef8efd758fc3e3b0967d550ffd4
Reviewed-on: https://chromium-review.googlesource.com/985675
Reviewed-by: Kenichi Ishibashi <bashi@chromium.org>
Commit-Queue: Kenichi Ishibashi <bashi@chromium.org>
Cr-Commit-Position: refs/heads/master@{#546776}
[modify] https://crrev.com/2ad71d138d55feab49fe8297bf5105bcbbcaa533/third_party/WebKit/LayoutTests/flag-specific/enable-features=NetworkService/external/wpt/service-workers/service-worker/navigation-timing.https-expected.txt

Project Member

Comment 19 by bugdroid1@chromium.org, Mar 29 2018

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/981b3796e311601d4f44d35f0aab9077195a76dc

commit 981b3796e311601d4f44d35f0aab9077195a76dc
Author: Reilly Grant <reillyg@chromium.org>
Date: Thu Mar 29 18:43:12 2018

Update virtual test expectations for navigation-timing.https.html

Rebaseline the NetworkService expectations for the
navigation-mojo-response and outofblink-cors virtual tests suites.

Bug: 782958
Change-Id: Id000af5d6c8d82255a55a58a42a9436cec99005d
Tbr: bashi@chromium.org
No-Try: true
Reviewed-on: https://chromium-review.googlesource.com/986648
Reviewed-by: Reilly Grant <reillyg@chromium.org>
Commit-Queue: Reilly Grant <reillyg@chromium.org>
Cr-Commit-Position: refs/heads/master@{#546885}
[modify] https://crrev.com/981b3796e311601d4f44d35f0aab9077195a76dc/third_party/WebKit/LayoutTests/flag-specific/enable-features=NetworkService/virtual/navigation-mojo-response/external/wpt/service-workers/service-worker/navigation-timing.https-expected.txt
[modify] https://crrev.com/981b3796e311601d4f44d35f0aab9077195a76dc/third_party/WebKit/LayoutTests/flag-specific/enable-features=NetworkService/virtual/outofblink-cors/external/wpt/service-workers/service-worker/navigation-timing.https-expected.txt

Comment 20 by bashi@chromium.org, May 18 2018

Issue 844274 has been merged into this issue.

Comment 21 by bashi@chromium.org, May 18 2018

Labels: -M-65 M-69
Let me leave some comments of current status and the next step:
- Currently PerformanceNavigationTiming#workerStart isn't set properly. It doesn't contain SW startup time. We need to fix it.
- We are going to fix it as a part of service worker servicification (S13nServiceWorker).
Description: Show this description
Blockedon: 715640
Labels: -Pri-1 -M-69 Pri-2
Project Member

Comment 25 by bugdroid1@chromium.org, Sep 7

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/65e2f0f3c514295dad505806748b0007824841ef

commit 65e2f0f3c514295dad505806748b0007824841ef
Author: Kenichi Ishibashi <bashi@chromium.org>
Date: Fri Sep 07 08:04:53 2018

S13nServiceWorker: Fix `requestStart` performance timing for navigation

ServiceWorkerNavigationLoader is responsible for setting up LoadTimingInfo
which are used to create web-exposed PerformanceResourceTiming. Specifically,
the field |send_start| in LoadTimingInfo is populated as `requestStart` in
PerformanceResourceTiming.

The resource timing spec[1] doesn't state explicitly but according to a
spec discussion[2], following ordering would be reasonable:

 workerStart <= fetchStart <= requestStart

Before this CL, ServiceWorkerNavigationLoader recorded `requestStart` before
starting a service worker, at the same time `workerStart` is recorded. This
doesn't seem a good timing because `requestStart` would be less than
`fetchStart`, which is recorded after the service worker is started.
This CL moves the timing to record |send_start| (and corresponding |send_end|)
to the time the service worker is started.

Note that web-exposed `fetchStart` still doesn't follow the above ordering
even after this CL, as we have a special case code for `fetchStart` in navigation.
A follow-up CL will address `fetchStart` case.

The wpt service-workers/service-worker/navigation-timing.https.html should
cover this change.

[1] https://w3c.github.io/resource-timing/#sec-performanceresourcetiming
[2] https://github.com/w3c/resource-timing/issues/119

Bug: 782958
Change-Id: I339d41d8c93a2cbcd053d4348d8e0f51b1134925
Reviewed-on: https://chromium-review.googlesource.com/1212423
Reviewed-by: Kinuko Yasuda <kinuko@chromium.org>
Reviewed-by: Makoto Shimazu <shimazu@chromium.org>
Commit-Queue: Kenichi Ishibashi <bashi@chromium.org>
Cr-Commit-Position: refs/heads/master@{#589458}
[modify] https://crrev.com/65e2f0f3c514295dad505806748b0007824841ef/content/browser/service_worker/service_worker_navigation_loader.cc

Project Member

Comment 26 by bugdroid1@chromium.org, Sep 10

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/e699a315a0b1ac1c051de9b4b8ca64e1b00abd00

commit e699a315a0b1ac1c051de9b4b8ca64e1b00abd00
Author: Kenichi Ishibashi <bashi@chromium.org>
Date: Mon Sep 10 01:50:21 2018

S13nServiceWorker: Fix `fetchStart` performance timing for subresources

ServiceWorkerSubresourceLoader records loading milestones. These
milestones are used to create web-exposed PerformanceResourceTiming.

Before this CL, ServiceWorkerSubresourceLoader recorded
|service_worker_ready_time| before calling GetControllerServiceWorker().
This doesn't seem a good timing to record it because:
- |service_worker_ready_time| is used to create `fetchStart` of
  PerformanceResourceTiming.
- `fetchStart` should be recorded after the controller service worker is
  ready to handle fetch event.
- But the worker may not be running until we call GetControllerServiceWorker().

This CL moves the timing to record |service_worker_raedy_time| and some others
after calling GetControllerServiceWorker(), as calling it makes sure that
the controller is running and ready to handle a fetch event.

The wpt ervice-workers/service-worker/resource-timing.https.html should
cover this change.

Bug: 782958
Change-Id: Ic6f6abd34ffdc84e002357a905e7a7726e6b5870
Reviewed-on: https://chromium-review.googlesource.com/1212244
Commit-Queue: Kenichi Ishibashi <bashi@chromium.org>
Reviewed-by: Kinuko Yasuda <kinuko@chromium.org>
Cr-Commit-Position: refs/heads/master@{#589818}
[modify] https://crrev.com/e699a315a0b1ac1c051de9b4b8ca64e1b00abd00/content/renderer/service_worker/service_worker_subresource_loader.cc

Project Member

Comment 27 by bugdroid1@chromium.org, Sep 10

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/137522b46759fe0441f801f6e7bea09ae5fb25a0

commit 137522b46759fe0441f801f6e7bea09ae5fb25a0
Author: Kenichi Ishibashi <bashi@chromium.org>
Date: Mon Sep 10 08:18:14 2018

serviece worker: Fix PerformanceNavigationTiming#fetchStart

This is a follow-up CL of crrev.com/c/1212423 and fixes timing ordering of
PerformanceNavigationTiming attributes.

Background:
`fetchStart` of PerformanceNavigationTiming comes from |fetch_start| of
NavigationTiming, which is set by NavigationRequest. Since
NavigationRequest isn't aware of service worker interception
`fetchStart` could come earlier than `workerStart` when the navigation is
routed to a service worker. However, `fetchStart` is supposed to come
after `workerStart`.

We can address this mis-ordering by using worker ready time. When
worker ready time is greater than |fetch_start| of NavigationTiming,
use worker ready time as |fetch_start|. Justifications:
- `fetchStart` is should be recorded after redirects end.
- `fetchStart` is should be recorded after `workerStart` if a service worker
  intercepted the navigation.
- There seems no particular ordering between `redirectEnd` and `workerStart`.
- NavigationRequest already updates |fetch_start| for redirects.

Bug: 782958
Change-Id: I90bdeaee73d361c9d35024f13fd0d3f91ba42b02
Reviewed-on: https://chromium-review.googlesource.com/1215426
Reviewed-by: Makoto Shimazu <shimazu@chromium.org>
Reviewed-by: Kinuko Yasuda <kinuko@chromium.org>
Commit-Queue: Kenichi Ishibashi <bashi@chromium.org>
Cr-Commit-Position: refs/heads/master@{#589851}
[modify] https://crrev.com/137522b46759fe0441f801f6e7bea09ae5fb25a0/content/browser/frame_host/navigation_request.cc
[delete] https://crrev.com/389d563b1a49e8f3f75156871cc95438d280c77e/third_party/WebKit/LayoutTests/external/wpt/service-workers/service-worker/navigation-timing.https-expected.txt
[delete] https://crrev.com/389d563b1a49e8f3f75156871cc95438d280c77e/third_party/WebKit/LayoutTests/virtual/outofblink-cors-ns/external/wpt/service-workers/service-worker/navigation-timing.https-expected.txt
[delete] https://crrev.com/389d563b1a49e8f3f75156871cc95438d280c77e/third_party/WebKit/LayoutTests/virtual/outofblink-cors/external/wpt/service-workers/service-worker/navigation-timing.https-expected.txt
[delete] https://crrev.com/389d563b1a49e8f3f75156871cc95438d280c77e/third_party/WebKit/LayoutTests/virtual/service-worker-servicification/external/wpt/service-workers/service-worker/navigation-timing.https-expected.txt

I forgot to remove some test expectations. Will upload a fix.
Labels: -Pri-2 Pri-3
Update: I think we've fixed all known issues on S13nServiceWorker path. We can close this when we ship S13nServiceWorker or NetworkService. De-prioritizing.
What's the status of S13nServiceWorker and NetworkService?
maxlg: S13nSW is  issue 715640  and could probably be closed soon. It's shipping in Chrome 71. NetworkService is issue 598073.

Sign in to add a comment