Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Merged
merged 3 commits into from
Oct 17, 2018
Merged

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

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
83a5c52
core(driver): add hanging request logging
patrickhulce Oct 16, 2018
7aaa709
Merge branch 'master' into log_hanging_reqs
patrickhulce Oct 17, 2018
e5e566b
add comment
patrickhulce Oct 17, 2018
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
27 changes: 27 additions & 0 deletions lighthouse-core/gather/driver.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -469,6 +469,7 @@ class Driver {
* @private
*/
_waitForNetworkIdle(networkQuietThresholdMs) {
let hasDCLFired = false;
/** @type {NodeJS.Timer|undefined} */
let idleTimeout;
/** @type {(() => void)} */
Expand Down Expand Up @@ -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();
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

i've been a little concerned about the length of our NetworkRecord callbacks. I was seeing 1+ms for some while doing some OYB profiling a while back, and there are a lot of callbacks.

Can we detect whether or not we're in verbose mode before doing any of this work? Short of settings in here or changing lighthouse-logger again, I'm not sure there is, sadly.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

+1 to this and another lighthouse-logger change, I want one level in between verbose and default (debug or info perhaps?) that doesn't contain every protocol message

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good call. Yah not showing events from Network domain would be my number one request.

// 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`);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

we should probably remove all the network busy, network semi-quiet logs in NetworkRecorder. At least I've never found them useful, and this will give equivalent info (except fully quiet, I guess)

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

FWIW I still found them helpful to track exactly when the idle timeout would be started and cancelled (and to break up the repeated sets of URLs when filtering out the '<= event:verbose' events which are the real crazy chatty ones!), but agreed the wall of them every time we call recordsFromLogs is super annoying.

}
}
};

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);
};
});

Expand Down
24 changes: 20 additions & 4 deletions lighthouse-core/lib/network-recorder.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
/**
Expand All @@ -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);
}
Expand Down Expand Up @@ -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.
Expand All @@ -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});
}
});
Expand Down Expand Up @@ -175,6 +190,7 @@ class NetworkRecorder extends EventEmitter {
this._records.push(request);
this._recordsById.set(request.requestId, request);

this.emit('requeststarted', request);
this._emitNetworkStatus();
}

Expand Down