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

core(network-recorder): use findNetworkQuietPeriods for networkIdle #4102

Merged
merged 3 commits into from
Jan 2, 2018
Merged

core(network-recorder): use findNetworkQuietPeriods for networkIdle #4102

Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
910ca79
core(NetworkRecorder): fix inconsistent timestamps
patrickhulce Dec 20, 2017
fea3676
feedback and cleanup
patrickhulce Dec 27, 2017
8c42f4d
reduce diff noise
patrickhulce Dec 27, 2017
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
47 changes: 3 additions & 44 deletions lighthouse-core/audits/consistently-interactive.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,7 @@

const Audit = require('./audit');
const Util = require('../report/v2/renderer/util.js');
const NetworkRecorder = require('../lib/network-recorder');
const TracingProcessor = require('../lib/traces/tracing-processor');

// Parameters (in ms) for log-normal CDF scoring. To see the curve:
Expand All @@ -16,7 +17,6 @@ const SCORING_MEDIAN = 10000;

const REQUIRED_QUIET_WINDOW = 5000;
const ALLOWED_CONCURRENT_REQUESTS = 2;
const IGNORED_NETWORK_SCHEMES = ['data', 'ws'];

/**
* @fileoverview This audit identifies the time the page is "consistently interactive".
Expand Down Expand Up @@ -49,49 +49,8 @@ class ConsistentlyInteractiveMetric extends Audit {
*/
static _findNetworkQuietPeriods(networkRecords, traceOfTab) {
const traceEndTsInMs = traceOfTab.timestamps.traceEnd / 1000;

// First collect the timestamps of when requests start and end
const timeBoundaries = [];
networkRecords.forEach(record => {
const scheme = record.parsedURL && record.parsedURL.scheme;
if (IGNORED_NETWORK_SCHEMES.includes(scheme)) {
return;
}

// convert the network record timestamp to ms to line-up with traceOfTab
timeBoundaries.push({time: record.startTime * 1000, isStart: true});
if (record.finished) {
timeBoundaries.push({time: record.endTime * 1000, isStart: false});
}
});

timeBoundaries.sort((a, b) => a.time - b.time);

let numInflightRequests = 0;
let quietPeriodStart = 0;
const quietPeriods = [];
timeBoundaries.forEach(boundary => {
if (boundary.isStart) {
// we've just started a new request. are we exiting a quiet period?
if (numInflightRequests === ALLOWED_CONCURRENT_REQUESTS) {
quietPeriods.push({start: quietPeriodStart, end: boundary.time});
}
numInflightRequests++;
} else {
numInflightRequests--;
// we've just completed a request. are we entering a quiet period?
if (numInflightRequests === ALLOWED_CONCURRENT_REQUESTS) {
quietPeriodStart = boundary.time;
}
}
});

// Check if the trace ended in a quiet period
if (numInflightRequests <= ALLOWED_CONCURRENT_REQUESTS) {
quietPeriods.push({start: quietPeriodStart, end: traceEndTsInMs});
}

return quietPeriods;
return NetworkRecorder.findNetworkQuietPeriods(networkRecords,
ALLOWED_CONCURRENT_REQUESTS, traceEndTsInMs);
}

/**
Expand Down
209 changes: 157 additions & 52 deletions lighthouse-core/lib/network-recorder.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -10,6 +10,8 @@ const NetworkManager = require('./web-inspector').NetworkManager;
const EventEmitter = require('events').EventEmitter;
const log = require('lighthouse-logger');

const IGNORED_NETWORK_SCHEMES = ['data', 'ws'];

class NetworkRecorder extends EventEmitter {
/**
* Creates an instance of NetworkRecorder.
Expand All @@ -24,10 +26,14 @@ class NetworkRecorder extends EventEmitter {
this.startedRequestCount = 0;
this.finishedRequestCount = 0;

this.networkManager.addEventListener(this.EventTypes.RequestStarted,
this.onRequestStarted.bind(this));
this.networkManager.addEventListener(this.EventTypes.RequestFinished,
this.onRequestFinished.bind(this));
this.networkManager.addEventListener(
this.EventTypes.RequestStarted,
this.onRequestStarted.bind(this)
);
this.networkManager.addEventListener(
this.EventTypes.RequestFinished,
this.onRequestFinished.bind(this)
);
}

get EventTypes() {
Expand All @@ -39,11 +45,82 @@ class NetworkRecorder extends EventEmitter {
}

isIdle() {
return this.activeRequestCount() === 0;
const quietPeriods = NetworkRecorder.findNetworkQuietPeriods(this._records, 0);
return quietPeriods.some(period => period.ongoing);
}

is2Idle() {
return this.activeRequestCount() <= 2;
const quietPeriods = NetworkRecorder.findNetworkQuietPeriods(this._records, 2);
return quietPeriods.some(period => period.ongoing);
}

_emitNetworkStatus() {
if (this.isIdle()) {
this.emit('networkidle');
} else {
this.emit('networkbusy');
}

if (this.is2Idle()) {
this.emit('network-2-idle');
} else {
this.emit('network-2-busy');
}
}

/**
* Finds all time periods where the number of inflight requests is less than or equal to the
* number of allowed concurrent requests.
* @param {!Array<!WebInspector.NetworkRequest>} networkRecords
* @param {number} allowedConcurrentRequests
* @param {number=} endTime
* @return {!Array<{start: number, end: number, ongoing: boolean|undefined}>}
Copy link
Member

Choose a reason for hiding this comment

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

naming bikeshed! is ongoing === "in flight"? if so i'd prefer that as a name, but i suspect there's a difference already..... :)

Copy link
Collaborator Author

@patrickhulce patrickhulce Dec 27, 2017 •
edited
Loading

Choose a reason for hiding this comment

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

yeah they're different haha :)

it's a flag to signal that this period had no end, basically that it's Infinity even though we mark it at endTime, suggestions welcome I just nuked it instead :)

*/
static findNetworkQuietPeriods(networkRecords, allowedConcurrentRequests, endTime = Infinity) {
// First collect the timestamps of when requests start and end
let timeBoundaries = [];
networkRecords.forEach(record => {
const scheme = record.parsedURL && record.parsedURL.scheme;
if (IGNORED_NETWORK_SCHEMES.includes(scheme)) {
return;
}

// convert the network record timestamp to ms
timeBoundaries.push({time: record.startTime * 1000, isStart: true});
if (record.finished) {
timeBoundaries.push({time: record.endTime * 1000, isStart: false});
}
});

timeBoundaries = timeBoundaries
.filter(boundary => boundary.time <= endTime)
.sort((a, b) => a.time - b.time);

let numInflightRequests = 0;
let quietPeriodStart = 0;
const quietPeriods = [];
timeBoundaries.forEach(boundary => {
if (boundary.isStart) {
// we've just started a new request. are we exiting a quiet period?
if (numInflightRequests === allowedConcurrentRequests) {
quietPeriods.push({start: quietPeriodStart, end: boundary.time});
}
numInflightRequests++;
} else {
numInflightRequests--;
// we've just completed a request. are we entering a quiet period?
if (numInflightRequests === allowedConcurrentRequests) {
quietPeriodStart = boundary.time;
}
}
});

// Check we ended in a quiet period
if (numInflightRequests <= allowedConcurrentRequests) {
quietPeriods.push({start: quietPeriodStart, end: endTime, ongoing: true});
}

return quietPeriods;
}

/**
Expand All @@ -53,22 +130,17 @@ class NetworkRecorder extends EventEmitter {
*/
onRequestStarted(request) {
this.startedRequestCount++;
request.data._observedNodeStartTime = Date.now();
Copy link
Member

Choose a reason for hiding this comment

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

what are we doing with these two timestamps?

Copy link
Collaborator Author

Choose a reason for hiding this comment

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

we actually aren't anymore but it was useful for debugging delta between trace and epoch timestamps :)

this._records.push(request.data);

const activeCount = this.activeRequestCount();
log.verbose('NetworkRecorder', `Request started. ${activeCount} requests in progress` +
` (${this.startedRequestCount} started and ${this.finishedRequestCount} finished).`);

// If only one request in progress, emit event that we've transitioned from
// idle to busy.
if (activeCount === 1) {
this.emit('networkbusy');
}
log.verbose(
Copy link
Member

Choose a reason for hiding this comment

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

do we want to keep these lines attached to activeRequestCount now? since our idling logic isn't related it seems better to drop the logs or have them log out the networkStatus

Copy link
Collaborator Author

Choose a reason for hiding this comment

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

yeah good point I just removed all other active request count tracking since we don't really need it, moved log to network status

'NetworkRecorder',
`Request started. ${activeCount} requests in progress` +
` (${this.startedRequestCount} started and ${this.finishedRequestCount} finished).`
);

// If exactly three requests in progress, we've transitioned from 2-idle to 2-busy.
if (activeCount === 3) {
this.emit('network-2-busy');
}
this._emitNetworkStatus();
}

/**
Expand All @@ -79,21 +151,17 @@ class NetworkRecorder extends EventEmitter {
*/
onRequestFinished(request) {
this.finishedRequestCount++;
request.data._observedNodeEndTime = Date.now();
this.emit('requestloaded', request.data);

const activeCount = this.activeRequestCount();
log.verbose('NetworkRecorder', `Request finished. ${activeCount} requests in progress` +
` (${this.startedRequestCount} started and ${this.finishedRequestCount} finished).`);
log.verbose(
'NetworkRecorder',
`Request finished. ${activeCount} requests in progress` +
` (${this.startedRequestCount} started and ${this.finishedRequestCount} finished).`
);

// If no requests in progress, emit event that we've transitioned from busy
// to idle.
if (this.isIdle()) {
this.emit('networkidle');
}

if (this.is2Idle()) {
this.emit('network-2-idle');
}
this._emitNetworkStatus();
}

// The below methods proxy network data into the DevTools SDK network layer.
Expand All @@ -102,10 +170,18 @@ class NetworkRecorder extends EventEmitter {

onRequestWillBeSent(data) {
// NOTE: data.timestamp -> time, data.type -> resourceType
this.networkManager._dispatcher.requestWillBeSent(data.requestId,
data.frameId, data.loaderId, data.documentURL, data.request,
data.timestamp, data.wallTime, data.initiator, data.redirectResponse,
data.type);
this.networkManager._dispatcher.requestWillBeSent(
data.requestId,
data.frameId,
data.loaderId,
data.documentURL,
data.request,
data.timestamp,
data.wallTime,
data.initiator,
data.redirectResponse,
data.type
);
}

onRequestServedFromCache(data) {
Expand All @@ -114,33 +190,54 @@ class NetworkRecorder extends EventEmitter {

onResponseReceived(data) {
// NOTE: data.timestamp -> time, data.type -> resourceType
this.networkManager._dispatcher.responseReceived(data.requestId,
data.frameId, data.loaderId, data.timestamp, data.type, data.response);
this.networkManager._dispatcher.responseReceived(
data.requestId,
data.frameId,
data.loaderId,
data.timestamp,
data.type,
data.response
);
}

onDataReceived(data) {
// NOTE: data.timestamp -> time
this.networkManager._dispatcher.dataReceived(data.requestId, data.timestamp,
data.dataLength, data.encodedDataLength);
this.networkManager._dispatcher.dataReceived(
data.requestId,
data.timestamp,
data.dataLength,
data.encodedDataLength
);
}

onLoadingFinished(data) {
// NOTE: data.timestamp -> finishTime
this.networkManager._dispatcher.loadingFinished(data.requestId,
data.timestamp, data.encodedDataLength);
this.networkManager._dispatcher.loadingFinished(
data.requestId,
data.timestamp,
data.encodedDataLength
);
}

onLoadingFailed(data) {
// NOTE: data.timestamp -> time, data.type -> resourceType,
// data.errorText -> localizedDescription
this.networkManager._dispatcher.loadingFailed(data.requestId,
data.timestamp, data.type, data.errorText, data.canceled,
data.blockedReason);
this.networkManager._dispatcher.loadingFailed(
data.requestId,
data.timestamp,
data.type,
data.errorText,
data.canceled,
data.blockedReason
);
}

onResourceChangedPriority(data) {
this.networkManager._dispatcher.resourceChangedPriority(data.requestId,
data.newPriority, data.timestamp);
this.networkManager._dispatcher.resourceChangedPriority(
data.requestId,
data.newPriority,
data.timestamp
);
}

/**
Expand All @@ -154,14 +251,22 @@ class NetworkRecorder extends EventEmitter {
}

switch (method) {
case 'Network.requestWillBeSent': return this.onRequestWillBeSent(params);
case 'Network.requestServedFromCache': return this.onRequestServedFromCache(params);
case 'Network.responseReceived': return this.onResponseReceived(params);
case 'Network.dataReceived': return this.onDataReceived(params);
case 'Network.loadingFinished': return this.onLoadingFinished(params);
case 'Network.loadingFailed': return this.onLoadingFailed(params);
case 'Network.resourceChangedPriority': return this.onResourceChangedPriority(params);
default: return;
case 'Network.requestWillBeSent':
return this.onRequestWillBeSent(params);
case 'Network.requestServedFromCache':
return this.onRequestServedFromCache(params);
case 'Network.responseReceived':
return this.onResponseReceived(params);
case 'Network.dataReceived':
return this.onDataReceived(params);
case 'Network.loadingFinished':
return this.onLoadingFinished(params);
case 'Network.loadingFailed':
return this.onLoadingFailed(params);
case 'Network.resourceChangedPriority':
return this.onResourceChangedPriority(params);
default:
return;
}
}

Expand Down
3 changes: 2 additions & 1 deletion lighthouse-core/test/audits/consistently-interactive-test.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -74,7 +74,7 @@ describe('Performance: consistently-interactive audit', () => {

const result = ConsistentlyInteractive.findOverlappingQuietPeriods(cpu, network, traceOfTab);
assert.deepEqual(result.cpuQuietPeriod, {start: 0, end: traceEnd / 1000});
assert.deepEqual(result.networkQuietPeriod, {start: 0, end: traceEnd / 1000});
assert.deepEqual(result.networkQuietPeriod, {start: 0, end: traceEnd / 1000, ongoing: true});
});

it('should throw when trace ended too soon after FMP', () => {
Expand Down Expand Up @@ -188,6 +188,7 @@ describe('Performance: consistently-interactive audit', () => {
assert.deepEqual(result.networkQuietPeriod, {
start: 32000 + navigationStart / 1000,
end: traceEnd / 1000,
ongoing: true,
});
assert.equal(result.cpuQuietPeriods.length, 3);
assert.equal(result.networkQuietPeriods.length, 2);
Expand Down
1 change: 1 addition & 0 deletions package.json
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -26,6 +26,7 @@
"smoke": "bash lighthouse-cli/test/smokehouse/run-all-tests.sh",
"coverage": "istanbul cover -x \"**/third_party/**\" _mocha -- $(find */test -name '*-test.js') --timeout 10000 --reporter progress --report lcovonly",
"coveralls": "yarn coverage && cat ./coverage/lcov.info | coveralls && ./node_modules/codecov/bin/codecov",
"debug": "node --inspect-brk ./lighthouse-cli/index.js",
"start": "node ./lighthouse-cli/index.js",
"test": "yarn lint --quiet && yarn unit && yarn type-check && yarn closure",
"unit-core": "bash lighthouse-core/scripts/run-mocha.sh --core",
Expand Down