spec what requestStart, responseStart, and responseEnd should represent when service worker is involved

[wanderview]

I'm trying to improve the PerformanceRequestTiming support in firefox when a request is intercepted by a service worker. I've implemented workerStart, but its a bit unclear what requestStart, responseStart, and responseEnd mean in this context.

Looking at the output from chrome it seems like these are being set:

fetchStart:1.9050000000000002
requestStart:2.325
responseEnd:6.73
responseStart:5.495000000000001
startTime:0
workerStart:2.32

Here requestStart is slightly after workerStart. Is this when respondWith() was called?

The responseStart is a few milliseconds later. Does this measure when the respondWith() promise resolves?

I assume responseEnd is when the synthesized body is complete.

Also, the WPT test here:

https://github.com/w3c/web-platform-tests/blob/master/service-workers/service-worker/resource-timing.https.html#L15

Wants workerStart to occur before fetchStart, but that is not what chrome is doing for this request. Also, this requirement was a bit awkward to implement in firefox. We trigger workerStart after we create our network channel, so its more natural for fetchStart to occur first. I plan to relax this requirement in the WPT test.

[wanderview]

@mattto Do you have any input here? I'd like to be compatible if we can, but these other values seem under specified.

[wanderview]

For subresource requests chrome seems to generate workerStart before fetchStart, but the reverse for navigation requests.

Is there any guaranteed ordering between these two?

[wanderview]

Actually, I decided to bring the fetchStart up to workerStart in gecko. So I don't need to change the WPT test, but it seems chrome's behavior does not always conform to the expected test behavior here. It would be nice to clarify what these events mean.

[mfalken]

Yes I've seen some strange behavior from Chrome. I think our workerStart is created when the renderer process (i.e., web content process) has begun starting up the worker thread, but service worker startup actually starts before that in the browser process. I wouldn't be surprised if there are things to improve here both spec and implementation wise.

I wrote a bit about this before at https://groups.google.com/a/chromium.org/d/msg/blink-dev/ck9M6Ev21lo/oj8kK098CAAJ

[wanderview]

Maybe we can quickly sketch "what does each timing value mean in each browser" at TPAC. Even if its not spec'd it would be nice to put it in this issue.

Should I leave the "workerStart >= fetchStart" in the test for now?

Note, I am expanding the test with:

    assert_greater_than_equal(entry.responseStart, entry.fetchStart, description);
    assert_greater_than_equal(entry.responseEnd, entry.responseStart, description);
    assert_greater_than(entry.duration, 0, description);

[mfalken]

Sounds good to discuss at TPAC (but I'd have to prepare to be able to share accurate information). Maybe better to focus on what the timing values should mean.

Makes sense to me to assert fetchStart < workerStart. cc/ @igrigorik @spanicker

[mfalken]

I mean yea workerStart >= fetchStart makes sense to me.

[wanderview]

I mean yea workerStart >= fetchStart makes sense to me.

Honestly I don't really know what "fetchStart" means for a synthesized response. I'm making our values conform to this, but I don't know if they make sense.

[wanderview]

I guess it would be useful to know what sites interpret these values to mean today. @n8schloss do you have any insight here?

[wanderview]

Just thinking about it a bit I would recommend the following:

• workerStart means when we decide to intercept and may or may not need to spin up worker. (As currently defined AFAICT.)
• requestStart means when we first the FetchEvent in the worker thread
• responseStart means when the respondWith() promise resolves
• responseEnd means when the respondWith() Response body completes

And I guess fetchStart == workerStart.

Any thoughts?

[igrigorik]

• workerStart means when we decide to intercept and may or may not need to spin up worker. (As currently defined AFAICT.)
• requestStart means when we first the FetchEvent in the worker thread
• responseStart means when the respondWith() promise resolves
• responseEnd means when the respondWith() Response body completes

nod.. I think those make sense.

And I guess fetchStart == workerStart.

The delta between workerStart and fetchStart is meant to capture the worker startup time. They are not the same, unless worker is already ready or there is no worker to start...

/cc @toddreifsteck

[wanderview]

The delta between workerStart and fetchStart is meant to capture the worker startup time. They are not the same, unless worker is already ready or there is no worker to start...

That is not what the spec says for step 1.2 here:

https://w3c.github.io/resource-timing/#dom-performanceresourcetiming-workerstart

"Immediately before the user agent runs the worker" should be before the browser starts its thread. Assuming "run the worker" refers to the current "run service worker" algorithm here:

https://w3c.github.io/ServiceWorker/#run-service-worker-algorithm

The thread isn't created until step 4 there.

[wanderview]

I just implemented workerStart based on the interpretation in #119 (comment). If this is wrong, it would be great to get clarification. @mattto, what does chrome do here?

[wanderview]

I think I misunderstood #119 (comment).

I think my problem is I don't understand what fetchStart is intended to be in a service worker interception case. Is it the time when we fire the FetchEvent?

[wanderview]

I think we really need the spec aligned with fetch spec to clarify service worker behavior with these values. In the meantime I will move fetchStart times in firefox to be when the FetchEvent is fired on the SW thread.

[mfalken]

I think Chome will have different behavior depending on whether the service worker provided a response or fell back to network. When it falls back to network we don't seem to set workerStart. It's a bug.

We seem to try to set workerStart to the time we decide a service worker is needed, and fetchStart to the time right before we start dispatching the fetch event to the running worker (fetchStart is set in the browser/parent process, not in the renderer/content process or worker thread). So I'm not sure why in some cases fetchStart happens before workerStart as the output in the original comment shows.

[wanderview]

Values in the initial comment here may have been from a redirect leading to an intercepted request. I can't remember, unfortunately.

[bashi]

I took a closer look at how Chrome implements these attributes. Here is summary:

• workerStart is recorded when we decide to intercept the request. We starts a worker when needed after that. Regarding network fallback cases, we seem to set workerStart accordingly.
• fetchStart is recorded before dispatching the FetchEvent. For subresource, this always comes after workerStart (workerStart <= fetchStart). For navigation, Chrome overrides this attribute to the time when the navigation starts. Currently this happens before preparing to start worker, so workerStart >= fetchStart. This explains what wanderview observed previously. Chrome should fix this inconsistency.
• requestStart is recorded at the same timing as fetchStart.
• responseStart is recorded after the fetch event handler is executed. At this point the respondWith() promise is resolved.
• responseEnd is recorded when the response is fully loaded.

I think that workerStart should be always less than or equal to fetchStart as the delta is meant to capture the worker startup time (according to igrigorik's comment). We are planning to fix timing for navigation.

Other things we may want to clarify are:

1. How multiple redirects interacts with workerStart?
   Multiple redirects can happen for navigation (according to mattto). Suppose there are some redirects r1 -> r2 -> r3 -> r4 -> r5 and say r2 and r4 go though a service worker. In this case what would the expected behavior be? Should workerStart be set only when the first request go though a service worker?

2. workerStart for no-fetch-event workers
   Just treat as no-active worker case (i.e. set to zero)?

[mfalken]

1. Since fetchStart is defined to be about the final request after redirects, it seems consistent if workerStart is about the worker that handled the final request after redirects.

2. Seems OK to set workerStart to zero for no-fetch-event workers.

[yoavweiss]

As the workerStart nuances seem to be covered in #118, it seems safe to bump this to L3, when we'll actually define Fetch intergration.

[igrigorik]

👍

[makotoshimazu]

Let me revive this issue to confirm my understanding of the conclusion of this discussion.

Here's my understanding:

• workerStart: when the browser finds a service worker that handles the request (and before starting a worker thread if it's not started).
• fetchStart: the time just before firing a FetchEvent on the worker thread.
• requestStart: == fetchStart
  and fetchStart - workerStart should be the time spent for starting the worker thread.

In short, the conclusion is mostly #119 (comment) but fetchStart == requestStart.

Is this correct?

[mfalken]

In Chrome the milestones are like this:

• [A] Decide to intercept the request.
• [B] Start the worker (if needed).
• [C] The worker thread has started (this may have happened in the past)
• [D] The fetch event IPC arrives on the worker thread.
• [E] Queue the fetch event (the worker may be running other events)
• [F] Enter the fetch event handler.

Based on this thread, perhaps these milestones may be worth considering:

• workerStart: [A], right when we decide to intercept the request
• fetchStart: [D], right when the IPC arrives. In spec terms, this could be the "Queue a task" step 21.3 of Handle Fetch.
• requestStart: [F], right when the fetch event handler is entered. In spec terms, this could be the "Dispatch e" step 11 of that task.

The current text spec seems rather different:

• workerStart: [B], if startup was needed, else [F]
• fetchStart: The entry part to the Fetch algorithm. This is a time before [A]. The Fetch algorithm leads to SW's Handle Fetch which is where [A] happens.
• requestStart: Does not mention service worker, but is probably intended to be [F].

Do the milestones [A], [D], [F] make sense for workerStart, fetchStart, requestStart? A complication is redirects, but maybe we can just use the final request for all of workerStart, fetchStart, requestStart.

[mfalken]

This means fetchStart would have to change totally if we want (fetchStart - workerStart) to measure something like worker startup time, but that would make the SW and the non-SW case differ greatly. We might want to keep fetchStart as-is. Instead change requestStart to be one of [D], [E], [F] in the SW case, or add a new workerReady milestone so (workerReady - workerStart) or (requestStart - workerStart) captures it.

[jakearchibald]

but that would make the SW and the non-SW case differ greatly

Yeah, I think we should avoid that, so I agree with keeping fetchStart as is, assuming browsers implement the current spec text.

It feels like the spec is trying to say workerStart is the time the browser decides to use a service worker for that request. So I agree with @mfalken that this should be [A]. I guess this is step 16 of handle fetch.

requestStart is a tricky one. Here's the spec text:

The time immediately before the user agent starts requesting the resource from the server, or from relevant application caches or from local resources

To me, it seems like it's saying the source of the data has been selected, but that source hasn't yet been queried. But the existence of connectStart means that connection work has already been done at this point. I guess that also means it's after any kind of queuing the request might get, due to priority or limits. With service worker, I guess the equivalent of connecting is starting the worker. That means, yep, I agree with @mfalken, requestStart is [F], just before dispatching the fetch event. I also agree with @mfalken that this happens just before the dispatch step, so it's part of the task queued in the service worker.

(requestStart - workerStart) gives you the delay between deciding to use a service worker, and running code to handle the event. This would be long if service worker startup is slow, or the fetch event takes a long time to dispatch due to main thread work in the service worker. Is that what folks want to know?

If folks just want to capture worker startup time, then yeah we'd need something like workerReady.

[yoavweiss]

^^ @nicjansma

[marcelduran]

In the case where a page is controlled by a SW (with a registered fetch event handler), navigation.workerStart may be:

• the time immediately before the fetch event is fired at the SW if the SW is active, or
• the time immediately before running the SW if SW is not running.

Can one infer the SW start up time by computing startup = fetchStart - workerStart then assert:

• startup > 0: SW was not active and took this long to start up.
• startup == 0: SW was already running?

In other words, is the time immediately before fetch event is fired the same as navigation.fetchStart?

[mfalken]

(belated) Notes from Service Worker WG meeting on Nov 20:

• We need better integration of Fetch and Timing specs. Rough estimate of 1 quarter of work. No one is volunteering so far.
• @mfalken to respond to workerStart and redirects navigation-timing#131 (done).
• Service Worker folks to read through the proposed milestones above and see if it makes sense.

[noamr]

I think this is now covered explicitly in the FETCH & SW specs and also in WPT.