misc(logging): add hanging request logging in driver (#6297)

GoogleChrome · Oct 17, 2018 · 43c5ee1 · 43c5ee1
1 parent bf069a6
commit 43c5ee1
Show file tree

Hide file tree

Showing 2 changed files with 47 additions and 4 deletions.
diff --git a/lighthouse-core/gather/driver.js b/lighthouse-core/gather/driver.js
@@ -469,6 +469,7 @@ class Driver {
    * @private
    */
   _waitForNetworkIdle(networkQuietThresholdMs) {
+    let hasDCLFired = false;
     /** @type {NodeJS.Timer|undefined} */
     let idleTimeout;
     /** @type {(() => void)} */
@@ -499,19 +500,45 @@ class Driver {
       };
 
       const domContentLoadedListener = () => {
+        hasDCLFired = true;
         if (networkStatusMonitor.is2Idle()) {
           onIdle();
         } else {
           onBusy();
         }
       };
 
+      // We frequently need to debug why LH is still waiting for the page.
+      // This listener is added to all network events to verbosely log what URLs we're waiting on.
+      const logStatus = () => {
+        if (!hasDCLFired) {
+          log.verbose('Driver', 'Waiting on DomContentLoaded');
+          return;
+        }
+
+        const inflightRecords = networkStatusMonitor.getInflightRecords();
+        // If there are more than 20 inflight requests, load is still in full swing.
+        // Wait until it calms down a bit to be a little less spammy.
+        if (inflightRecords.length < 20) {
+          for (const record of inflightRecords) {
+            log.verbose('Driver', `Waiting on ${record.url.slice(0, 120)} to finish`);
+          }
+        }
+      };
+
+      networkStatusMonitor.on('requeststarted', logStatus);
+      networkStatusMonitor.on('requestloaded', logStatus);
+      networkStatusMonitor.on('network-2-busy', logStatus);
+
       this.once('Page.domContentEventFired', domContentLoadedListener);
       cancel = () => {
         idleTimeout && clearTimeout(idleTimeout);
         this.off('Page.domContentEventFired', domContentLoadedListener);
         networkStatusMonitor.removeListener('network-2-busy', onBusy);
         networkStatusMonitor.removeListener('network-2-idle', onIdle);
+        networkStatusMonitor.removeListener('requeststarted', logStatus);
+        networkStatusMonitor.removeListener('requestloaded', logStatus);
+        networkStatusMonitor.removeListener('network-2-busy', logStatus);
       };
     });
 

diff --git a/lighthouse-core/lib/network-recorder.js b/lighthouse-core/lib/network-recorder.js
@@ -11,7 +11,7 @@ const log = require('lighthouse-logger');
 
 const IGNORED_NETWORK_SCHEMES = ['data', 'ws'];
 
-/** @typedef {'requestloaded'|'network-2-idle'|'networkidle'|'networkbusy'|'network-2-busy'} NetworkRecorderEvent */
+/** @typedef {'requeststarted'|'requestloaded'|'network-2-idle'|'networkidle'|'networkbusy'|'network-2-busy'} NetworkRecorderEvent */
 
 class NetworkRecorder extends EventEmitter {
   /**
@@ -26,6 +26,13 @@ class NetworkRecorder extends EventEmitter {
     this._recordsById = new Map();
   }
 
+  /**
+   * @return {Array<LH.Artifacts.NetworkRequest>}
+   */
+  getInflightRecords() {
+    return this._records.filter(record => !NetworkRecorder.isNetworkRecordFinished(record));
+  }
+
   getRecords() {
     return Array.from(this._records);
   }
@@ -106,6 +113,16 @@ class NetworkRecorder extends EventEmitter {
     return !!(isFrameRootRequest && responseReceived && record.endTime);
   }
 
+  /**
+   * @param {LH.Artifacts.NetworkRequest} record
+   * @return {boolean}
+   */
+  static isNetworkRecordFinished(record) {
+    return record.finished ||
+      NetworkRecorder._isQUICAndFinished(record) ||
+      NetworkRecorder._isFrameRootRequestAndFinished(record);
+  }
+
   /**
    * Finds all time periods where the number of inflight requests is less than or equal to the
    * number of allowed concurrent requests.
@@ -126,9 +143,7 @@ class NetworkRecorder extends EventEmitter {
 
       // convert the network record timestamp to ms
       timeBoundaries.push({time: record.startTime * 1000, isStart: true});
-      if (record.finished ||
-          NetworkRecorder._isQUICAndFinished(record) ||
-          NetworkRecorder._isFrameRootRequestAndFinished(record)) {
+      if (NetworkRecorder.isNetworkRecordFinished(record)) {
         timeBoundaries.push({time: record.endTime * 1000, isStart: false});
       }
     });
@@ -175,6 +190,7 @@ class NetworkRecorder extends EventEmitter {
     this._records.push(request);
     this._recordsById.set(request.requestId, request);
 
+    this.emit('requeststarted', request);
     this._emitNetworkStatus();
   }