Skip to content

Commit

Permalink
feat(ssr): add perf timings (#5143)
Browse files Browse the repository at this point in the history 
* fix: fix it

* fix: fix tests and update names

---------

Co-authored-by: Will Harney <[email protected]>
  • Loading branch information
@nolanlawson @wjhsf
nolanlawson and wjhsf authored Jan 24, 2025
1 parent 8d3bc08 commit fa70380
Show file tree
Hide file tree
Showing 9 changed files with 183 additions and 77 deletions.
1 change: 1 addition & 0 deletions package.json
View file
Original file line number Diff line number Diff line change
Expand Up @@ -24,6 +24,7 @@
"test:ci": "vitest run --workspace vitest.workspace.mjs --coverage",
"test:karma": "nx test @lwc/integration-karma",
"test:karma:start": "nx start @lwc/integration-karma",
"test:hydration:start": "nx hydration:start @lwc/integration-karma",
"test:integration": "nx sauce @lwc/integration-tests",
"test:performance": "nx test @lwc/perf-benchmarks",
"test:performance:best": "nx test:best @lwc/perf-benchmarks",
Expand Down
12 changes: 12 additions & 0 deletions packages/@lwc/engine-core/src/framework/hydration.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -55,6 +55,13 @@ import { getScopeTokenClass } from './stylesheet';
import { renderComponent } from './component';
import { applyRefs } from './modules/refs';
import { unwrapIfNecessary } from './sanitized-html-content';
import {
logGlobalOperationEndWithVM,
logGlobalOperationStartWithVM,
logOperationEnd,
logOperationStart,
OperationId,
} from './profiler';
import type { Classes } from './hydration-utils';
import type {
VNodes,
Expand Down Expand Up @@ -85,6 +92,8 @@ let hasMismatch = false;
export function hydrateRoot(vm: VM) {
hasMismatch = false;

logGlobalOperationStartWithVM(OperationId.GlobalSsrHydrate, vm);

runConnectedCallback(vm);
hydrateVM(vm);

Expand All @@ -98,6 +107,7 @@ export function hydrateRoot(vm: VM) {
logHydrationWarning('Hydration completed with errors.');
}
}
logGlobalOperationEndWithVM(OperationId.GlobalSsrHydrate, vm);
}

function hydrateVM(vm: VM) {
Expand All @@ -111,7 +121,9 @@ function hydrateVM(vm: VM) {
renderRoot: parentNode,
renderer: { getFirstChild },
} = vm;
logOperationStart(OperationId.Patch, vm);
hydrateChildren(getFirstChild(parentNode), children, parentNode, vm, false);
logOperationEnd(OperationId.Patch, vm);
runRenderedCallback(vm);
}

Expand Down
30 changes: 19 additions & 11 deletions packages/@lwc/engine-core/src/framework/profiler.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -20,11 +20,15 @@ export const enum OperationId {
RenderedCallback = 4,
DisconnectedCallback = 5,
ErrorCallback = 6,
GlobalHydrate = 7,
GlobalRehydrate = 8,
GlobalRender = 7,
GlobalRerender = 8,
GlobalSsrHydrate = 9,
}

type GlobalOperationId = OperationId.GlobalHydrate | OperationId.GlobalRehydrate;
type GlobalOperationId =
| OperationId.GlobalRender
| OperationId.GlobalRerender
| OperationId.GlobalSsrHydrate;

const enum Phase {
Start = 0,
Expand Down Expand Up @@ -60,8 +64,9 @@ const operationIdNameMapping = [
'renderedCallback',
'disconnectedCallback',
'errorCallback',
'lwc-hydrate',
'lwc-rehydrate',
'lwc-render',
'lwc-rerender',
'lwc-ssr-hydrate',
] as const satisfies Record<OperationId, string>;

const operationTooltipMapping = [
Expand All @@ -79,10 +84,12 @@ const operationTooltipMapping = [
'component disconnectedCallback()',
// errorCallback
'component errorCallback()',
// lwc-hydrate
// lwc-render
'component first rendered',
// lwc-rehydrate
// lwc-rerender
'component re-rendered',
// lwc-ssr-hydrate
'component hydrated from server-rendered HTML',
] as const satisfies Record<OperationId, string>;

// Even if all the browser the engine supports implements the UserTiming API, we need to guard the measure APIs.
Expand Down Expand Up @@ -154,13 +161,14 @@ function getProperties(vm: VM<any, any>): [string, string][] {
function getColor(opId: OperationId): TrackColor {
// As of Sept 2024: primary (dark blue), secondary (light blue), tertiary (green)
switch (opId) {
// GlobalHydrate and Constructor tend to occur at the top level
case OperationId.GlobalHydrate:
// GlobalSsrHydrate, GlobalRender, and Constructor tend to occur at the top level
case OperationId.GlobalRender:
case OperationId.GlobalSsrHydrate:
case OperationId.Constructor:
return 'primary';
// GlobalRehydrate also occurs at the top level, but we want to use tertiary (green) because it's easier to
// GlobalRerender also occurs at the top level, but we want to use tertiary (green) because it's easier to
// distinguish from primary, and at a glance you should be able to easily tell re-renders from first renders.
case OperationId.GlobalRehydrate:
case OperationId.GlobalRerender:
return 'tertiary';
// Everything else (patch/render/callbacks)
default:
Expand Down
12 changes: 6 additions & 6 deletions packages/@lwc/engine-core/src/framework/vm.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -250,11 +250,11 @@ export function connectRootElement(elm: any) {

if (process.env.NODE_ENV !== 'production') {
// Flush any logs for this VM so that the initial properties from the constructor don't "count"
// in subsequent re-renders (lwc-rehydrate). Right now we're at the first render (lwc-hydrate).
// in subsequent re-renders (lwc-rerender). Right now we're at the first render (lwc-hydrate).
flushMutationLogsForVM(vm);
}

logGlobalOperationStartWithVM(OperationId.GlobalHydrate, vm);
logGlobalOperationStartWithVM(OperationId.GlobalRender, vm);

// Usually means moving the element from one place to another, which is observable via
// life-cycle hooks.
Expand All @@ -265,7 +265,7 @@ export function connectRootElement(elm: any) {
runConnectedCallback(vm);
rehydrate(vm);

logGlobalOperationEndWithVM(OperationId.GlobalHydrate, vm);
logGlobalOperationEndWithVM(OperationId.GlobalRender, vm);
}

export function disconnectRootElement(elm: any) {
Expand Down Expand Up @@ -656,7 +656,7 @@ function flushRehydrationQueue() {
const mutationLogs =
process.env.NODE_ENV === 'production' ? undefined : getAndFlushMutationLogs();

logGlobalOperationStart(OperationId.GlobalRehydrate);
logGlobalOperationStart(OperationId.GlobalRerender);

if (process.env.NODE_ENV !== 'production') {
assert.invariant(
Expand All @@ -679,15 +679,15 @@ function flushRehydrationQueue() {
ArrayUnshift.apply(rehydrateQueue, ArraySlice.call(vms, i + 1));
}
// we need to end the measure before throwing.
logGlobalOperationEnd(OperationId.GlobalRehydrate, mutationLogs);
logGlobalOperationEnd(OperationId.GlobalRerender, mutationLogs);

// re-throwing the original error will break the current tick, but since the next tick is
// already scheduled, it should continue patching the rest.
throw error;
}
}

logGlobalOperationEnd(OperationId.GlobalRehydrate, mutationLogs);
logGlobalOperationEnd(OperationId.GlobalRerender, mutationLogs);
}

export function runConnectedCallback(vm: VM) {
Expand Down
50 changes: 25 additions & 25 deletions packages/@lwc/integration-karma/test/misc/performance-timing/index.spec.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -20,8 +20,8 @@ function testConstructor(expected) {
});
}

function testRehydration(expected) {
it('component rehydration', () => {
function testRerender(expected) {
it('component rerender', () => {
const elm = createElement('x-child', { is: Child });
document.body.appendChild(elm);

Expand All @@ -43,8 +43,8 @@ function testNestedTree(expected) {
});
}

function testNestedRehydration(expected) {
it('captures component nested component tree rehydration', () => {
function testNestedRerender(expected) {
it('captures component nested component tree rerender', () => {
const elm = createElement('x-parent', { is: Parent });
document.body.appendChild(elm);

Expand Down Expand Up @@ -92,40 +92,40 @@ describe.runIf(isUserTimingSupported && process.env.NODE_ENV !== 'production')(
describe.runIf(process.env.NODE_ENV === 'production')('production mode', () => {
testConstructor([
{
label: /lwc-hydrate/,
label: /lwc-render/,
},
]);

testRehydration([
testRerender([
{
label: /lwc-rehydrate/,
label: /lwc-rerender/,
},
]);

testNestedTree([
{
label: /lwc-hydrate/,
label: /lwc-render/,
},
]);

testNestedRehydration([
testNestedRerender([
{
label: /lwc-rehydrate/,
label: /lwc-rerender/,
},
]);

testLifecycleHooks([
{
label: /lwc-hydrate/,
label: /lwc-render/,
},
]);

testNestedComponentCreation([
{
label: /lwc-hydrate/,
label: /lwc-render/,
children: [
{
label: /lwc-hydrate/,
label: /lwc-render/,
},
],
},
Expand All @@ -138,7 +138,7 @@ describe.runIf(isUserTimingSupported && process.env.NODE_ENV !== 'production')(
label: /<x-child> - constructor/,
},
{
label: /lwc-hydrate/,
label: /lwc-render/,
children: [
{
label: /<x-child> - render/,
Expand All @@ -150,9 +150,9 @@ describe.runIf(isUserTimingSupported && process.env.NODE_ENV !== 'production')(
},
]);

testRehydration([
testRerender([
{
label: /lwc-rehydrate/,
label: /lwc-rerender/,
children: [
{
label: /<x-child> - render/,
Expand All @@ -170,23 +170,23 @@ describe.runIf(isUserTimingSupported && process.env.NODE_ENV !== 'production')(
? [
{ label: '<x-parent> - constructor', children: [] },
{
label: 'lwc-hydrate',
label: 'lwc-render',
children: [
{ label: '<x-parent> - render', children: [] },
{
label: '<x-parent> - patch',
children: [
{ label: '<x-child> - constructor', children: [] },
{
label: 'lwc-hydrate',
label: 'lwc-render',
children: [
{ label: '<x-child> - render', children: [] },
{ label: '<x-child> - patch', children: [] },
],
},
{ label: '<x-child> - constructor', children: [] },
{
label: 'lwc-hydrate',
label: 'lwc-render',
children: [
{ label: '<x-child> - render', children: [] },
{ label: '<x-child> - patch', children: [] },
Expand All @@ -202,7 +202,7 @@ describe.runIf(isUserTimingSupported && process.env.NODE_ENV !== 'production')(
label: /<x-parent> - constructor/,
},
{
label: /lwc-hydrate/,
label: /lwc-render/,
children: [
{
label: /<x-parent> - render/,
Expand Down Expand Up @@ -235,9 +235,9 @@ describe.runIf(isUserTimingSupported && process.env.NODE_ENV !== 'production')(
]
);

testNestedRehydration([
testNestedRerender([
{
label: /lwc-rehydrate/,
label: /lwc-rerender/,
children: [
{
label: /<x-parent> - render/,
Expand Down Expand Up @@ -268,7 +268,7 @@ describe.runIf(isUserTimingSupported && process.env.NODE_ENV !== 'production')(
label: /<x-lifecycle> - constructor/,
},
{
label: /lwc-hydrate/,
label: /lwc-render/,
children: [
{
label: /<x-lifecycle> - connectedCallback/,
Expand All @@ -294,7 +294,7 @@ describe.runIf(isUserTimingSupported && process.env.NODE_ENV !== 'production')(
label: /<x-nested> - constructor/,
},
{
label: /lwc-hydrate/,
label: /lwc-render/,
children: [
{
label: /<x-nested> - render/,
Expand All @@ -306,7 +306,7 @@ describe.runIf(isUserTimingSupported && process.env.NODE_ENV !== 'production')(
label: /<x-child> - constructor/,
},
{
label: /lwc-hydrate/,
label: /lwc-render/,
children: [
{
label: /<x-child> - render/,
Expand Down
Loading

0 comments on commit fa70380

Please sign in to comment.