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

Improve performance testing #20802

Merged
merged 4 commits into from
Mar 12, 2020
Merged

Improve performance testing #20802

Show file tree
Hide file tree
Changes from 3 commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
2ccc4d6
Use browser timings for load events
sgomes Mar 11, 2020
64c9ef8
Measure typing perf using browser traces
sgomes Mar 11, 2020
66227a5
Apply rounding in performance reporter
sgomes Mar 12, 2020
7515486
Track perf across keydown, keypress, and keyup
sgomes Mar 12, 2020
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
15 changes: 10 additions & 5 deletions packages/e2e-tests/config/performance-reporter.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,6 +4,11 @@ function average( array ) {
return array.reduce( ( a, b ) => a + b ) / array.length;
}

function round( number, decimalPlaces = 2 ) {
const factor = Math.pow( 10, decimalPlaces );
return Math.round( number * factor ) / factor;
}

class PerformanceReporter {
onRunComplete() {
const path = __dirname + '/../specs/performance/results.json';
Expand All @@ -17,11 +22,11 @@ class PerformanceReporter {

// eslint-disable-next-line no-console
console.log( `
Average time to load: ${ average( load ) }ms
Average time to DOM content load: ${ average( domcontentloaded ) }ms
Average time to type character: ${ average( type ) }ms
Slowest time to type character: ${ Math.max( ...type ) }ms
Fastest time to type character: ${ Math.min( ...type ) }ms
Average time to load: ${ round( average( load ) ) }ms
Average time to DOM content load: ${ round( average( domcontentloaded ) ) }ms
Average time to type character: ${ round( average( type ) ) }ms
Slowest time to type character: ${ round( Math.max( ...type ) ) }ms
Fastest time to type character: ${ round( Math.min( ...type ) ) }ms
` );
}
}
Expand Down
57 changes: 45 additions & 12 deletions packages/e2e-tests/specs/performance/performance.test.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -2,7 +2,7 @@
* External dependencies
*/
import { join } from 'path';
import { existsSync, readFileSync, writeFileSync } from 'fs';
import { existsSync, readFileSync, unlinkSync, writeFileSync } from 'fs';

/**
* WordPress dependencies
Expand All @@ -19,6 +19,12 @@ function readFile( filePath ) {
: '';
}

function deleteFile( filePath ) {
if ( existsSync( filePath ) ) {
unlinkSync( filePath );
}
}

describe( 'Performance', () => {
it( '1000 paragraphs', async () => {
const html = readFile(
Expand Down Expand Up @@ -49,35 +55,62 @@ describe( 'Performance', () => {
};

let i = 1;
let startTime;

await page.on( 'load', () =>
results.load.push( new Date() - startTime )
);
await page.on( 'domcontentloaded', () =>
results.domcontentloaded.push( new Date() - startTime )
);

while ( i-- ) {
startTime = new Date();
await page.reload( { waitUntil: [ 'domcontentloaded', 'load' ] } );
const timings = JSON.parse(
await page.evaluate( () =>
JSON.stringify( window.performance.timing )
)
);
const {
navigationStart,
domContentLoadedEventEnd,
loadEventEnd,
} = timings;
results.load.push( loadEventEnd - navigationStart );
results.domcontentloaded.push(
domContentLoadedEventEnd - navigationStart
);
}

await insertBlock( 'Paragraph' );

i = 200;
const traceFile = __dirname + '/trace.json';

await page.tracing.start( {
path: traceFile,
screenshots: false,
categories: [ 'devtools.timeline' ],
} );

while ( i-- ) {
startTime = new Date();
await page.keyboard.type( 'x' );
results.type.push( new Date() - startTime );
}

await page.tracing.stop();

const traceResults = JSON.parse( readFile( traceFile ) );
const isKeypressEvent = ( item ) =>
item.cat === 'devtools.timeline' &&
item.name === 'EventDispatch' &&
item.dur &&
item.args &&
item.args.data &&
item.args.data.type === 'keypress';
Copy link
Contributor

Choose a reason for hiding this comment

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

I'm not sure that's enough, I know previously keydown was also a problem.

Capture d’écran 2020-03-12 à 11 16 51 AM

You can see in the screenshot that there's aa keydown and then a keypress. Both of these are gathered in a "Task". and after that there are "follow up async tasks).

Ideally, if we can meansure the three segments it would be great, I believe the most important thing is the sync behavior (keydown + keypress). A format like that might be best keydown+keypress ( follow-ups: xx ) eg: 25ms ( follow-ups: 40ms )

What do you think?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I don't think it will make much difference, since I expect the absolute values not to be as important as their evolution over time, and the keydown/keyup events don't seem to have a great deal of variability.

That said, for completeness sake, I added a commit where I calculate the sum of the three event durations for a total value for each virtual key press.

Copy link
Contributor Author

@sgomes sgomes Mar 12, 2020 •
edited
Loading

Choose a reason for hiding this comment

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

I just noticed that you'd suggested separating out the values of the different event types in the output. Do you think that's necessary, or is the sum enough?

Copy link
Contributor

Choose a reason for hiding this comment

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

That sum is enough for the first part (the synchronous work). I don't know though if it's possible somehow to compute the time spent in the asynchronous work. In the trace it's shown as separate from keydown, keyup, keypress event, it's shown as multiple small tasks.

I'd say, getting that value is less important but if we manage to get it, we shouldn't sum it with the rest.

does that make sense?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I'd argue that whether or not the async value is important depends on what you're trying to measure. If you're trying to measure input latency as perceived by the user, then the async value isn't important, as that work happens after the screen has updated and probably does not limit interactivity in any way, as the tasks are very short.

In any case, I suspect it would be extremely difficult to get that value, as there wouldn't be a good way of correlating the async work with the key events that triggered it.


results.type = traceResults.traceEvents
.filter( isKeypressEvent )
.map( ( item ) => item.dur / 1000 );

writeFileSync(
__dirname + '/results.json',
JSON.stringify( results, null, 2 )
);

deleteFile( traceFile );

expect( true ).toBe( true );
} );
} );