Bug 237317 - PerformanceNavigationTiming Response Start unavailable when using Service Worker Cache
Summary: PerformanceNavigationTiming Response Start unavailable when using Service Wor...
Status: RESOLVED FIXED
Alias: None
Product: WebKit
Classification: Unclassified
Component: Service Workers (show other bugs)
Version: Safari 15
Hardware: Mac (Apple Silicon) macOS 12
: P2 Normal
Assignee: Alex Christensen
URL: https://sw-lifecycle-test.app.baqend....
Keywords: InRadar
Depends on:
Blocks:
 
Reported: 2022-03-01 04:00 PST by Daniel Schulz
Modified: 2022-03-17 14:46 PDT (History)
6 users (show)

See Also:


Attachments
A Document, Script and Service Worker that exhibit the described bug (1.43 KB, application/zip)
2022-03-01 04:00 PST, Daniel Schulz
no flags Details
Patch (6.04 KB, patch)
2022-03-08 18:51 PST, Alex Christensen
no flags Details | Formatted Diff | Diff
Patch (10.07 KB, patch)
2022-03-16 20:18 PDT, Alex Christensen
no flags Details | Formatted Diff | Diff
Patch (14.70 KB, patch)
2022-03-17 10:51 PDT, Alex Christensen
no flags Details | Formatted Diff | Diff
Patch (14.85 KB, patch)
2022-03-17 12:23 PDT, Alex Christensen
no flags Details | Formatted Diff | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Daniel Schulz 2022-03-01 04:00:05 PST
Created attachment 453487 [details]
A Document, Script and Service Worker that exhibit the described bug

When The document is being served from a Service Worker Cache, the PerofrmanceNavigationTiming API returns always 0 for its responseStart value.
When the document comes from the Network instead of the Service Worker Cache, it responds the correct value.

I expect the responseStart value to always be reported correctly, even if it's being served from Cache.

Tested in Safari 15.2 and 15.4TP on MacOS 12.1 on a MacBook Pro M1 2020.

Steps to reproduce:
- Serve the files from the attached zip
- Open the index.html in Safari
- Reload the page
Comment 1 Daniel Schulz 2022-03-01 23:43:50 PST
Amendment: Apparently the responseStart Value is missing for all request that go through the service worker, not only cached ones.

I also uploaded a demo on our server for your convenience: https://sw-lifecycle-test.app.baqend.com/safari-timing-sw/
Comment 2 Radar WebKit Bug Importer 2022-03-08 04:01:16 PST
<rdar://problem/89960336>
Comment 3 Alex Christensen 2022-03-08 18:51:09 PST
Created attachment 454185 [details]
Patch
Comment 4 youenn fablet 2022-03-08 23:26:12 PST
(In reply to Daniel Schulz from comment #1)
> Amendment: Apparently the responseStart Value is missing for all request
> that go through the service worker, not only cached ones.

The non-cached service worker loads might be fixed in https://bugs.webkit.org/show_bug.cgi?id=235179.
Comment 5 youenn fablet 2022-03-08 23:30:16 PST
Comment on attachment 454185 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=454185&action=review

> Source/WebCore/ChangeLog:6
> +        Reviewed by NOBODY (OOPS!).

Can we add a test?

> Source/WebCore/Modules/cache/DOMCache.cpp:89
> +    resourceResponse.setDeprecatedNetworkLoadMetrics(WTFMove(metrics));

NetworkResourceLoader does not fill the network load metrics in the same way in case of a matching cache entry.
Should we be consistent?
Also, is this consistent with what other browsers are doing?
Comment 6 Daniel Schulz 2022-03-09 01:13:17 PST
Firefox (97, 98) and Chrome 99 (MacOS) always return a responseStart value.
Comment 7 youenn fablet 2022-03-09 01:17:31 PST
(In reply to Daniel Schulz from comment #6)
> Firefox (97, 98) and Chrome 99 (MacOS) always return a responseStart value.

Sure, the question is what other values they are providing.
For instance, is the timing info from load served from service worker cache similar to   loads served from network cache.
Comment 8 Daniel Schulz 2022-03-09 04:07:48 PST
Chrome and Firefox treat SW response time as the responseStart value. 
In my tests it's consistently marginally faster than the TTFB from network cache responses. Those two are treated the same way, both in the Network diagram and in the responseStart value from the performanceNavigation API.
Comment 9 Chris Dumez 2022-03-09 07:21:02 PST
Comment on attachment 454185 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=454185&action=review

> Source/WebCore/platform/network/NetworkLoadMetrics.h:97
> +    bool complete : 1 { false };

FYI, I tried this recently since it is supposed to work in C++20. However, our Windows bots don't like it still..
Comment 10 Alex Christensen 2022-03-09 08:26:13 PST
Comment on attachment 454185 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=454185&action=review

I was hoping there was a web platform test for this already and it would start passing.  Looks like we'll need to write one.

>> Source/WebCore/Modules/cache/DOMCache.cpp:89
>> +    resourceResponse.setDeprecatedNetworkLoadMetrics(WTFMove(metrics));
> 
> NetworkResourceLoader does not fill the network load metrics in the same way in case of a matching cache entry.
> Should we be consistent?
> Also, is this consistent with what other browsers are doing?

This is consistent with what other browsers are doing, but we still need to look into what happens with the disk cache and with the other metrics
Comment 11 Braden O'Guinn 2022-03-16 14:28:39 PDT
Our company is seeing this same issue. Webkit running on iOS/OSX 15.X consistently returns 0 values for PerformanceNavigationTiming entries, whereas these numbers are populated via the deprecated window.performance.timing (minus redirectEnd, redirectStart, and secureConnectionStart) with correct timestamps. See below:

PerformanceNavigationTiming:

connectEnd: 0
connectStart: 0
domComplete: 4308
domContentLoadedEventEnd: 2202
domContentLoadedEventStart: 2030.0000000000002
domInteractive: 2030.0000000000002
domainLookupEnd: 0
domainLookupStart: 0
duration: 4311
entryType: "navigation"
fetchStart: 0
initiatorType: "navigation"
loadEventEnd: 4311
loadEventStart: 4309
name: "https://www.etsy.com/market/citrine"
nextHopProtocol: ""
redirectCount: 0
redirectEnd: 0
redirectStart: 0
requestStart: 0
responseEnd: 0
responseStart: 0
secureConnectionStart: 0
startTime: 0
type: "navigate"
unloadEventEnd: 1020
unloadEventStart: 1019.0000000000001
workerStart: 0

window.performance.timing:

connectEnd: 1647455955426
connectStart: 1647455955426
domComplete: 1647455959163
domContentLoadedEventEnd: 1647455956101
domContentLoadedEventStart: 1647455956081
domInteractive: 1647455956081
domLoading: 1647455955735
domainLookupEnd: 1647455955426
domainLookupStart: 1647455955426
fetchStart: 1647455955426
loadEventEnd: 1647455959168
loadEventStart: 1647455959165
navigationStart: 1647455955411
redirectEnd: 0
redirectStart: 0
requestStart: 1647455955426
responseEnd: 1647455955715
responseStart: 1647455955715
secureConnectionStart: 0
unloadEventEnd: 1647455955734
unloadEventStart: 1647455955734

This is a navigation request with an empty service worker serving the page request from-network. We would expect to see this populated fully, as it is in Firefox, Chrome, Opera, etc.
Comment 12 Alex Christensen 2022-03-16 17:45:58 PDT
It looks like we're missing requestStart, responseStart, and responseEnd.  Chrome and Firefox have them.  And it needs a test...
Comment 13 Alex Christensen 2022-03-16 20:18:47 PDT
Created attachment 454927 [details]
Patch
Comment 14 Alex Christensen 2022-03-17 10:51:24 PDT
Created attachment 454994 [details]
Patch
Comment 15 youenn fablet 2022-03-17 11:15:54 PDT
Comment on attachment 454994 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=454994&action=review

> LayoutTests/http/wpt/service-workers/resources/navigation-timing-part-2.html:9
> +    let navTiming = performance.getEntries()[0];

Maybe add a test to check that navigator.serviceWorker.controller is not null.

> LayoutTests/http/wpt/service-workers/resources/navigation-timing-part-2.html:10
> +    let navTimingResult = (navTiming.requestStart > 0

Could be const.
Comment 16 Alex Christensen 2022-03-17 12:23:51 PDT
Created attachment 455001 [details]
Patch
Comment 17 EWS 2022-03-17 14:20:40 PDT
Committed r291441 (248565@main): <https://commits.webkit.org/248565@main>

All reviewed patches have been landed. Closing bug and clearing flags on attachment 455001 [details].
Comment 18 Alex Christensen 2022-03-17 14:46:35 PDT
Thanks for the report!