clients(lr): gather network timing numbers from headers (#7888)

lighthouse-core/audits/network-requests.js

@@ -41,6 +41,11 @@ class NetworkRequests extends Audit {
         undefined : (time - earliestStartTime) * 1000;
 
       const results = records.map(record => {
+        const endTimeDeltaMs = record.lrStatistics && record.lrStatistics.endTimeDeltaMs;
+        const TCPMs = record.lrStatistics && record.lrStatistics.TCPMs;
+        const requestMs = record.lrStatistics && record.lrStatistics.requestMs;
+        const responseMs = record.lrStatistics && record.lrStatistics.responseMs;
+
         return {
           url: URL.elideDataURI(record.url),
           startTime: timeToMs(record.startTime),
@@ -50,6 +55,10 @@ class NetworkRequests extends Audit {
           statusCode: record.statusCode,
           mimeType: record.mimeType,
           resourceType: record.resourceType,
+          lrEndTimeDeltaMs: endTimeDeltaMs, // Only exists on Lightrider runs
+          lrTCPMs: TCPMs, // Only exists on Lightrider runs
+          lrRequestMs: requestMs, // Only exists on Lightrider runs
+          lrResponseMs: responseMs, // Only exists on Lightrider runs
         };
       });
 

lighthouse-core/lib/network-request.js

@@ -15,6 +15,15 @@ const URL = require('./url-shim');
 
 const SECURE_SCHEMES = ['data', 'https', 'wss', 'blob', 'chrome', 'chrome-extension', 'about'];
 
+// Lightrider X-Header names for timing information.
+// See: _updateTransferSizeForLightrider and _updateTimingsForLightrider.
+const HEADER_TCP = 'X-TCPMs';
+const HEADER_SSL = 'X-SSLMs';
+const HEADER_REQ = 'X-RequestMs';
+const HEADER_RES = 'X-ResponseMs';
+const HEADER_TOTAL = 'X-TotalMs';
+const HEADER_FETCHED_SIZE = 'X-TotalFetchedSize';
+
 /**
  * @typedef HeaderEntry
  * @property {string} name
@@ -28,6 +37,18 @@ const SECURE_SCHEMES = ['data', 'https', 'wss', 'blob', 'chrome', 'chrome-extens
  * @property {string} securityOrigin
  */
 
+/**
+ * @typedef LightriderStatistics
+ * The difference in endTime between the observed Lighthouse endTime and Lightrider's derived endTime.
+ * @property {number} endTimeDeltaMs
+ * The time spent making a TCP connection (connect + SSL).
+ * @property {number} TCPMs
+ * The time spent requesting a resource from a remote server, we use this to approx RTT.
+ * @property {number} requestMs
+ * The time spent transferring a resource from a remote server.
+ * @property {number} responseMs
+ */
+
 /** @type {SelfMap<LH.Crdp.Page.ResourceType>} */
 const RESOURCE_TYPES = {
   XHR: 'XHR',
@@ -48,7 +69,7 @@ const RESOURCE_TYPES = {
   CSPViolationReport: 'CSPViolationReport',
 };
 
-module.exports = class NetworkRequest {
+class NetworkRequest {
   constructor() {
     this.requestId = '';
     this.connectionId = '0';
@@ -73,6 +94,9 @@ module.exports = class NetworkRequest {
     this.fromDiskCache = false;
     this.fromMemoryCache = false;
 
+    /** @type {LightriderStatistics|undefined} Extra timing information available only when run in Lightrider. */
+    this.lrStatistics = undefined;
+
     this.finished = false;
     this.requestMethod = '';
     this.statusCode = -1;
@@ -205,6 +229,7 @@ module.exports = class NetworkRequest {
 
     this._updateResponseReceivedTimeIfNecessary();
     this._updateTransferSizeForLightrider();
+    this._updateTimingsForLightrider();
   }
 
   /**
@@ -223,6 +248,7 @@ module.exports = class NetworkRequest {
 
     this._updateResponseReceivedTimeIfNecessary();
     this._updateTransferSizeForLightrider();
+    this._updateTimingsForLightrider();
   }
 
   /**
@@ -309,6 +335,8 @@ module.exports = class NetworkRequest {
 
     this.responseReceivedTime = Math.min(this.responseReceivedTime, headersReceivedTime);
     this.responseReceivedTime = Math.max(this.responseReceivedTime, this.startTime);
+    // We're only at responseReceived (_onResponse) at this point.
+    // This endTime may be redefined again after onLoading is done.
     this.endTime = Math.max(this.endTime, this.responseReceivedTime);
   }
 
@@ -338,13 +366,74 @@ module.exports = class NetworkRequest {
    * both dataReceived and loadingFinished.
    */
   _updateTransferSizeForLightrider() {
-    // Bail if we somehow already have transfer size data.
+    // Bail if we aren't in Lightrider.
     if (!global.isLightrider) return;
 
-    const totalFetchedSize = this.responseHeaders.find(item => item.name === 'X-TotalFetchedSize');
+    const totalFetchedSize = this.responseHeaders.find(item => item.name === HEADER_FETCHED_SIZE);
     // Bail if the header was missing.
     if (!totalFetchedSize) return;
-    this.transferSize = parseFloat(totalFetchedSize.value);
+    const floatValue = parseFloat(totalFetchedSize.value);
+    // Bail if the header cannot be parsed.
+    if (isNaN(floatValue)) return;
+    this.transferSize = floatValue;
+  }
+
+  /**
+   * LR gets additional, accurate timing information from its underlying fetch infrastructure.  This
+   * is passed in via X-Headers similar to 'X-TotalFetchedSize'.
+   */
+  _updateTimingsForLightrider() {
+    // Bail if we aren't in Lightrider.
+    if (!global.isLightrider) return;
+
+    // For more info on timing nomenclature: https://www.w3.org/TR/resource-timing-2/#processing-model
+
+    //    StartTime
+    //    | ConnectStart
+    //    | |     SSLStart  SSLEnd
+    //    | |     |         | ConnectEnd
+    //    | |     |         | | SendStart/End   ReceiveHeadersEnd
+    //    | |     |         | | |               |                EndTime
+    //    ▼ ▼     ▼         ▼ ▼ ▼               ▼                ▼
+    //    [ [TCP  [   SSL   ] ] [   Request   ] [   Response   ] ]
+    //    ▲ ▲     ▲         ▲ ▲ ▲             ▲ ▲              ▲ ▲
+    //    | |     '-SSLMs---' | '-requestMs---' '-responseMs---' |
+    //    | '----TCPMs--------'                                  |
+    //    |                                                      |
+    //    '------------------------TotalMs-----------------------'
+
+    const totalHeader = this.responseHeaders.find(item => item.name === HEADER_TOTAL);
+    // Bail if there was no totalTime.
+    if (!totalHeader) return;
+
+    const totalMs = parseInt(totalHeader.value);
+    const TCPMsHeader = this.responseHeaders.find(item => item.name === HEADER_TCP);
+    const SSLMsHeader = this.responseHeaders.find(item => item.name === HEADER_SSL);
+    const requestMsHeader = this.responseHeaders.find(item => item.name === HEADER_REQ);
+    const responseMsHeader = this.responseHeaders.find(item => item.name === HEADER_RES);
+
+    // Make sure all times are initialized and are non-negative.
+    const TCPMs = TCPMsHeader ? Math.max(0, parseInt(TCPMsHeader.value)) : 0;
+    const SSLMs = SSLMsHeader ? Math.max(0, parseInt(SSLMsHeader.value)) : 0;
+    const requestMs = requestMsHeader ? Math.max(0, parseInt(requestMsHeader.value)) : 0;
+    const responseMs = responseMsHeader ? Math.max(0, parseInt(responseMsHeader.value)) : 0;
+
+    // Bail if the timings don't add up.
+    if (TCPMs + requestMs + responseMs !== totalMs) {
+      return;
+    }
+
+    // Bail if SSL time is > TCP time.
+    if (SSLMs > TCPMs) {
+      return;
+    }
+
+    this.lrStatistics = {
+      endTimeDeltaMs: (this.endTime - (this.startTime + (totalMs / 1000))) * 1000,
+      TCPMs: TCPMs,
+      requestMs: requestMs,
+      responseMs: responseMs,
+    };
   }
 
   /**
@@ -377,4 +466,13 @@ module.exports = class NetworkRequest {
   static get TYPES() {
     return RESOURCE_TYPES;
   }
-};
+}
+
+NetworkRequest.HEADER_TCP = HEADER_TCP;
+NetworkRequest.HEADER_SSL = HEADER_SSL;
+NetworkRequest.HEADER_REQ = HEADER_REQ;
+NetworkRequest.HEADER_RES = HEADER_RES;
+NetworkRequest.HEADER_TOTAL = HEADER_TOTAL;
+NetworkRequest.HEADER_FETCHED_SIZE = HEADER_FETCHED_SIZE;
+
+module.exports = NetworkRequest;

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

@@ -0,0 +1,180 @@
+/**
+ * @license Copyright 2019 Google Inc. All Rights Reserved.
+ * Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except in compliance with the License. You may obtain a copy of the License at http://www.apache.org/licenses/LICENSE-2.0
+ * Unless required by applicable law or agreed to in writing, software distributed under the License is distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the License for the specific language governing permissions and limitations under the License.
+ */
+'use strict';
+
+const NetworkRequest = require('../../lib/network-request.js');
+const NetworkRecorder = require('../../lib/network-recorder.js');
+const networkRecordsToDevtoolsLog = require('../network-records-to-devtools-log.js');
+
+/* eslint-env jest */
+describe('NetworkRequest', () => {
+  afterEach(() => {
+    global.isLightrider = undefined;
+  });
+
+  describe('update transfer size for Lightrider', () => {
+    function getRequest() {
+      return {
+        transferSize: 100,
+        responseHeaders: [{name: NetworkRequest.HEADER_FETCHED_SIZE, value: '10'}],
+      };
+    }
+
+    it('does nothing if not Lightrider', () => {
+      const req = getRequest();
+      expect(req.transferSize).toStrictEqual(100);
+
+      const devtoolsLog = networkRecordsToDevtoolsLog([req]);
+      const record = NetworkRecorder.recordsFromLogs(devtoolsLog)[0];
+
+      expect(record.transferSize).toStrictEqual(100);
+    });
+
+    it('updates transfer size if Lightrider', () => {
+      const req = getRequest();
+      expect(req.transferSize).toStrictEqual(100);
+
+      const devtoolsLog = networkRecordsToDevtoolsLog([req]);
+      global.isLightrider = true;
+      const record = NetworkRecorder.recordsFromLogs(devtoolsLog)[0];
+
+      expect(record.transferSize).toStrictEqual(10);
+    });
+
+    it('does nothing if header is non float', () => {
+      const req = getRequest();
+      req.responseHeaders = [
+        {name: NetworkRequest.HEADER_FETCHED_SIZE, value: 'ten'},
+      ];
+      expect(req.transferSize).toStrictEqual(100);
+
+      const devtoolsLog = networkRecordsToDevtoolsLog([req]);
+      global.isLightrider = true;
+      const record = NetworkRecorder.recordsFromLogs(devtoolsLog)[0];
+
+      expect(record.transferSize).toStrictEqual(100);
+    });
+
+    it('does nothing if no header is set', () => {
+      const req = getRequest();
+      req.responseHeaders = [];
+      expect(req.transferSize).toStrictEqual(100);
+
+      const devtoolsLog = networkRecordsToDevtoolsLog([req]);
+      global.isLightrider = true;
+      const record = NetworkRecorder.recordsFromLogs(devtoolsLog)[0];
+
+      expect(record.transferSize).toStrictEqual(100);
+    });
+  });
+
+  describe('update fetch stats for Lightrider', () => {
+    function getRequest() {
+      return {
+        // units = seconds
+        startTime: 0,
+        endTime: 2,
+        responseReceivedTime: 1,
+
+        // units = ms
+        responseHeaders: [
+          {name: NetworkRequest.HEADER_TOTAL, value: '10000'},
+          {name: NetworkRequest.HEADER_TCP, value: '5000'},
+          {name: NetworkRequest.HEADER_REQ, value: '2500'},
+          {name: NetworkRequest.HEADER_SSL, value: '1000'},
+          {name: NetworkRequest.HEADER_RES, value: '2500'},
+        ],
+      };
+    }
+
+    it('updates lrStatistics if in Lightrider', () => {
+      const req = getRequest();
+
+      const devtoolsLog = networkRecordsToDevtoolsLog([req]);
+      global.isLightrider = true;
+      const record = NetworkRecorder.recordsFromLogs(devtoolsLog)[0];
+
+      expect(record.startTime).toStrictEqual(0);
+      expect(record.endTime).toStrictEqual(2);
+      expect(record.responseReceivedTime).toStrictEqual(1);
+      expect(record.lrStatistics).toStrictEqual({
+        endTimeDeltaMs: -8000,
+        TCPMs: 5000,
+        requestMs: 2500,
+        responseMs: 2500,
+      });
+    });
+
+    it('does nothing if not Lightrider', () => {
+      const req = getRequest();
+      req.responseHeaders = [];
+
+      const devtoolsLog = networkRecordsToDevtoolsLog([req]);
+      global.isLightrider = false;
+      const record = NetworkRecorder.recordsFromLogs(devtoolsLog)[0];
+
+      expect(record).toMatchObject(req);
+      expect(record.lrStatistics).toStrictEqual(undefined);
+    });
+
+    it('does nothing if no HEADER_TOTAL', () => {
+      const req = getRequest();
+      req.responseHeaders = req.responseHeaders.filter(item => {
+        return item.name !== NetworkRequest.HEADER_TOTAL;
+      });
+
+      const devtoolsLog = networkRecordsToDevtoolsLog([req]);
+      global.isLightrider = true;
+      const record = NetworkRecorder.recordsFromLogs(devtoolsLog)[0];
+
+      expect(record).toMatchObject(req);
+      expect(record.lrStatistics).toStrictEqual(undefined);
+    });
+
+    it('does nothing if header timings do not add up', () => {
+      const req = getRequest();
+      const tcpHeader = req.responseHeaders[1];
+      expect(tcpHeader.name).toStrictEqual(NetworkRequest.HEADER_TCP);
+      tcpHeader.value = '5001';
+
+      const devtoolsLog = networkRecordsToDevtoolsLog([req]);
+      global.isLightrider = true;
+      const record = NetworkRecorder.recordsFromLogs(devtoolsLog)[0];
+
+      expect(record).toMatchObject(req);
+      expect(record.lrStatistics).toStrictEqual(undefined);
+    });
+
+    it('does nothing if SSL time exceeds TCP time', () => {
+      const req = getRequest();
+      const sslHeader = req.responseHeaders[3];
+      expect(sslHeader.name).toStrictEqual(NetworkRequest.HEADER_SSL);
+      sslHeader.value = '5500';
+
+      const devtoolsLog = networkRecordsToDevtoolsLog([req]);
+
+      global.isLightrider = true;
+      const record = NetworkRecorder.recordsFromLogs(devtoolsLog)[0];
+
+      expect(record).toMatchObject(req);
+      expect(record.lrStatistics).toStrictEqual(undefined);
+    });
+
+    it('does not update lrStatistics when a timing header parses as NaN', () => {
+      const req = getRequest();
+      const tcpHeader = req.responseHeaders[1];
+      expect(tcpHeader.name).toStrictEqual(NetworkRequest.HEADER_TCP);
+      tcpHeader.value = 'Not a number';
+
+      const devtoolsLog = networkRecordsToDevtoolsLog([req]);
+      global.isLightrider = true;
+      const record = NetworkRecorder.recordsFromLogs(devtoolsLog)[0];
+
+      expect(record).toMatchObject(req);
+      expect(record.lrStatistics).toStrictEqual(undefined);
+    });
+  });
+});