Bug 225737

Summary: Resource Timing: Duration is 0 in many cases
Product: WebKit Reporter: Nic Jansma <nic>
Component: PlatformAssignee: Alex Christensen <achristensen>
Status: RESOLVED FIXED    
Severity: Normal CC: achristensen, cdumez, ews-watchlist, japhet, nic, webkit-bug-importer
Priority: P2 Keywords: InRadar
Version: WebKit Nightly Build   
Hardware: Mac (Intel)   
OS: macOS 10.15   
See Also: https://bugs.webkit.org/show_bug.cgi?id=229516
Attachments:
Description Flags
Patch
none
Patch
ews-feeder: commit-queue-
Patch cdumez: review+

Description Nic Jansma 2021-05-12 22:25:20 PDT
I'm seeing many cases where ResouceTiming's duration attribute is 0 when it should not be.  It should only be 0 if it truly took 0ms to load (e.g. fast cache?).

For example, see some of the test cases here: https://nicj.net/dev/resourcetiming/error-resources.html

There are 2 cross-origin test cases where the duration is showing 0.

* 4xx Result Code (cross-origin)

{
  "name": "[cross origin 404]",
  "entryType": "resource",
  "startTime": 124,
  "duration": 0,
  "initiatorType": "img",
  "nextHopProtocol": "h2",
  "workerStart": 0,
  "redirectStart": 0,
  "redirectEnd": 0,
  "fetchStart": 124,
  "domainLookupStart": 0,
  "domainLookupEnd": 0,
  "connectStart": 0,
  "connectEnd": 0,
  "secureConnectionStart": 0,
  "requestStart": 0,
  "responseStart": 0,
  "responseEnd": 234
}

* 5xx Result Code (cross-origin)

{
  "name": "[cross origin 500]",
  "entryType": "resource",
  "startTime": 124,
  "duration": 0,
  "initiatorType": "img",
  "nextHopProtocol": "h2",
  "workerStart": 0,
  "redirectStart": 0,
  "redirectEnd": 0,
  "fetchStart": 124,
  "domainLookupStart": 0,
  "domainLookupEnd": 0,
  "connectStart": 0,
  "connectEnd": 0,
  "secureConnectionStart": 0,
  "requestStart": 0,
  "responseStart": 0,
  "responseEnd": 234
}

Both of these cases have a non-zero fetchStart and responseEnd, and the difference between the two is non-zero.  For example, the later case should have a duration of 234-124=110.

In the above two cases, these were for non-200 responses.  This may be related to https://bugs.webkit.org/show_bug.cgi?id=202040?

However, I'm not convinced this is only for non-200 responses.  For example, I went to CNN.com and 105 of 150 resources had a duration==0.
Comment 1 Radar WebKit Bug Importer 2021-05-19 22:26:20 PDT
<rdar://problem/78242390>
Comment 2 Alex Christensen 2021-06-21 23:12:18 PDT
Created attachment 431947 [details]
Patch
Comment 3 Alex Christensen 2021-06-22 13:35:08 PDT
Created attachment 431989 [details]
Patch
Comment 4 Alex Christensen 2021-06-22 15:23:24 PDT
Created attachment 432000 [details]
Patch
Comment 5 Alex Christensen 2021-06-22 23:42:12 PDT
Comment on attachment 432000 [details]
Patch

Now is not the right time to make a change like this.  The status quo will have to suffice for a little while longer.
Comment 6 Alex Christensen 2021-08-03 20:57:39 PDT
Comment on attachment 432000 [details]
Patch

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

> Source/WebCore/loader/ResourceTimingInformation.cpp:43
> +    return resource.resourceRequest().url().protocolIsInHTTPFamily()

Note to my hopefully-not-too-far-in-the-future self:

Making this change here doesn't just fix this test, but it allows this change to fix even more tests, like http://wpt.live/resource-timing/buffer-full-add-then-clear.html

diff --git a/Source/WebCore/loader/SubresourceLoader.cpp b/Source/WebCore/loader/SubresourceLoader.cpp
index a261eaef4f24..ac1ab9783d9a 100644
--- a/Source/WebCore/loader/SubresourceLoader.cpp
+++ b/Source/WebCore/loader/SubresourceLoader.cpp
@@ -494,7 +494,11 @@ void SubresourceLoader::didReceiveResponse(const ResourceResponse& response, Com
             didFinishLoadingOnePart(emptyMetrics);
         }
 
-        checkForHTTPStatusCodeError();
+        if (checkForHTTPStatusCodeError()) {
+            auto* metrics = this->response().deprecatedNetworkLoadMetricsOrNull();
+            reportResourceTiming(metrics ? *metrics : NetworkLoadMetrics { });
+            cancel();
+       }
 
         if (m_inAsyncResponsePolicyCheck)
             m_policyForResponseCompletionHandler = completionHandlerCaller.release();
@@ -563,7 +567,6 @@ bool SubresourceLoader::checkForHTTPStatusCodeError()
 
     m_state = Finishing;
     m_resource->error(CachedResource::LoadError);
-    cancel();
     return true;
 }
Comment 7 Chris Dumez 2021-08-16 14:40:05 PDT
Comment on attachment 432000 [details]
Patch

r=me
Comment 8 Alex Christensen 2021-08-16 14:43:16 PDT
r281110
Comment 9 Alex Christensen 2021-08-16 16:58:18 PDT
http://trac.webkit.org/r281123
Comment 10 Alex Christensen 2021-08-16 17:12:06 PDT
Note: r281123 probably wasn't necessary because bug 229167 probably introduced that crash in an early version of the patch that I'm fixing, but I think it doesn't hurt to be cautious to not introduce a null crash in the loading code.