tests: better times for generated network requests #14714

brendankenny · 2023-01-26T00:46:15Z

network-records-to-devtools-log is very convenient, but it has always played fast and loose with network timings, doing pretty much the bare minimum to create partial network records with the given timings, even when those timings don't internally make sense (startTime can be after endTime, etc). This worked because unit tests usually provided the properties needed for the unit being tested, but that's fragile and it finally caught up to us in #14574 when combined with the timing complexity of _recomputeTimesWithResourceTiming.

So, it's time to have network-records-to-devtools-log actually put in some effort into generating internally consistent timing. Unfortunately the many interrelations between the timings make this a little complex, but they're pretty easily testable, expandable if new properties are needed, and AFAIK the fundamentals haven't changed for the lifetime of Lighthouse so should be pretty stable. There's also a bunch of new assertions to assist authoring to let you know if you've asked for an impossible network request (which we've done a few times).

The approach is to look at each partial network request individually, extract any timing properties provided, assert they're internally consistent, and then fill in the rest of the timing properties with values that are at least possible (under the assumption that if more probable values are needed, the caller would need to provide them). This produces a normalized timing object, which is then used for any subsequent uses of timing data so that the logic is all in one place instead of spread out in each function producing a devtoolsLog entry, as it was before.

brendankenny · 2023-01-26T00:47:29Z

core/test/audits/preload-lcp-image-test.js

@@ -55,7 +55,7 @@ describe('Performance: preload-lcp audit', () => {
        priority: 'High',
        isLinkPreload: false,
        startTime: 0,
-        endTime: 0.5,
+        endTime: 500,


startTime 0 + receiveHeadersEnd 500 is well after an endTime of 0.5 :)

brendankenny · 2023-01-26T00:49:31Z

core/test/computed/metrics/lantern-first-contentful-paint-test.js

+        endTime: 1000,
        timing: {sslStart: 50, sslEnd: 100, connectStart: 50, connectEnd: 100},


these timing entries aren't possible before an endTime of 0.0001, but going back to #13452, main document is always included (so doesn't need to be before FCP), and the next (incomplete) request can be any time after FCP, so these changes still hit the check added in that PR

brendankenny · 2023-01-26T00:50:46Z

core/test/gather/gatherers/inspector-issues-test.js

 */
 function mockRequest(partial) {
-  return Object.assign(new NetworkRequest(), {


assigning to a new NetworkRequest makes for a weird network request (lots of -1s), and then passing it through networkRecordsToDevtoolsLog just breaks things. Instead, just use networkRecordsToDevtoolsLog and NetworkRecorder to make the NetworkRequests

brendankenny · 2023-01-26T00:51:28Z

core/test/lib/network-request-test.js

-        endTime: 2000,
+        startTime: 50,
        responseReceivedTime: 1000,
+        endTime: 2000,


test change from #14574 to verify this works for that

brendankenny · 2023-01-26T00:59:49Z

core/test/network-records-to-devtools-log.js

+ * Takes the partial network timing and fills in the missing values so at least
+ * time is linear (if not realistic). The main timing properties on


brendankenny · 2023-01-26T01:00:37Z

core/test/network-records-to-devtools-log.js

+    responseReceivedTime,
+    endTime,
+    timing: {
+      // TODO: other `timing` properties could have default values.


this could be expanded, e.g. no DNS for follow up requests, no SSL for non-https, etc, but seemed unnecessary for now

brendankenny · 2023-01-26T01:01:25Z

core/test/network-records-to-devtools-log.js

+    // Note: since redirectResponseTimestamp (aka the redirect's endTime) is
+    // used as a last resort, some redirected requests may start before the
+    // redirect ends. Up to the caller to override if this matters.


this isn't possible to fix without figuring out timing for all requests at once instead of individually, so the extra complexity didn't seem worth it (afaik there's no real correctness problem, just might be surprising)

paulirish · 2023-01-26T01:31:44Z

core/test/network-records-to-devtools-log.js

+// Default request startTime if none provided. Do not use 0 due to guard against
+// bad network records starting at 0. See https://github.com/GoogleChrome/lighthouse/pull/6780
+const defaultStart = 1000;
+const defaultTimingOffset = 1000;


these two values just allow us to be lazy when making mock requests and the results will look reasonable, right?
If the true numbers arent provided, then the req starts at 1000 and then two of the phases take at least 1s.. ya?

yep, exactly. I left a comment saying basically that down on getNormalizedRequestTiming but could put something up here as well if it would help

connorjclark

Seems great.

connorjclark · 2023-01-26T19:34:29Z

core/test/network-records-to-devtools-log.js

+ * are up to the caller to order correctly. If no absolute times are provided,
+ * starts at `defaultStart`, finishes receiving headers `defaultTimingOffset` ms
+ * later, then endTime is `defaultTimingOffset` ms after that.


Suggested change

* are up to the caller to order correctly. If no absolute times are provided,

* starts at `defaultStart`, finishes receiving headers `defaultTimingOffset` ms

* later, then endTime is `defaultTimingOffset` ms after that.

* are up to the caller to order correctly.

* If no absolute times are provided: starts at `defaultStart`, finishes receiving

* headers `defaultTimingOffset` ms later, then endTime is `defaultTimingOffset` ms after that.

I'm having some trouble parsing this sentence. Trivial edit above, but hopefully you can improve further.

connorjclark · 2023-01-26T19:35:47Z

core/test/network-records-to-devtools-log.js

+    // redirect ends. Up to the caller to override if this matters.
+    extractedTimes.redirectResponseTimestamp,
+  ];
+  const startTime = possibleStarts.filter(timeDefined)[0] ?? defaultStart;


nit

Suggested change

const startTime = possibleStarts.filter(timeDefined)[0] ?? defaultStart;

const startTime = possibleStarts.find(timeDefined) ?? defaultStart;

connorjclark · 2023-01-26T19:44:54Z

core/test/network-records-to-devtools-log.js

+    for (let j = i + 1; j < keys.length; j++) {
+      const comparison = keys[j];
+      if (!timeDefined(values[comparison])) continue;
+      assert(values[step] <= values[comparison], `'${step}' (${values[step]}) exceeds '${comparison}' (${values[comparison]}) in test network record`); // eslint-disable-line max-len


I had a minor concern about how much this would generate the error string without ever needing to show it, but this path is hit <3000 times when running the core tests so not a big deal.

tests: better times for generated network requests

81a8fa2

brendankenny requested a review from a team as a code owner January 26, 2023 00:46

brendankenny requested review from connorjclark and removed request for a team January 26, 2023 00:46

devtools-bot assigned connorjclark Jan 26, 2023

devtools-bot added the waiting4reviewer label Jan 26, 2023

brendankenny commented Jan 26, 2023

View reviewed changes

Merge branch 'main' into generate-timing

3553b97

vercel bot deployed to Preview January 26, 2023 01:11 View deployment

paulirish reviewed Jan 26, 2023

View reviewed changes

Merge branch 'main' into generate-timing

7694892

vercel bot deployed to Preview January 26, 2023 18:52 View deployment

connorjclark approved these changes Jan 26, 2023

View reviewed changes

feedback

36e6f64

vercel bot deployed to Preview January 26, 2023 21:18 View deployment

brendankenny added the land-when-ci-is-green label Jan 26, 2023

brendankenny merged commit f22a3ed into main Jan 26, 2023

brendankenny deleted the generate-timing branch January 26, 2023 21:33

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

tests: better times for generated network requests #14714

tests: better times for generated network requests #14714

brendankenny commented Jan 26, 2023 •

edited

Loading

brendankenny Jan 26, 2023

brendankenny Jan 26, 2023 •

edited

Loading

brendankenny Jan 26, 2023 •

edited

Loading

brendankenny Jan 26, 2023

brendankenny Jan 26, 2023

brendankenny Jan 26, 2023

brendankenny Jan 26, 2023 •

edited

Loading

paulirish Jan 26, 2023

brendankenny Jan 26, 2023

connorjclark left a comment

connorjclark Jan 26, 2023

connorjclark Jan 26, 2023

brendankenny Jan 26, 2023

connorjclark Jan 26, 2023

		endTime: 1000,
		timing: {sslStart: 50, sslEnd: 100, connectStart: 50, connectEnd: 100},

		* Takes the partial network timing and fills in the missing values so at least
		* time is linear (if not realistic). The main timing properties on

	const startTime = possibleStarts.filter(timeDefined)[0] ?? defaultStart;
	const startTime = possibleStarts.find(timeDefined) ?? defaultStart;

tests: better times for generated network requests #14714

tests: better times for generated network requests #14714

Conversation

brendankenny commented Jan 26, 2023 • edited Loading

Choose a reason for hiding this comment

brendankenny Jan 26, 2023 • edited Loading

Choose a reason for hiding this comment

brendankenny Jan 26, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

brendankenny Jan 26, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

connorjclark left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

brendankenny commented Jan 26, 2023 •

edited

Loading

brendankenny Jan 26, 2023 •

edited

Loading

brendankenny Jan 26, 2023 •

edited

Loading

brendankenny Jan 26, 2023 •

edited

Loading