Bug 168086 – [Resource Timing] Support Resource Timing in Workers

• Status: RESOLVED
• Resolution: FIXED
• Component: WebCore Misc.

[Joseph Pecoraro]

Support Resource Timing in Workers

- PerformanceResourceTiming class should be available.
- Performance.setResourceTimingBufferSize, etc should be available.
- PerformanceObserver should be available.
- Timeline should include "resource" entryTypes for resources requested through the Worker (importScript, XHR, Fetch, etc)

[Joseph Pecoraro]

<rdar://problem/30430117>

[Joseph Pecoraro]

Tests not-yet-experimental runtime-enabled-features are a bit of a kerfuffle.

For these cases we should use a <!-- Test Option --> to enable the feature before the page loads. We should not use Internals methods to enable the feature after the page has loaded. So I think I'll tackle this separately while I continue to work on this patch.

However my hope is that soon we will be able to make this an experimental feature and we can drop this complexity in Tests.

[Joseph Pecoraro]

Created attachment 301580 [details]
[PATCH] Proposed Fix

[Joseph Pecoraro]

Created attachment 301581 [details]
[PATCH] For Bots

(Since its taking longer then expected for other blocking patches to get reviewed)

[WebKit Commit Bot]

Attachment 301580 [details] did not pass style-queue:


ERROR: Source/WebCore/loader/DocumentThreadableLoader.cpp:52:  "ResourceTiming.h" already included at Source/WebCore/loader/DocumentThreadableLoader.cpp:51  [build/include] [4]
Total errors found: 1 in 92 files


If any of these errors are false positives, please file a bug against check-webkit-style.

[WebKit Commit Bot]

Attachment 301581 [details] did not pass style-queue:


ERROR: Source/WebCore/loader/DocumentThreadableLoader.cpp:52:  "ResourceTiming.h" already included at Source/WebCore/loader/DocumentThreadableLoader.cpp:51  [build/include] [4]
Total errors found: 1 in 103 files


If any of these errors are false positives, please file a bug against check-webkit-style.

[Joseph Pecoraro]

Created attachment 301582 [details]
[PATCH] For Bots

[Build Bot]

Comment on attachment 301582 [details]
[PATCH] For Bots

Attachment 301582 [details] did not pass mac-ews (mac):
Output: http://webkit-queues.webkit.org/results/3120010

New failing tests:
imported/w3c/web-platform-tests/resource-timing/rt-resource-errors.html
js/dom/global-constructors-attributes-dedicated-worker.html
imported/w3c/web-platform-tests/resource-timing/rt-cors.html

[Build Bot]

Created attachment 301583 [details]
Archive of layout-test-results from ews102 for mac-elcapitan

The attached test failures were seen while running run-webkit-tests on the mac-ews.
Bot: ews102  Port: mac-elcapitan  Platform: Mac OS X 10.11.6

[Build Bot]

Comment on attachment 301582 [details]
[PATCH] For Bots

Attachment 301582 [details] did not pass mac-wk2-ews (mac-wk2):
Output: http://webkit-queues.webkit.org/results/3120017

New failing tests:
imported/w3c/web-platform-tests/resource-timing/rt-resource-errors.html
js/dom/global-constructors-attributes-dedicated-worker.html
imported/w3c/web-platform-tests/resource-timing/rt-cors.html

[Build Bot]

Created attachment 301584 [details]
Archive of layout-test-results from ews105 for mac-elcapitan-wk2

The attached test failures were seen while running run-webkit-tests on the mac-wk2-ews.
Bot: ews105  Port: mac-elcapitan-wk2  Platform: Mac OS X 10.11.6

[Build Bot]

Comment on attachment 301582 [details]
[PATCH] For Bots

Attachment 301582 [details] did not pass ios-sim-ews (ios-simulator-wk2):
Output: http://webkit-queues.webkit.org/results/3120026

New failing tests:
imported/w3c/web-platform-tests/resource-timing/rt-resource-errors.html
imported/w3c/web-platform-tests/resource-timing/rt-shared-resource-in-frames.html
js/dom/global-constructors-attributes-dedicated-worker.html

[Build Bot]

Created attachment 301585 [details]
Archive of layout-test-results from ews121 for ios-simulator-wk2

The attached test failures were seen while running run-webkit-tests on the ios-sim-ews.
Bot: ews121  Port: ios-simulator-wk2  Platform: Mac OS X 10.11.6

[Build Bot]

Comment on attachment 301582 [details]
[PATCH] For Bots

Attachment 301582 [details] did not pass mac-debug-ews (mac):
Output: http://webkit-queues.webkit.org/results/3120023

New failing tests:
imported/w3c/web-platform-tests/resource-timing/rt-resource-errors.html
js/dom/global-constructors-attributes-dedicated-worker.html
imported/w3c/web-platform-tests/resource-timing/rt-cors.html

[Build Bot]

Created attachment 301586 [details]
Archive of layout-test-results from ews112 for mac-elcapitan

The attached test failures were seen while running run-webkit-tests on the mac-debug-ews.
Bot: ews112  Port: mac-elcapitan  Platform: Mac OS X 10.11.6

[Joseph Pecoraro]

Good news is that everything worked! Bad news is that random URLs used to ensure non-cached resources cause an issue in at least one test. This is still reviewable while I clean up the tests a bit.

[Joseph Pecoraro]

Created attachment 301596 [details]
[PATCH] Proposed Fix

[Build Bot]

Comment on attachment 301596 [details]
[PATCH] Proposed Fix

Attachment 301596 [details] did not pass mac-ews (mac):
Output: http://webkit-queues.webkit.org/results/3120865

New failing tests:
imported/w3c/web-platform-tests/resource-timing/rt-cors.html

[Build Bot]

Created attachment 301601 [details]
Archive of layout-test-results from ews102 for mac-elcapitan

The attached test failures were seen while running run-webkit-tests on the mac-ews.
Bot: ews102  Port: mac-elcapitan  Platform: Mac OS X 10.11.6

[Build Bot]

Comment on attachment 301596 [details]
[PATCH] Proposed Fix

Attachment 301596 [details] did not pass mac-wk2-ews (mac-wk2):
Output: http://webkit-queues.webkit.org/results/3120868

New failing tests:
imported/w3c/web-platform-tests/resource-timing/rt-cors.html

[Build Bot]

Created attachment 301602 [details]
Archive of layout-test-results from ews105 for mac-elcapitan-wk2

The attached test failures were seen while running run-webkit-tests on the mac-wk2-ews.
Bot: ews105  Port: mac-elcapitan-wk2  Platform: Mac OS X 10.11.6

[Build Bot]

Comment on attachment 301596 [details]
[PATCH] Proposed Fix

Attachment 301596 [details] did not pass mac-debug-ews (mac):
Output: http://webkit-queues.webkit.org/results/3120878

New failing tests:
imported/w3c/web-platform-tests/resource-timing/rt-cors.html

[Build Bot]

Created attachment 301603 [details]
Archive of layout-test-results from ews116 for mac-elcapitan

The attached test failures were seen while running run-webkit-tests on the mac-debug-ews.
Bot: ews116  Port: mac-elcapitan  Platform: Mac OS X 10.11.6

[Alex Christensen]

Comment on attachment 301596 [details]
[PATCH] Proposed Fix

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

imported/w3c/web-platform-tests/resource-timing/rt-cors.html isn't doing very well.

> Source/WebCore/ChangeLog:79
> +        (WebCore::ResourceTiming::ResourceTiming):
> +        Class that encapsulates all of the data needed for a PerformanceResourceTiming entry.

Yet another class that contains timing data?  Can't we use this instead of one of the existing classes that contains timing data?

> Source/WebCore/loader/SubresourceLoader.cpp:677
> +    SecurityOrigin& origin = m_origin ? *m_origin : document->securityOrigin();

I'm not sure we want to continue if m_origin is null.

> Source/WebCore/loader/WorkerThreadableLoader.cpp:233
> +    Ref<ThreadableLoaderClientWrapper> protectedWorkerClientWrapper = *m_workerClientWrapper;
> +    m_loaderProxy.postTaskForModeToWorkerGlobalScope([protectedWorkerClientWrapper = WTFMove(protectedWorkerClientWrapper), resourceTiming = resourceTiming.isolatedCopy()] (ScriptExecutionContext& context) mutable {

protectedWorkerClientWrapper = makeRef(m_workerClientWrapper) in the lambda capture.  No need to make a local variable.

> Source/WebCore/loader/cache/CachedResourceLoader.cpp:779
> +            } else if (document() && RuntimeEnabledFeatures::sharedFeatures().resourceTimingEnabled()) {

RuntimeEnabledFeatures::sharedFeatures().resourceTimingEnabled looks like it's used inconsistently in this patch.  For example, is it intentional that this is only checked for Documents and not workers?

> Source/WebCore/page/Performance.cpp:175
> +    RefPtr<PerformanceResourceTiming> entry = PerformanceResourceTiming::create(m_timeOrigin, WTFMove(resourceTiming));

auto, which would make this a Ref.

[Joseph Pecoraro]

Its possible that El Capitan's data is different from Sierra (what I'm testing).

All of these failures are El-Capitan complaining that requestStart is not after connectEnd. I'll need to test on El Capitan. That said, this patch is still reviewable as is.

[Joseph Pecoraro]

Comment on attachment 301596 [details]
[PATCH] Proposed Fix

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

> Source/WebCore/page/PerformanceResourceTiming.cpp:175
> -    return networkLoadTimeToDOMHighResTimeStamp(m_timing.requestStart);
> +    // requestStart is 0 when a network request is not made.
> +    if (m_networkLoadTiming.requestStart <= 0)
> +        return connectEnd();
> +
> +    return networkLoadTimeToDOMHighResTimeStamp(m_networkLoadTiming.requestStart);

Oh interesting. The old code was using m_timing.requestStart and not networkLoadTiming's requestStart.

[Joseph Pecoraro]

Comment on attachment 301596 [details]
[PATCH] Proposed Fix

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

>> Source/WebCore/ChangeLog:79
>> +        Class that encapsulates all of the data needed for a PerformanceResourceTiming entry.
> 
> Yet another class that contains timing data?  Can't we use this instead of one of the existing classes that contains timing data?

Yeah, this is rather unfortunate and they are beginning to clash.

Here is a list of all the Timing classes and their purposes:

    DocumentTiming:
      - WebContentProcess timestamps (event times)
      - Used for Navigation Timing fields
      - Owned by Document

    LoadTiming
      - WebContentProcess collected timestamps (start time, redirects)
      - Used for both Resource Timing and Navigation Timing (these fields ^)
      - Owned by Loaders (CachedResourceLoader DocumentLoader, ResourceLoader) and eventually passed to a Performance*Timing

    NetworkLoadTiming
      - NetworkProcess collected timestamps (dnsStart ... connectStart ... responseStart)
      - Used for both Resource Timing and Navigation Timing (these fields ^)
      - Owned by ResourceResponse (gross) and now a ResourceTiming and eventually passed to a Performance*Timing
      - As part of ResourceResponse this is how it gets serialized to the WebContentProcess and used by Loaders (gross)

    --

    ResourceTiming
      - Used only for Resource Timing.
      - Encapsulates all necessary data for a Resource Timing entry
      - Serializable so it can be assembled on the loading thread and then passed to Workers
      - Carries a LoadTiming and NetworkLoadTiming since both are needed for all Resource Timing fields
      - Owned by nobody, this is just a struct passed around to get the data to a PerformanceResourceTiming object in the right context

    --

    PerformanceTiming
      - The Navigation Timing object (PerformanceTiming instance)
      - Uses a DocumentTiming, LoadTiming, and NetworkLoadTiming

    PerformanceResourceTiming
      - A Resource Timing entry (PerformanceResourceTiming instance)
      - Uses a LoadTiming and NetworkLoadTiming

-----

I do think LoadTiming and NetworkLoadTiming being separate has an advantage. Because the NetworkLoadTiming data comes from the NetworkProcess keeping it small and specific is a nice cognitive separation. I plan on adding a new message from the NetworkLoad -> ResourceLoader message that only contains the NetworkLoadTiming data (and some more metrics).

I do think ResourceTiming should be separate from the others. Resource Timing entries are created for all kinds of loads (cache, load, synchronous load). I think packaging all the necessary data together, which may be assembled differently for the different loads is useful. Likewise passing this package along instead of the individual pieces.

>> Source/WebCore/loader/SubresourceLoader.cpp:677
>> +    SecurityOrigin& origin = m_origin ? *m_origin : document->securityOrigin();
> 
> I'm not sure we want to continue if m_origin is null.

This was a very confusing area for me. My understanding is that m_origin is only set when we are loading via a ThreadableLoader (XHR, Fetch, EventSource). These kinds of loads originate from either a Document or Worker and they pass their SecurityOrigin over to the loader thread so it can be used to handle Cross Origin behavior for these loads.

I arrived at this conclusion because m_origin is initialized from CachedResource::origin() which comes from CachedResourceRequest::origin() which is only set by DocumentThreadableLoader.

Other, non-ThreadableLoader loads that use SubResourceLoader do not set this origin. The original Resource Timing used document->securityOrigin here and I kept that unchanged.

--

Probably the best solution would be to ensure m_origin is always set for any load in a SubResourceLoader, so there is never confusion. That would probably be best done as a targeted cleanup patch. What do you think?

>> Source/WebCore/loader/WorkerThreadableLoader.cpp:233
>> +    m_loaderProxy.postTaskForModeToWorkerGlobalScope([protectedWorkerClientWrapper = WTFMove(protectedWorkerClientWrapper), resourceTiming = resourceTiming.isolatedCopy()] (ScriptExecutionContext& context) mutable {
> 
> protectedWorkerClientWrapper = makeRef(m_workerClientWrapper) in the lambda capture.  No need to make a local variable.

Neat! I was not aware of makeRef. I'll convert this and the other bridge methods.

>> Source/WebCore/loader/cache/CachedResourceLoader.cpp:779
>> +            } else if (document() && RuntimeEnabledFeatures::sharedFeatures().resourceTimingEnabled()) {
> 
> RuntimeEnabledFeatures::sharedFeatures().resourceTimingEnabled looks like it's used inconsistently in this patch.  For example, is it intentional that this is only checked for Documents and not workers?

Good catch!

>> Source/WebCore/page/Performance.cpp:175
>> +    RefPtr<PerformanceResourceTiming> entry = PerformanceResourceTiming::create(m_timeOrigin, WTFMove(resourceTiming));
> 
> auto, which would make this a Ref.

A Ref does not easily get converted into a RefPtr when appending to m_resourceTimingBuffer. That is why existing code used RefPtr.

[Joseph Pecoraro]

I created an El Capitan partition and it does look like it was possible for a requestStart to happen before connectionEnd in El Capitan:

    $ sw_vers
    ProductName:	Mac OS X
    ProductVersion:	10.11.6
    BuildVersion:	15G31

    --- stderr from test ---

    2017-02-15 21:42:30.349 com.apple.WebKit.Networking.Development[41618:151126] >>> TIMING DATA: {
        "_kCFNTimingDataConnectEnd" = "508916550.347444";
        "_kCFNTimingDataConnectStart" = "508916550.347444";
        "_kCFNTimingDataConnectionReused" = 1;
        "_kCFNTimingDataDomainLookupEnd" = "508916550.346444";
        "_kCFNTimingDataDomainLookupStart" = "508916550.346444";
        "_kCFNTimingDataFetchStart" = "508916550.328835";
        "_kCFNTimingDataRedirectCount" = 3;
        "_kCFNTimingDataRedirectCountW3C" = 0;
        "_kCFNTimingDataRedirectEnd" = 0;
        "_kCFNTimingDataRedirectStart" = 0;
        "_kCFNTimingDataRequestStart" = "508916550.330722";
        "_kCFNTimingDataResponseEnd" = "508916550.349124";
        "_kCFNTimingDataResponseStart" = "508916550.331586";
        "_kCFNTimingDataSecureConnectionStart" = 0;
        "_kCFNTimingDataTimingDataInit" = "508916550.346192";
    }

Note in this example the ordered by timestamps we get:

    FetchStart:         508916550.328835
    RequestStart:       508916550.330722
    ResponseStart:      508916550.331586
    TimingDataInit:     508916550.346192
    DomainLookupStart:  508916550.346444
    DomainLookupEnd:    508916550.346444
    ConnectStart:       508916550.347444
    ConnectEnd:         508916550.347444
    ResponseEnd:        508916550.349124

This is completely whacky. For starters, TimingDataInit should be the earliest value that all other values are measured relative to. But here it isn't even the earliest value.

A different entry looks like:

    TimingDataInit:     508916550.058271
    DomainLookupEnd:    508916550.058545
    DomainLookupStart:  508916550.058545
    FetchStart:         508916550.057944
    ConnectEnd:         508916550.059545
    ConnectStart:       508916550.059545
    RequestStart:       508916550.059958
    ResponseStart:      508916550.060892
    ResponseEnd:        508916550.061163

Which is more reasonable. Still I'm not sure how I can make sense of the data. I'm going to compare more closely to data in Sierra and try to make a decision about what to do. This feature may just need to be disabled on El Capitan if we can't ensure its accuracy (I don't want websites gathering metrics that are inaccurate).

[Joseph Pecoraro]

Yes, Sierra has better numbers:

Raw dictionary (from copyTimingData):

    2017-02-15 22:40:43.872 com.apple.WebKit.Networking.Development[2486:91984] >>> TIMING DATA: {
        "_kCFNTimingDataConnectEnd" = "508920043.870083";
        "_kCFNTimingDataConnectStart" = "508920043.869083";
        "_kCFNTimingDataConnectionReused" = 0;
        "_kCFNTimingDataDomainLookupEnd" = "508920043.869083";
        "_kCFNTimingDataDomainLookupStart" = "508920043.869083";
        "_kCFNTimingDataFetchStart" = "508920043.86863";
        "_kCFNTimingDataLocalAddressAndPort" = "127.0.0.1:49622";
        "_kCFNTimingDataRedirectCount" = 0;
        "_kCFNTimingDataRedirectCountW3C" = 0;
        "_kCFNTimingDataRedirectEnd" = 0;
        "_kCFNTimingDataRedirectStart" = 0;
        "_kCFNTimingDataRemoteAddressAndPort" = "127.0.0.1:8801";
        "_kCFNTimingDataRequestEnd" = "508920043.870279";
        "_kCFNTimingDataRequestStart" = "508920043.870251";
        "_kCFNTimingDataResponseEnd" = "508920043.871618";
        "_kCFNTimingDataResponseStart" = "508920043.871418";
        "_kCFNTimingDataSecureConnectionStart" = 0;
        "_kCFNTimingDataTimingDataInit" = "508920043.868856";
    }

Ordered by Time:    

    FetchStart:         508920043.86863
    TimingDataInit:     508920043.868856 ?
    ConnectStart:       508920043.869083
    ConnectEnd:         508920043.870083
    DomainLookupStart:  508920043.869083
    DomainLookupEnd:    508920043.869083
    RequestStart:       508920043.870251
    RequestEnd:         508920043.870279
    ResponseStart:      508920043.871418
    ResponseEnd:        508920043.871618

I'm not surprised, because access to timing data became Public API in Sierra (NSURLSessionTaskTransactionMetrics) and this aligns with the graphic there:
https://docs-assets.developer.apple.com/published/df414fd961/23287374-c86a-4b5c-80d4-c1d596f20f85.png

---

I wonder if the El Capitan numbers were skewed because the "Connection Reused", and so maybe it is reporting the connection numbers from a previous request. If that is the case we could clear out the numbers.

[Joseph Pecoraro]

Hmm, no that still doesn't make sense just looking at the raw numbers. I'm going to start by skipping this test on El Capitan. If I can't make sense of the numbers and can't guarantee accuracy we may have to disable on that OS.

[Joseph Pecoraro]

(In reply to comment #30)
> Hmm, no that still doesn't make sense just looking at the raw numbers. I'm
> going to start by skipping this test on El Capitan. If I can't make sense of
> the numbers and can't guarantee accuracy we may have to disable on that OS.

Filed Bug 168415.

[Joseph Pecoraro]

Created attachment 301715 [details]
[PATCH] Proposed Fix

[WebKit Commit Bot]

Attachment 301715 [details] did not pass style-queue:


ERROR: LayoutTests/platform/mac/TestExpectations:1532:  Path does not exist.  [test/expectations] [5]
Total errors found: 1 in 95 files


If any of these errors are false positives, please file a bug against check-webkit-style.

[Build Bot]

Comment on attachment 301715 [details]
[PATCH] Proposed Fix

Attachment 301715 [details] did not pass ios-sim-ews (ios-simulator-wk2):
Output: http://webkit-queues.webkit.org/results/3126892

New failing tests:
imported/w3c/web-platform-tests/resource-timing/rt-shared-resource-in-frames.html

[Build Bot]

Created attachment 301726 [details]
Archive of layout-test-results from ews121 for ios-simulator-wk2

The attached test failures were seen while running run-webkit-tests on the ios-sim-ews.
Bot: ews121  Port: ios-simulator-wk2  Platform: Mac OS X 10.11.6

[Joseph Pecoraro]

Hmm, rt-shared-resource-in-frames.html is sometimes flakey in all browsers. That said, I do believe this test is correct. I'm going to preemptively mark it as flakey and file a bug to follow up on this.

[Joseph Pecoraro]

<https://trac.webkit.org/changeset/212449>