From 5e88a26dae811460a3f148bab3089179ea7f496f Mon Sep 17 00:00:00 2001 From: Shane Exterkamp Date: Tue, 9 Apr 2019 10:01:28 -0700 Subject: [PATCH 1/5] Add timing data application and tests back. --- lighthouse-core/lib/network-request.js | 35 +++++++++- .../test/lib/network-request-test.js | 65 ++++++++++++++++++- 2 files changed, 96 insertions(+), 4 deletions(-) diff --git a/lighthouse-core/lib/network-request.js b/lighthouse-core/lib/network-request.js index c1be94fed1ac..55b51faf267d 100644 --- a/lighthouse-core/lib/network-request.js +++ b/lighthouse-core/lib/network-request.js @@ -428,8 +428,41 @@ class NetworkRequest { return; } + // Init blank timing if needed. + if (this.timing === undefined) { + this.timing = { + requestTime: this.startTime, + proxyStart: -1, + proxyEnd: -1, + dnsStart: -1, + dnsEnd: -1, + connectStart: -1, + connectEnd: -1, + sslStart: -1, + sslEnd: -1, + workerStart: -1, + workerReady: -1, + sendStart: -1, + sendEnd: -1, + pushStart: -1, + pushEnd: -1, + receiveHeadersEnd: -1, + }; + } + + const origEnd = this.endTime; + // EndTime and responseReceivedTime are in seconds, so conversion is necessary. + this.endTime = this.startTime + (totalMs / 1000); + this.responseReceivedTime = this.startTime + ((TCPMs + requestMs) / 1000); + this.timing.connectStart = 0; + this.timing.connectEnd = TCPMs; + this.timing.sslStart = TCPMs - SSLMs; + this.timing.sslEnd = TCPMs; + this.timing.sendStart = TCPMs; + this.timing.sendEnd = TCPMs; + this.timing.receiveHeadersEnd = TCPMs + requestMs; this.lrStatistics = { - endTimeDeltaMs: (this.endTime - (this.startTime + (totalMs / 1000))) * 1000, + endTimeDeltaMs: (origEnd - this.endTime) * 1000, TCPMs: TCPMs, requestMs: requestMs, responseMs: responseMs, diff --git a/lighthouse-core/test/lib/network-request-test.js b/lighthouse-core/test/lib/network-request-test.js index ea6c5554ee6e..797ee738bcdc 100644 --- a/lighthouse-core/test/lib/network-request-test.js +++ b/lighthouse-core/test/lib/network-request-test.js @@ -90,7 +90,7 @@ describe('NetworkRequest', () => { }; } - it('updates lrStatistics if in Lightrider', () => { + it('updates fetch stats and lrStatistics if in Lightrider', () => { const req = getRequest(); const devtoolsLog = networkRecordsToDevtoolsLog([req]); @@ -98,8 +98,8 @@ describe('NetworkRequest', () => { const record = NetworkRecorder.recordsFromLogs(devtoolsLog)[0]; expect(record.startTime).toStrictEqual(0); - expect(record.endTime).toStrictEqual(2); - expect(record.responseReceivedTime).toStrictEqual(1); + expect(record.endTime).toStrictEqual(10); + expect(record.responseReceivedTime).toStrictEqual(7.5); expect(record.lrStatistics).toStrictEqual({ endTimeDeltaMs: -8000, TCPMs: 5000, @@ -176,5 +176,64 @@ describe('NetworkRequest', () => { expect(record).toMatchObject(req); expect(record.lrStatistics).toStrictEqual(undefined); }); + + it('Handles negative timing data', function() { + const req = getRequest(); + req.responseHeaders = [{name: NetworkRequest.HEADER_TOTAL, value: '10000'}, + {name: NetworkRequest.HEADER_TCP, value: '-1'}, + {name: NetworkRequest.HEADER_REQ, value: '-1'}, + {name: NetworkRequest.HEADER_SSL, value: '-1'}, + {name: NetworkRequest.HEADER_RES, value: '10000'}]; + + const devtoolsLog = networkRecordsToDevtoolsLog([req]); + global.isLightrider = true; + const record = NetworkRecorder.recordsFromLogs(devtoolsLog)[0]; + + expect(record.startTime).toStrictEqual(0); + expect(record.endTime).toStrictEqual(10); + expect(record.responseReceivedTime).toStrictEqual(0); + expect(record.lrStatistics).toStrictEqual({ + endTimeDeltaMs: -8000, + TCPMs: 0, + requestMs: 0, + responseMs: 10000, + }); + }); + + it('does not updates fetch stats if SLLMs > TCPMs', function() { + const req = getRequest(); + const sslHeader = req.responseHeaders[3]; + expect(sslHeader.name).toStrictEqual(NetworkRequest.HEADER_SSL); + sslHeader.value = '6000'; + + const devtoolsLog = networkRecordsToDevtoolsLog([req]); + global.isLightrider = true; + const record = NetworkRecorder.recordsFromLogs(devtoolsLog)[0]; + + expect(record).toMatchObject(req); + expect(record.lrStatistics).toStrictEqual(undefined); + }); + + it('initialized a blank timing', function() { + const req = getRequest(); + + const devtoolsLog = networkRecordsToDevtoolsLog([req]); + const record = NetworkRecorder.recordsFromLogs(devtoolsLog)[0]; + global.isLightrider = true; + + expect(record.timing).toStrictEqual(undefined); + record._updateTimingsForLightrider(); + expect(record.timing.proxyStart).toStrictEqual(-1); + + expect(record.startTime).toStrictEqual(0); + expect(record.endTime).toStrictEqual(10); + expect(record.responseReceivedTime).toStrictEqual(7.5); + expect(record.lrStatistics).toStrictEqual({ + endTimeDeltaMs: -8000, + TCPMs: 5000, + requestMs: 2500, + responseMs: 2500, + }); + }); }); }); From 7e516526c3e1681bf3010a9938286521eb3517df Mon Sep 17 00:00:00 2001 From: Shane Exterkamp Date: Tue, 9 Apr 2019 12:56:59 -0700 Subject: [PATCH 2/5] Add whitespace --- lighthouse-core/lib/network-request.js | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/lighthouse-core/lib/network-request.js b/lighthouse-core/lib/network-request.js index 55b51faf267d..0afb8a3dfc65 100644 --- a/lighthouse-core/lib/network-request.js +++ b/lighthouse-core/lib/network-request.js @@ -451,9 +451,10 @@ class NetworkRequest { } const origEnd = this.endTime; - // EndTime and responseReceivedTime are in seconds, so conversion is necessary. + // `this.endTime` and `this.responseReceivedTime` are in seconds, so convert from milliseconds. this.endTime = this.startTime + (totalMs / 1000); this.responseReceivedTime = this.startTime + ((TCPMs + requestMs) / 1000); + this.timing.connectStart = 0; this.timing.connectEnd = TCPMs; this.timing.sslStart = TCPMs - SSLMs; @@ -461,6 +462,7 @@ class NetworkRequest { this.timing.sendStart = TCPMs; this.timing.sendEnd = TCPMs; this.timing.receiveHeadersEnd = TCPMs + requestMs; + this.lrStatistics = { endTimeDeltaMs: (origEnd - this.endTime) * 1000, TCPMs: TCPMs, From 1c1ac75c8f7192f9c6cec6a14fcb2382686b8812 Mon Sep 17 00:00:00 2001 From: Shane Exterkamp Date: Tue, 9 Apr 2019 13:32:16 -0700 Subject: [PATCH 3/5] Testing changes. --- .../test/lib/network-request-test.js | 102 +++++++++++++++--- 1 file changed, 85 insertions(+), 17 deletions(-) diff --git a/lighthouse-core/test/lib/network-request-test.js b/lighthouse-core/test/lib/network-request-test.js index 797ee738bcdc..a5ca25f175d6 100644 --- a/lighthouse-core/test/lib/network-request-test.js +++ b/lighthouse-core/test/lib/network-request-test.js @@ -90,7 +90,7 @@ describe('NetworkRequest', () => { }; } - it('updates fetch stats and lrStatistics if in Lightrider', () => { + it('updates timings if in Lightrider', () => { const req = getRequest(); const devtoolsLog = networkRecordsToDevtoolsLog([req]); @@ -100,6 +100,13 @@ describe('NetworkRequest', () => { expect(record.startTime).toStrictEqual(0); expect(record.endTime).toStrictEqual(10); expect(record.responseReceivedTime).toStrictEqual(7.5); + expect(record.timing.connectStart).toStrictEqual(0); + expect(record.timing.connectEnd).toStrictEqual(5000); + expect(record.timing.sslStart).toStrictEqual(4000); + expect(record.timing.sslEnd).toStrictEqual(5000); + expect(record.timing.sendStart).toStrictEqual(5000); + expect(record.timing.sendEnd).toStrictEqual(5000); + expect(record.timing.receiveHeadersEnd).toStrictEqual(7500); expect(record.lrStatistics).toStrictEqual({ endTimeDeltaMs: -8000, TCPMs: 5000, @@ -177,7 +184,7 @@ describe('NetworkRequest', () => { expect(record.lrStatistics).toStrictEqual(undefined); }); - it('Handles negative timing data', function() { + it('treats negative timings as 0', function() { const req = getRequest(); req.responseHeaders = [{name: NetworkRequest.HEADER_TOTAL, value: '10000'}, {name: NetworkRequest.HEADER_TCP, value: '-1'}, @@ -192,6 +199,13 @@ describe('NetworkRequest', () => { expect(record.startTime).toStrictEqual(0); expect(record.endTime).toStrictEqual(10); expect(record.responseReceivedTime).toStrictEqual(0); + expect(record.timing.connectStart).toStrictEqual(0); + expect(record.timing.connectEnd).toStrictEqual(0); + expect(record.timing.sslStart).toStrictEqual(0); + expect(record.timing.sslEnd).toStrictEqual(0); + expect(record.timing.sendStart).toStrictEqual(0); + expect(record.timing.sendEnd).toStrictEqual(0); + expect(record.timing.receiveHeadersEnd).toStrictEqual(0); expect(record.lrStatistics).toStrictEqual({ endTimeDeltaMs: -8000, TCPMs: 0, @@ -200,35 +214,89 @@ describe('NetworkRequest', () => { }); }); - it('does not updates fetch stats if SLLMs > TCPMs', function() { + it('treats missing timings as 0', function() { const req = getRequest(); - const sslHeader = req.responseHeaders[3]; - expect(sslHeader.name).toStrictEqual(NetworkRequest.HEADER_SSL); - sslHeader.value = '6000'; + req.responseHeaders = [{name: NetworkRequest.HEADER_TOTAL, value: '10000'}, + {name: NetworkRequest.HEADER_TCP, value: '1000'}, + {name: NetworkRequest.HEADER_RES, value: '9000'}]; const devtoolsLog = networkRecordsToDevtoolsLog([req]); global.isLightrider = true; const record = NetworkRecorder.recordsFromLogs(devtoolsLog)[0]; - expect(record).toMatchObject(req); - expect(record.lrStatistics).toStrictEqual(undefined); + expect(record.startTime).toStrictEqual(0); + expect(record.endTime).toStrictEqual(10); + expect(record.responseReceivedTime).toStrictEqual(1); + expect(record.timing.connectStart).toStrictEqual(0); + expect(record.timing.connectEnd).toStrictEqual(1000); + expect(record.timing.sslStart).toStrictEqual(1000); + expect(record.timing.sslEnd).toStrictEqual(1000); + expect(record.timing.sendStart).toStrictEqual(1000); + expect(record.timing.sendEnd).toStrictEqual(1000); + expect(record.timing.receiveHeadersEnd).toStrictEqual(1000); + expect(record.lrStatistics).toStrictEqual({ + endTimeDeltaMs: -8000, + TCPMs: 1000, + requestMs: 0, + responseMs: 9000, + }); }); - it('initialized a blank timing', function() { + it('created a new timing property if one did not exist', function() { const req = getRequest(); const devtoolsLog = networkRecordsToDevtoolsLog([req]); - const record = NetworkRecorder.recordsFromLogs(devtoolsLog)[0]; + + const noLRRecord = NetworkRecorder.recordsFromLogs(devtoolsLog)[0]; + expect(noLRRecord.timing).toStrictEqual(undefined); + global.isLightrider = true; + const lrRecord = NetworkRecorder.recordsFromLogs(devtoolsLog)[0]; + expect(lrRecord.timing.proxyStart).toStrictEqual(-1); + + expect(lrRecord.startTime).toStrictEqual(0); + expect(lrRecord.endTime).toStrictEqual(10); + expect(lrRecord.responseReceivedTime).toStrictEqual(7.5); + expect(lrRecord.timing.proxyStart).toStrictEqual(-1); + expect(lrRecord.timing.connectStart).toStrictEqual(0); + expect(lrRecord.timing.connectEnd).toStrictEqual(5000); + expect(lrRecord.timing.sslStart).toStrictEqual(4000); + expect(lrRecord.timing.sslEnd).toStrictEqual(5000); + expect(lrRecord.timing.sendStart).toStrictEqual(5000); + expect(lrRecord.timing.sendEnd).toStrictEqual(5000); + expect(lrRecord.timing.receiveHeadersEnd).toStrictEqual(7500); + expect(lrRecord.lrStatistics).toStrictEqual({ + endTimeDeltaMs: -8000, + TCPMs: 5000, + requestMs: 2500, + responseMs: 2500, + }); + }); + + it('merges with existing timing properties', function() { + const req = getRequest(); + req.timing = {proxyStart: 17, sslStart: 35}; + const devtoolsLog = networkRecordsToDevtoolsLog([req]); - expect(record.timing).toStrictEqual(undefined); - record._updateTimingsForLightrider(); - expect(record.timing.proxyStart).toStrictEqual(-1); + const noLRRecord = NetworkRecorder.recordsFromLogs(devtoolsLog)[0]; + expect(noLRRecord.timing.proxyStart).toStrictEqual(17); + expect(noLRRecord.timing.sslStart).toStrictEqual(35); - expect(record.startTime).toStrictEqual(0); - expect(record.endTime).toStrictEqual(10); - expect(record.responseReceivedTime).toStrictEqual(7.5); - expect(record.lrStatistics).toStrictEqual({ + global.isLightrider = true; + const lrRecord = NetworkRecorder.recordsFromLogs(devtoolsLog)[0]; + + expect(lrRecord.startTime).toStrictEqual(0); + expect(lrRecord.endTime).toStrictEqual(10); + expect(lrRecord.responseReceivedTime).toStrictEqual(7.5); + expect(lrRecord.timing.proxyStart).toStrictEqual(17); + expect(lrRecord.timing.connectStart).toStrictEqual(0); + expect(lrRecord.timing.connectEnd).toStrictEqual(5000); + expect(lrRecord.timing.sslStart).toStrictEqual(4000); + expect(lrRecord.timing.sslEnd).toStrictEqual(5000); + expect(lrRecord.timing.sendStart).toStrictEqual(5000); + expect(lrRecord.timing.sendEnd).toStrictEqual(5000); + expect(lrRecord.timing.receiveHeadersEnd).toStrictEqual(7500); + expect(lrRecord.lrStatistics).toStrictEqual({ endTimeDeltaMs: -8000, TCPMs: 5000, requestMs: 2500, From a0e5fd24f95a166c3495a13f0e2ff5a5f9e907ef Mon Sep 17 00:00:00 2001 From: Shane Exterkamp Date: Tue, 9 Apr 2019 14:57:51 -0700 Subject: [PATCH 4/5] Convert tests to toMatchObject --- .../test/lib/network-request-test.js | 84 +++++++++++-------- 1 file changed, 47 insertions(+), 37 deletions(-) diff --git a/lighthouse-core/test/lib/network-request-test.js b/lighthouse-core/test/lib/network-request-test.js index a5ca25f175d6..8f1fa323be25 100644 --- a/lighthouse-core/test/lib/network-request-test.js +++ b/lighthouse-core/test/lib/network-request-test.js @@ -100,13 +100,15 @@ describe('NetworkRequest', () => { expect(record.startTime).toStrictEqual(0); expect(record.endTime).toStrictEqual(10); expect(record.responseReceivedTime).toStrictEqual(7.5); - expect(record.timing.connectStart).toStrictEqual(0); - expect(record.timing.connectEnd).toStrictEqual(5000); - expect(record.timing.sslStart).toStrictEqual(4000); - expect(record.timing.sslEnd).toStrictEqual(5000); - expect(record.timing.sendStart).toStrictEqual(5000); - expect(record.timing.sendEnd).toStrictEqual(5000); - expect(record.timing.receiveHeadersEnd).toStrictEqual(7500); + expect(record.timing).toMatchObject({ + connectStart: 0, + connectEnd: 5000, + sslStart: 4000, + sslEnd: 5000, + sendStart: 5000, + sendEnd: 5000, + receiveHeadersEnd: 7500, + }); expect(record.lrStatistics).toStrictEqual({ endTimeDeltaMs: -8000, TCPMs: 5000, @@ -199,13 +201,15 @@ describe('NetworkRequest', () => { expect(record.startTime).toStrictEqual(0); expect(record.endTime).toStrictEqual(10); expect(record.responseReceivedTime).toStrictEqual(0); - expect(record.timing.connectStart).toStrictEqual(0); - expect(record.timing.connectEnd).toStrictEqual(0); - expect(record.timing.sslStart).toStrictEqual(0); - expect(record.timing.sslEnd).toStrictEqual(0); - expect(record.timing.sendStart).toStrictEqual(0); - expect(record.timing.sendEnd).toStrictEqual(0); - expect(record.timing.receiveHeadersEnd).toStrictEqual(0); + expect(record.timing).toMatchObject({ + connectStart: 0, + connectEnd: 0, + sslStart: 0, + sslEnd: 0, + sendStart: 0, + sendEnd: 0, + receiveHeadersEnd: 0, + }); expect(record.lrStatistics).toStrictEqual({ endTimeDeltaMs: -8000, TCPMs: 0, @@ -227,13 +231,15 @@ describe('NetworkRequest', () => { expect(record.startTime).toStrictEqual(0); expect(record.endTime).toStrictEqual(10); expect(record.responseReceivedTime).toStrictEqual(1); - expect(record.timing.connectStart).toStrictEqual(0); - expect(record.timing.connectEnd).toStrictEqual(1000); - expect(record.timing.sslStart).toStrictEqual(1000); - expect(record.timing.sslEnd).toStrictEqual(1000); - expect(record.timing.sendStart).toStrictEqual(1000); - expect(record.timing.sendEnd).toStrictEqual(1000); - expect(record.timing.receiveHeadersEnd).toStrictEqual(1000); + expect(record.timing).toMatchObject({ + connectStart: 0, + connectEnd: 1000, + sslStart: 1000, + sslEnd: 1000, + sendStart: 1000, + sendEnd: 1000, + receiveHeadersEnd: 1000, + }); expect(record.lrStatistics).toStrictEqual({ endTimeDeltaMs: -8000, TCPMs: 1000, @@ -257,14 +263,16 @@ describe('NetworkRequest', () => { expect(lrRecord.startTime).toStrictEqual(0); expect(lrRecord.endTime).toStrictEqual(10); expect(lrRecord.responseReceivedTime).toStrictEqual(7.5); - expect(lrRecord.timing.proxyStart).toStrictEqual(-1); - expect(lrRecord.timing.connectStart).toStrictEqual(0); - expect(lrRecord.timing.connectEnd).toStrictEqual(5000); - expect(lrRecord.timing.sslStart).toStrictEqual(4000); - expect(lrRecord.timing.sslEnd).toStrictEqual(5000); - expect(lrRecord.timing.sendStart).toStrictEqual(5000); - expect(lrRecord.timing.sendEnd).toStrictEqual(5000); - expect(lrRecord.timing.receiveHeadersEnd).toStrictEqual(7500); + expect(lrRecord.timing).toMatchObject({ + proxyStart: -1, + connectStart: 0, + connectEnd: 5000, + sslStart: 4000, + sslEnd: 5000, + sendStart: 5000, + sendEnd: 5000, + receiveHeadersEnd: 7500, + }); expect(lrRecord.lrStatistics).toStrictEqual({ endTimeDeltaMs: -8000, TCPMs: 5000, @@ -288,14 +296,16 @@ describe('NetworkRequest', () => { expect(lrRecord.startTime).toStrictEqual(0); expect(lrRecord.endTime).toStrictEqual(10); expect(lrRecord.responseReceivedTime).toStrictEqual(7.5); - expect(lrRecord.timing.proxyStart).toStrictEqual(17); - expect(lrRecord.timing.connectStart).toStrictEqual(0); - expect(lrRecord.timing.connectEnd).toStrictEqual(5000); - expect(lrRecord.timing.sslStart).toStrictEqual(4000); - expect(lrRecord.timing.sslEnd).toStrictEqual(5000); - expect(lrRecord.timing.sendStart).toStrictEqual(5000); - expect(lrRecord.timing.sendEnd).toStrictEqual(5000); - expect(lrRecord.timing.receiveHeadersEnd).toStrictEqual(7500); + expect(lrRecord.timing).toMatchObject({ + proxyStart: 17, + connectStart: 0, + connectEnd: 5000, + sslStart: 4000, + sslEnd: 5000, + sendStart: 5000, + sendEnd: 5000, + receiveHeadersEnd: 7500, + }); expect(lrRecord.lrStatistics).toStrictEqual({ endTimeDeltaMs: -8000, TCPMs: 5000, From 6d5c53dea0eb7f58933e17f8b42013145971f1fd Mon Sep 17 00:00:00 2001 From: Shane Exterkamp Date: Wed, 10 Apr 2019 00:06:09 -0700 Subject: [PATCH 5/5] Always override timings and update tests. --- lighthouse-core/lib/network-request.js | 40 +++++++++---------- .../test/lib/network-request-test.js | 4 +- 2 files changed, 21 insertions(+), 23 deletions(-) diff --git a/lighthouse-core/lib/network-request.js b/lighthouse-core/lib/network-request.js index 0afb8a3dfc65..b93c7eeb104c 100644 --- a/lighthouse-core/lib/network-request.js +++ b/lighthouse-core/lib/network-request.js @@ -428,27 +428,25 @@ class NetworkRequest { return; } - // Init blank timing if needed. - if (this.timing === undefined) { - this.timing = { - requestTime: this.startTime, - proxyStart: -1, - proxyEnd: -1, - dnsStart: -1, - dnsEnd: -1, - connectStart: -1, - connectEnd: -1, - sslStart: -1, - sslEnd: -1, - workerStart: -1, - workerReady: -1, - sendStart: -1, - sendEnd: -1, - pushStart: -1, - pushEnd: -1, - receiveHeadersEnd: -1, - }; - } + // Init timing. + this.timing = { + requestTime: this.startTime, + proxyStart: -1, + proxyEnd: -1, + dnsStart: -1, + dnsEnd: -1, + connectStart: -1, + connectEnd: -1, + sslStart: -1, + sslEnd: -1, + workerStart: -1, + workerReady: -1, + sendStart: -1, + sendEnd: -1, + pushStart: -1, + pushEnd: -1, + receiveHeadersEnd: -1, + }; const origEnd = this.endTime; // `this.endTime` and `this.responseReceivedTime` are in seconds, so convert from milliseconds. diff --git a/lighthouse-core/test/lib/network-request-test.js b/lighthouse-core/test/lib/network-request-test.js index 8f1fa323be25..5abdfa5d6234 100644 --- a/lighthouse-core/test/lib/network-request-test.js +++ b/lighthouse-core/test/lib/network-request-test.js @@ -281,7 +281,7 @@ describe('NetworkRequest', () => { }); }); - it('merges with existing timing properties', function() { + it('overrides existing timing properties', function() { const req = getRequest(); req.timing = {proxyStart: 17, sslStart: 35}; const devtoolsLog = networkRecordsToDevtoolsLog([req]); @@ -297,7 +297,7 @@ describe('NetworkRequest', () => { expect(lrRecord.endTime).toStrictEqual(10); expect(lrRecord.responseReceivedTime).toStrictEqual(7.5); expect(lrRecord.timing).toMatchObject({ - proxyStart: 17, + proxyStart: -1, connectStart: 0, connectEnd: 5000, sslStart: 4000,