diff --git a/docs/proposals/0102-performance-timing.md b/docs/proposals/0102-performance-timing.md index ba9c59c5cf..e0bfd5806b 100644 --- a/docs/proposals/0102-performance-timing.md +++ b/docs/proposals/0102-performance-timing.md @@ -4,7 +4,7 @@ - Start Date: 2018-02-05 - RFC PR: https://github.com/salesforce/lwc/pull/61 -- Issue: TBD +- Implementation PR: https://github.com/salesforce/lwc/pull/98 ## Goals diff --git a/packages/lwc-engine/src/framework/__tests__/__snapshots__/performance-timing-test.ts.snap b/packages/lwc-engine/src/framework/__tests__/__snapshots__/performance-timing-test.ts.snap new file mode 100644 index 0000000000..66cb29b1bc --- /dev/null +++ b/packages/lwc-engine/src/framework/__tests__/__snapshots__/performance-timing-test.ts.snap @@ -0,0 +1,48 @@ +// Jest Snapshot v1, https://goo.gl/fbAQLP + +exports[`performance-timing captures all lifecycle hooks 1`] = ` +" + - constructor + - connectedCallback + - renderedCallback + - disconnectedCallback" +`; + +exports[`performance-timing captures component constructor 1`] = `""`; + +exports[`performance-timing captures error callback 1`] = ` +" + - constructor + - render + - patch + - constructor + - render + - errorCallback" +`; + +exports[`performance-timing captures nested component tree 1`] = ` +" + - constructor + - render + - patch + - constructor + - constructor + - render + - patch + - render + - patch" +`; + +exports[`performance-timing recovers from errors 1`] = ` +" + - constructor + - render" +`; + +exports[`performance-timing skips parent measurement when children component props change 1`] = ` +" + - render + - patch + - render + - patch" +`; diff --git a/packages/lwc-engine/src/framework/__tests__/performance-timing-test.ts b/packages/lwc-engine/src/framework/__tests__/performance-timing-test.ts new file mode 100644 index 0000000000..eb22ea03f8 --- /dev/null +++ b/packages/lwc-engine/src/framework/__tests__/performance-timing-test.ts @@ -0,0 +1,261 @@ +declare var global: Global; + +interface Global { + performance: UserTiming; +} + +interface UserTiming { + mark(name: string): void; + measure(label: string, name: string): void; + clearMarks(name: string): void; + clearMeasures(label: string): void; +} + +interface Mark { + name: string; + label: null | string; + children: Mark[]; + parent: Mark; +} + +class FlameChart { + activeMark: Mark; + + constructor() { + this.reset(); + } + + reset() { + this.activeMark = { + name: '', + label: '', + children: [], + parent: null, + } as any; + } + + injectPolyfill() { + const knownMarks = new Set(); + const knownMeasures = new Set(); + + global.performance = { + mark: (name: string) => { + const mark: Mark = { + name, + label: null, + children: [], + parent: this.activeMark, + }; + + if (this.activeMark) { + this.activeMark.children.push(mark); + } + + this.activeMark = mark; + }, + + measure: (label: string, mark: string) => { + if (!this.activeMark) { + throw new Error(`Unexpected measure ${label}, no matching mark for ${mark}`); + } else if (this.activeMark.name !== mark) { + throw new Error(`Unexpected measure ${label}, expected ${this.activeMark.name} received ${mark}`); + } + + this.activeMark.label = label; + this.activeMark = this.activeMark.parent; + }, + + // tslint:disable-next-line:no-empty + clearMarks(name: string): void {}, + + // tslint:disable-next-line:no-empty + clearMeasures(name: string): void {}, + }; + } + + buildFlamechart( + mark: Mark = this.activeMark, + indent: number = 0 + ): string { + return [ + '\t'.repeat(indent) + mark.label, + ...mark.children.map(c => this.buildFlamechart(c, indent + 1)), + ].join('\n'); + } + + toString() { + return this.buildFlamechart(); + } +} + +describe('performance-timing', () => { + let engine: any; + let flamechart: FlameChart; + + beforeEach(() => { + // Make sure to reset module cache between each test to ensure to reset the uid. + jest.resetModules(); + engine = require('../main.ts'); + + flamechart = new FlameChart(); + flamechart.injectPolyfill(); + }); + + it('captures component constructor', () => { + class Foo extends engine.Element {} + + const elm = engine.createElement('x-foo', { is: Foo }); + document.body.appendChild(elm); + + expect(flamechart.toString()).toMatchSnapshot(); + }); + + it('captures all lifecycle hooks', () => { + class Foo extends engine.Element { + // tslint:disable-next-line:no-empty + connectedCallback() {} + + // tslint:disable-next-line:no-empty + renderedCallback() {} + + // tslint:disable-next-line:no-empty + disconnectedCallback() {} + } + + const elm = engine.createElement('x-foo', { is: Foo }); + document.body.appendChild(elm); + document.body.removeChild(elm); + + expect(flamechart.toString()).toMatchSnapshot(); + }); + + it('captures nested component tree', () => { + class Bar extends engine.Element { + render() { + return ($api: any) => [ + $api.h('span', { key: 0 }, []) + ]; + } + } + + class Foo extends engine.Element { + render() { + return ($api: any) => [ + $api.c('x-bar', Bar, {}), + $api.c('x-bar', Bar, {}), + ]; + } + } + + const elm = engine.createElement('x-foo', { is: Foo }); + document.body.appendChild(elm); + + expect(flamechart.toString()).toMatchSnapshot(); + }); + + it('recovers from errors', () => { + class Foo extends engine.Element { + render() { + throw new Error('Nooo!'); + } + } + + const elm = engine.createElement('x-foo', { is: Foo }); + + try { + document.body.appendChild(elm); + } catch (err) { + expect(err.message).toBe('Nooo!'); + } + + expect(flamechart.toString()).toMatchSnapshot(); + }); + + it('captures error callback', () => { + class Bar extends engine.Element { + render() { + throw new Error('Noo!'); + } + } + + class Foo extends engine.Element { + render() { + return ($api: any) => [ + $api.c('x-bar', Bar, {}), + ]; + } + + // tslint:disable-next-line:no-empty + errorCallback() {} + } + + const elm = engine.createElement('x-foo', { is: Foo }); + document.body.appendChild(elm); + + expect(flamechart.toString()).toMatchSnapshot(); + }); + + it('skips parent measurement when children component props change', () => { + let bar: Bar; + let baz: Baz; + + class Bar extends engine.Element { + state: boolean = false; + + connectedCallback() { + bar = this; + } + + render() { + return ($api: any, $cmp: any) => [ + $api.t($cmp.state), + ]; + } + + static track = { + state: { config: 0 } + }; + } + + class Baz extends engine.Element { + state: boolean = false; + + connectedCallback() { + baz = this; + } + + render() { + return ($api: any, $cmp: any) => [ + $api.t($cmp.state), + ]; + } + + static track = { + state: { config: 0 } + }; + } + + class Foo extends engine.Element { + render() { + return ($api: any) => { + return [ + $api.c('x-bar', Bar, {}), + $api.c('x-baz', Baz, {}), + ]; + }; + } + } + + const elm = engine.createElement('x-foo', { is: Foo }); + document.body.appendChild(elm); + + flamechart.reset(); + + bar.state = true; + baz.state = true; + + return Promise.resolve().then(() => ( + expect(flamechart.toString()).toMatchSnapshot() + )); + }); +}); diff --git a/packages/lwc-engine/src/framework/invoker.ts b/packages/lwc-engine/src/framework/invoker.ts index 9bf4aebd4d..1d387c9792 100644 --- a/packages/lwc-engine/src/framework/invoker.ts +++ b/packages/lwc-engine/src/framework/invoker.ts @@ -8,6 +8,7 @@ import { isUndefined, isFunction } from "./language"; import { getComponentStack, VM } from "./vm"; import { ComponentConstructor, Component } from "./component"; import { VNodes } from "../3rdparty/snabbdom/types"; +import { startMeasure, endMeasure } from "./performance-timing"; export let isRendering: boolean = false; export let vmBeingRendered: VM|null = null; @@ -38,6 +39,11 @@ export function invokeComponentConstructor(vm: VM, Ctor: ComponentConstructor): const { context } = vm; const ctx = currentContext; establishContext(context); + + if (process.env.NODE_ENV !== 'production') { + startMeasure(vm, 'constructor'); + } + let component; let error; try { @@ -45,6 +51,10 @@ export function invokeComponentConstructor(vm: VM, Ctor: ComponentConstructor): } catch (e) { error = Object(e); } finally { + if (process.env.NODE_ENV !== 'production') { + endMeasure(vm, 'constructor'); + } + establishContext(ctx); if (error) { error.wcStack = getComponentStack(vm); @@ -67,6 +77,11 @@ export function invokeComponentRenderMethod(vm: VM): VNodes { vmBeingRendered = vm; let result; let error; + + if (process.env.NODE_ENV !== 'production') { + startMeasure(vm, 'render'); + } + try { const html = render.call(component); if (isFunction(html)) { @@ -79,6 +94,11 @@ export function invokeComponentRenderMethod(vm: VM): VNodes { } catch (e) { error = Object(e); } finally { + + if (process.env.NODE_ENV !== 'production') { + endMeasure(vm, 'render'); + } + establishContext(ctx); isRendering = isRenderingInception; vmBeingRendered = vmBeingRenderedInception; diff --git a/packages/lwc-engine/src/framework/performance-timing.ts b/packages/lwc-engine/src/framework/performance-timing.ts new file mode 100644 index 0000000000..0ba11c022e --- /dev/null +++ b/packages/lwc-engine/src/framework/performance-timing.ts @@ -0,0 +1,46 @@ +import { VM } from './vm'; + +export type MeasurementPhase = + | 'constructor' + | 'render' + | 'patch' + | 'connectedCallback' + | 'disconnectedCallback' + | 'renderedCallback' + | 'errorCallback'; + +// Even if all the browser the engine supports implements the UserTiming API, we need to guard the measure APIs. +// JSDom (used in Jest) for example doesn't implement the UserTiming APIs +const isUserTimingSupported: boolean = + typeof performance !== 'undefined' && + typeof performance.mark === 'function' && + typeof performance.clearMarks === 'function' && + typeof performance.measure === 'function' && + typeof performance.clearMeasures === 'function'; + +function getMarkName(vm: VM, phase: MeasurementPhase): string { + return `<${vm.def.name} (${vm.uid})> - ${phase}`; +} + +export function startMeasure(vm: VM, phase: MeasurementPhase) { + if (!isUserTimingSupported) { + return; + } + + const name = getMarkName(vm, phase); + performance.mark(name); +} + +export function endMeasure(vm: VM, phase: MeasurementPhase) { + if (!isUserTimingSupported) { + return; + } + + const name = getMarkName(vm, phase); + performance.measure(name, name); + + // Clear the created marks and measure to avoid filling the performance entries buffer. + // Note: Even if the entries get deleted, existing PerformanceObservers preserve a copy of those entries. + performance.clearMarks(name); + performance.clearMeasures(name); +} diff --git a/packages/lwc-engine/src/framework/vm.ts b/packages/lwc-engine/src/framework/vm.ts index d461b2fcd8..f1c91f154a 100644 --- a/packages/lwc-engine/src/framework/vm.ts +++ b/packages/lwc-engine/src/framework/vm.ts @@ -15,6 +15,7 @@ import { Membrane } from "./membrane"; import { Component } from "./component"; import { Context } from "./context"; import { ShadowRoot } from "./root"; +import { startMeasure, endMeasure } from "./performance-timing"; export interface HashTable { [key: string]: T; @@ -71,7 +72,15 @@ export function addInsertionIndex(vm: VM) { } const { connectedCallback } = vm.def; if (!isUndefined(connectedCallback)) { + if (process.env.NODE_ENV !== 'production') { + startMeasure(vm, 'connectedCallback'); + } + invokeComponentCallback(vm, connectedCallback); + + if (process.env.NODE_ENV !== 'production') { + endMeasure(vm, 'connectedCallback'); + } } } @@ -87,7 +96,15 @@ export function removeInsertionIndex(vm: VM) { } const { disconnectedCallback } = vm.def; if (!isUndefined(disconnectedCallback)) { + if (process.env.NODE_ENV !== 'production') { + startMeasure(vm, 'disconnectedCallback'); + } + invokeComponentCallback(vm, disconnectedCallback); + + if (process.env.NODE_ENV !== 'production') { + endMeasure(vm, 'disconnectedCallback'); + } } } @@ -206,6 +223,11 @@ function patchShadowRoot(vm: VM, children: VNodes) { return; // nothing to do here } let error; + + if (process.env.NODE_ENV !== 'production') { + startMeasure(vm, 'patch'); + } + try { // patch function mutates vnodes by adding the element reference, // however, if patching fails it contains partial changes. @@ -213,6 +235,10 @@ function patchShadowRoot(vm: VM, children: VNodes) { } catch (e) { error = Object(e); } finally { + if (process.env.NODE_ENV !== 'production') { + endMeasure(vm, 'patch'); + } + if (!isUndefined(error)) { const errorBoundaryVm = getErrorBoundaryVMFromOwnElement(vm); if (isUndefined(errorBoundaryVm)) { @@ -239,7 +265,15 @@ function processPostPatchCallbacks(vm: VM) { } const { renderedCallback } = vm.def; if (!isUndefined(renderedCallback)) { + if (process.env.NODE_ENV !== 'production') { + startMeasure(vm, 'renderedCallback'); + } + invokeComponentCallback(vm, renderedCallback); + + if (process.env.NODE_ENV !== 'production') { + endMeasure(vm, 'renderedCallback'); + } } } @@ -284,8 +318,17 @@ function recoverFromLifecyleError(failedVm: VM, errorBoundaryVm: VM, error: any) } resetShadowRoot(failedVm); // remove offenders const { errorCallback } = errorBoundaryVm.def; + + if (process.env.NODE_ENV !== 'production') { + startMeasure(errorBoundaryVm, 'errorCallback'); + } + // error boundaries must have an ErrorCallback invokeComponentCallback(errorBoundaryVm, errorCallback as ErrorCallback, [error, error.wcStack]); + + if (process.env.NODE_ENV !== 'production') { + endMeasure(errorBoundaryVm, 'errorCallback'); + } } export function resetShadowRoot(vm: VM) {