feat(engine): Implement performance timing

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
 

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`] = `
+"<ROOT>
+	<Foo (1)> - constructor
+	<Foo (1)> - connectedCallback
+	<Foo (1)> - renderedCallback
+	<Foo (1)> - disconnectedCallback"
+`;
+
+exports[`performance-timing captures component constructor 1`] = `"<ROOT>"`;
+
+exports[`performance-timing captures error callback 1`] = `
+"<ROOT>
+	<Foo (1)> - constructor
+	<Foo (1)> - render
+	<Foo (1)> - patch
+		<Bar (2)> - constructor
+		<Bar (2)> - render
+	<Foo (1)> - errorCallback"
+`;
+
+exports[`performance-timing captures nested component tree 1`] = `
+"<ROOT>
+	<Foo (1)> - constructor
+	<Foo (1)> - render
+	<Foo (1)> - patch
+		<Bar (2)> - constructor
+		<Bar (3)> - constructor
+		<Bar (2)> - render
+		<Bar (2)> - patch
+		<Bar (3)> - render
+		<Bar (3)> - patch"
+`;
+
+exports[`performance-timing recovers from errors 1`] = `
+"<ROOT>
+	<Foo (1)> - constructor
+	<Foo (1)> - render"
+`;
+
+exports[`performance-timing skips parent measurement when children component props change 1`] = `
+"<ROOT>
+	<Bar (2)> - render
+	<Bar (2)> - patch
+	<Baz (3)> - render
+	<Baz (3)> - patch"
+`;

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: '<ROOT>',
+            label: '<ROOT>',
+            children: [],
+            parent: null,
+        } as any;
+    }
+
+    injectPolyfill() {
+        const knownMarks = new Set<string>();
+        const knownMeasures = new Set<string>();
+
+        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()
+        ));
+    });
+});

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,13 +39,22 @@ 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 {
         component = new Ctor();
     } 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;