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

Performance tests: add more detailed loading metrics #32237

Merged
merged 2 commits into from
Oct 12, 2021
Merged

Performance tests: add more detailed loading metrics #32237

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
7832d74
Performance tests: add more detailed loading metrics
ellatrix Aug 16, 2021
7ff2938
Fix extraction
ellatrix Oct 12, 2021
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
83 changes: 59 additions & 24 deletions bin/plugin/commands/performance.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -29,33 +29,43 @@ const config = require( '../config' );
/**
* @typedef WPRawPerformanceResults
*
* @property {number[]} load Load Time.
* @property {number[]} type Average type time.
* @property {number[]} focus Average block selection time.
* @property {number[]} inserterOpen Average time to open global inserter.
* @property {number[]} inserterSearch Average time to search the inserter.
* @property {number[]} inserterHover Average time to move mouse between two block item in the inserter.
* @property {number[]} serverResponse Represents the time the server takes to respond.
* @property {number[]} firstPaint Represents the time when the user agent first rendered after navigation.
* @property {number[]} domContentLoaded Represents the time immediately after the document's DOMContentLoaded event completes.
* @property {number[]} loaded Represents the time when the load event of the current document is completed.
* @property {number[]} firstContentfulPaint Represents the time when the browser first renders any text or media.
* @property {number[]} firstBlock Represents the time when Puppeteer first sees a block selector in the DOM.
* @property {number[]} type Average type time.
* @property {number[]} focus Average block selection time.
* @property {number[]} inserterOpen Average time to open global inserter.
* @property {number[]} inserterSearch Average time to search the inserter.
* @property {number[]} inserterHover Average time to move mouse between two block item in the inserter.
*/

/**
* @typedef WPPerformanceResults
*
* @property {number=} load Load Time.
* @property {number=} type Average type time.
* @property {number=} minType Minium type time.
* @property {number=} maxType Maximum type time.
* @property {number=} focus Average block selection time.
* @property {number=} minFocus Min block selection time.
* @property {number=} maxFocus Max block selection time.
* @property {number=} inserterOpen Average time to open global inserter.
* @property {number=} minInserterOpen Min time to open global inserter.
* @property {number=} maxInserterOpen Max time to open global inserter.
* @property {number=} inserterSearch Average time to open global inserter.
* @property {number=} minInserterSearch Min time to open global inserter.
* @property {number=} maxInserterSearch Max time to open global inserter.
* @property {number=} inserterHover Average time to move mouse between two block item in the inserter.
* @property {number=} minInserterHover Min time to move mouse between two block item in the inserter.
* @property {number=} maxInserterHover Max time to move mouse between two block item in the inserter.
* @property {number=} serverResponse Represents the time the server takes to respond.
* @property {number=} firstPaint Represents the time when the user agent first rendered after navigation.
* @property {number=} domContentLoaded Represents the time immediately after the document's DOMContentLoaded event completes.
* @property {number=} loaded Represents the time when the load event of the current document is completed.
* @property {number=} firstContentfulPaint Represents the time when the browser first renders any text or media.
* @property {number=} firstBlock Represents the time when Puppeteer first sees a block selector in the DOM.
* @property {number=} type Average type time.
* @property {number=} minType Minium type time.
* @property {number=} maxType Maximum type time.
* @property {number=} focus Average block selection time.
* @property {number=} minFocus Min block selection time.
* @property {number=} maxFocus Max block selection time.
* @property {number=} inserterOpen Average time to open global inserter.
* @property {number=} minInserterOpen Min time to open global inserter.
* @property {number=} maxInserterOpen Max time to open global inserter.
* @property {number=} inserterSearch Average time to open global inserter.
* @property {number=} minInserterSearch Min time to open global inserter.
* @property {number=} maxInserterSearch Max time to open global inserter.
* @property {number=} inserterHover Average time to move mouse between two block item in the inserter.
* @property {number=} minInserterHover Min time to move mouse between two block item in the inserter.
* @property {number=} maxInserterHover Max time to move mouse between two block item in the inserter.
*/

/**
Expand Down Expand Up @@ -105,7 +115,12 @@ function formatTime( number ) {
*/
function curateResults( results ) {
return {
load: average( results.load ),
serverResponse: average( results.serverResponse ),
firstPaint: average( results.firstPaint ),
domContentLoaded: average( results.domContentLoaded ),
loaded: average( results.loaded ),
Copy link
Contributor

Choose a reason for hiding this comment

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

Do you think we can restore the "load" metric (in addition to these). I know it's not perfect but the history of http://codehealth.vercel.app relies on it. We can update the dashboards to use the other tools later.

firstContentfulPaint: average( results.firstContentfulPaint ),
firstBlock: average( results.firstBlock ),
type: average( results.type ),
minType: Math.min( ...results.type ),
maxType: Math.max( ...results.type ),
Expand Down Expand Up @@ -314,7 +329,22 @@ async function runPerformanceTests( branches, options ) {
for ( const branch of branches ) {
const medians = mapValues(
{
load: rawResults.map( ( r ) => r[ branch ].load ),
serverResponse: rawResults.map(
( r ) => r[ branch ].serverResponse
),
firstPaint: rawResults.map(
( r ) => r[ branch ].firstPaint
),
domContentLoaded: rawResults.map(
( r ) => r[ branch ].domContentLoaded
),
loaded: rawResults.map( ( r ) => r[ branch ].loaded ),
firstContentfulPaint: rawResults.map(
( r ) => r[ branch ].firstContentfulPaint
),
firstBlock: rawResults.map(
( r ) => r[ branch ].firstBlock
),
type: rawResults.map( ( r ) => r[ branch ].type ),
minType: rawResults.map( ( r ) => r[ branch ].minType ),
maxType: rawResults.map( ( r ) => r[ branch ].maxType ),
Expand Down Expand Up @@ -359,6 +389,11 @@ async function runPerformanceTests( branches, options ) {

// 5- Formatting the results.
log( '\n>> 🎉 Results.\n' );

log(
'\nPlease note that client side metrics EXCLUDE the server response time.\n'
);

for ( const testSuite of testSuites ) {
log( `\n>> ${ testSuite }\n` );

Expand Down
2 changes: 1 addition & 1 deletion docs/explanations/architecture/performance.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -6,7 +6,7 @@ Performance is a key feature for editor applications and the Block editor is not

To ensure the block editor stays performant across releases and development, we monitor some key metrics using [performance testing](/docs/contributors/code/testing-overview.md#performance-testing).

**Loading Time:** The time it takes to load an editor page.
**Loading Time:** The time it takes to load an editor page. This includes time the server takes to respond, times to first paint, first contentful paint, DOM content load complete, load complete and first block render.
**Typing Time:** The time it takes for the browser to respond while typing on the editor.
**Block Selection Time:** The time it takes for the browser to respond after a user selects block. (Inserting a block is also equivalent to selecting a block. Monitoring the selection is sufficient to cover both metrics).

Expand Down
26 changes: 23 additions & 3 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 @@ -29,19 +29,39 @@ class PerformanceReporter {

const results = readFileSync( filepath, 'utf8' );
const {
load,
serverResponse,
firstPaint,
domContentLoaded,
loaded,
firstContentfulPaint,
firstBlock,
type,
focus,
inserterOpen,
inserterHover,
inserterSearch,
} = JSON.parse( results );

if ( load && load.length ) {
if ( serverResponse && serverResponse.length ) {
// eslint-disable-next-line no-console
console.log( `
${ title( 'Loading Time:' ) }
Average time to load: ${ success( round( average( load ) ) + 'ms' ) }` );
Average time to server response (subtracted from client side metrics): ${ success(
round( average( serverResponse ) ) + 'ms'
) }
Average time to first paint: ${ success(
round( average( firstPaint ) ) + 'ms'
) }
Average time to DOM content load: ${ success(
round( average( domContentLoaded ) ) + 'ms'
) }
Average time to load: ${ success( round( average( loaded ) ) + 'ms' ) }
Average time to first contentful paint: ${ success(
round( average( firstContentfulPaint ) ) + 'ms'
) }
Average time to first block: ${ success(
round( average( firstBlock ) ) + 'ms'
) }` );
}

if ( type && type.length ) {
Expand Down
25 changes: 22 additions & 3 deletions packages/e2e-tests/specs/performance/post-editor.test.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -26,13 +26,19 @@ import {
getClickEventDurations,
getHoverEventDurations,
getSelectionEventDurations,
getLoadingDurations,
} from './utils';

jest.setTimeout( 1000000 );

describe( 'Post Editor Performance', () => {
const results = {
load: [],
serverResponse: [],
firstPaint: [],
domContentLoaded: [],
loaded: [],
firstContentfulPaint: [],
firstBlock: [],
type: [],
focus: [],
inserterOpen: [],
Expand Down Expand Up @@ -90,10 +96,23 @@ describe( 'Post Editor Performance', () => {
// Measuring loading time
let i = 5;
while ( i-- ) {
const startTime = new Date();
await page.reload();
await page.waitForSelector( '.wp-block' );
results.load.push( new Date() - startTime );
const {
serverResponse,
firstPaint,
domContentLoaded,
loaded,
firstContentfulPaint,
firstBlock,
} = await getLoadingDurations();

results.serverResponse.push( serverResponse );
results.firstPaint.push( firstPaint );
results.domContentLoaded.push( domContentLoaded );
results.loaded.push( loaded );
results.firstContentfulPaint.push( firstContentfulPaint );
results.firstBlock.push( firstBlock );
}
} );

Expand Down
32 changes: 27 additions & 5 deletions packages/e2e-tests/specs/performance/site-editor.test.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -20,7 +20,12 @@ import {
* Internal dependencies
*/
import { siteEditor } from '../../experimental-features';
import { readFile, deleteFile, getTypingEventDurations } from './utils';
import {
readFile,
deleteFile,
getTypingEventDurations,
getLoadingDurations,
} from './utils';

jest.setTimeout( 1000000 );

Expand All @@ -39,7 +44,12 @@ describe( 'Site Editor Performance', () => {

it( 'Loading', async () => {
const results = {
load: [],
serverResponse: [],
firstPaint: [],
domContentLoaded: [],
loaded: [],
firstContentfulPaint: [],
firstBlock: [],
type: [],
focus: [],
inserterOpen: [],
Expand Down Expand Up @@ -78,14 +88,26 @@ describe( 'Site Editor Performance', () => {

// Measuring loading time
while ( i-- ) {
const startTime = new Date();
await page.reload();
await page.waitForSelector( '.edit-site-visual-editor', {
timeout: 120000,
} );
await canvas().waitForSelector( '.wp-block', { timeout: 120000 } );

results.load.push( new Date() - startTime );
const {
serverResponse,
firstPaint,
domContentLoaded,
loaded,
firstContentfulPaint,
firstBlock,
} = await getLoadingDurations();

results.serverResponse.push( serverResponse );
results.firstPaint.push( firstPaint );
results.domContentLoaded.push( domContentLoaded );
results.loaded.push( loaded );
results.firstContentfulPaint.push( firstContentfulPaint );
results.firstBlock.push( firstBlock );
}

// Measuring typing performance inside the post content.
Expand Down
32 changes: 32 additions & 0 deletions packages/e2e-tests/specs/performance/utils.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -81,3 +81,35 @@ export function getHoverEventDurations( trace ) {
getEventDurationsForType( trace, isMouseOutEvent ),
];
}

export async function getLoadingDurations() {
return await page.evaluate( () => {
const [
{
requestStart,
responseStart,
responseEnd,
domContentLoadedEventEnd,
loadEventEnd,
},
] = performance.getEntriesByType( 'navigation' );
const paintTimings = performance.getEntriesByType( 'paint' );
return {
// Server side metric.
serverResponse: responseStart - requestStart,
// For client side metrics, consider the end of the response (the
// browser receives the HTML) as the start time (0).
firstPaint:
paintTimings.find( ( { name } ) => name === 'first-paint' )
.startTime - responseEnd,
domContentLoaded: domContentLoadedEventEnd - responseEnd,
loaded: loadEventEnd - responseEnd,
firstContentfulPaint:
paintTimings.find(
( { name } ) => name === 'first-contentful-paint'
).startTime - responseEnd,
// This is evaluated right after Puppeteer found the block selector.
firstBlock: performance.now() - responseEnd,
};
} );
}