feat(fetch): expose timings #32647

Skn0tt · 2024-09-17T08:08:57Z

Closes #19621. Adds the same timings() we have for browser responses to APIResponse. Please apply some extra care in reviewing the timing calculations.

In the protocol change, I was unsure wether to extend the existing ResourceTiming type or to add another property. I went with the added property to be in-line with how the events work for browser requests - let me know if we should do it differently instead.

make responseEnd optional make it more similar to existing types missed one!

Skn0tt · 2024-09-17T14:25:03Z

docs/src/api/class-request.md

@@ -314,7 +314,7 @@ Returns resource size information for given request.
  - `startTime` <[float]> Request start time in milliseconds elapsed since January 1, 1970 00:00:00 UTC
  - `domainLookupStart` <[float]> Time immediately before the browser starts the domain name lookup for the
    resource. The value is given in milliseconds relative to `startTime`, -1 if not available.
-  - `domainLookupEnd` <[float]> Time immediately after the browser starts the domain name lookup for the resource.
+  - `domainLookupEnd` <[float]> Time immediately after the browser ends the domain name lookup for the resource.


this is a drive-by fix - pretty sure it shouldn't say "start the domain name lookup"

Skn0tt · 2024-09-17T17:49:05Z

packages/playwright-core/src/server/fetch.ts

@@ -483,6 +504,9 @@ export abstract class APIRequestContext extends SdkObject {
        socket.on('lookup', () => { dnsLookupAt = monotonicTime(); });
        socket.on('connect', () => { tcpConnectionAt = monotonicTime(); });
        socket.on('secureConnect', () => { tlsHandshakeAt = monotonicTime(); });
+
+        // socks / http proxy
+        socket.on('proxyConnect', () => { tcpConnectionAt = monotonicTime(); });


Adding timings to the protocol uncovered that tcpConnectionAt was undefined for requests over SOCKS and HTTPS Proxy. Turns out that the library we use for that doesn't emit the connect event, but the proxyConnect event instead.

dgozman · 2024-09-18T09:53:28Z

packages/playwright-core/src/server/fetch.ts

+          const endAt = monotonicTime();
+          // spec: https://developer.mozilla.org/en-US/docs/Web/API/PerformanceResourceTiming
+          const timing: channels.ResourceTiming = {
+            startTime: startAt,


The docs say startTime is a wall time, not monotonic time.

done in b717257

dgozman · 2024-09-18T09:54:02Z

packages/playwright-core/src/server/fetch.ts

+          // spec: https://developer.mozilla.org/en-US/docs/Web/API/PerformanceResourceTiming
+          const timing: channels.ResourceTiming = {
+            startTime: startAt,
+            domainLookupStart: dnsLookupAt ? 0 : -1,


Why zero and not relativeTime()?

My understand is that the browser has some other steps like cache resolution before the DNS lookup, so there might be time between startTime and the DNS lookup start. On Node.js, I don't think there's anything between that - so it's zero, because we know the DNS lookup happens immediately after the request start.

dgozman · 2024-09-18T09:54:13Z

packages/playwright-core/src/server/fetch.ts

+          const timing: channels.ResourceTiming = {
+            startTime: startAt,
+            domainLookupStart: dnsLookupAt ? 0 : -1,
+            domainLookupEnd: dnsLookupAt ? dnsLookupAt! - startAt : -1,


relativeTime()?

done in b1d523b

dgozman · 2024-09-18T09:55:32Z

packages/playwright-core/src/server/fetch.ts

-            body
+            body,
+            timing,
+            responseEndTiming,


Why do we have two sets of timings now?

For browser requests, most of the timings are transmitted in the Response type, and then responseEndTiming arrives later in the requestFinished and requestFailed events. I opted to make this similar, so we have a big set of timings in timing and the final timing in responseEndTiming.

I thought about amending the ResourceTiming type instead, but then requestFinished would suddenly have the response end time both in responseEndTiming and in response.timing.responseEnd - that felt confusing.

github-actions · 2024-09-18T14:51:58Z

Test results for "tests 1"

2 failed
❌ [playwright-test] › babel.spec.ts:135:5 › should not transform external
❌ [playwright-test] › fixture-errors.spec.ts:471:5 › should not give enough time for second fixture teardown after timeout

3 flaky

⚠️ [firefox-library] › library/inspector/cli-codegen-2.spec.ts:407:7 › cli codegen › click should emit events in order
⚠️ [playwright-test] › ui-mode-test-ct.spec.ts:59:5 › should run component tests after editing test
⚠️ [webkit-library] › library/download.spec.ts:698:3 › should convert navigation to a resource with unsupported mime type into download

35496 passed, 659 skipped
✔️✔️✔️

Merge workflow run.

Skn0tt · 2024-09-27T11:27:57Z

We discussed this with the team and decided against exposing this via the API. Playwright isn't a network performance testing tool, and we don't want people using it like one. Rough timings can easily be measured in userland.

I'll open a separate PR to fix the bugs around HTTP / SOCKS Proxy we found in the existing measurements for HAR timings.

) Fixes a bug discovered in #32647. When using http proxy, the `connect` event isn't emitted so we don't populate `tcpConnectionAt`. The updated version of `https-proxy-agent` emits a `proxyConnect` as a replacement, so this PR updates and listens to that event. For socks proxies, the `on("socket")` event is emitted once the SOCKS connection is established, which is the equivalent of having a TCP connection available. --------- Signed-off-by: Simon Knott <[email protected]> Co-authored-by: Max Schmitt <[email protected]>

Skn0tt self-assigned this Sep 17, 2024