feat(engine): performance marks #756

jodarove · 2018-10-22T18:45:26Z

We need a way of measuring the time that lwc code is running in prod.

With that in mind, this pr is to add 3 global markers:

lwc-init which is the measure time creating a lwc root component.
lwc-hydrate to measure how long took hydrating all dependencies of the root component.
lwc-rehydrate to measure how long took to flush all scheduled rehydrations.

Does this PR introduce a breaking change?

Yes
No

jodarove · 2018-10-22T18:48:16Z

packages/lwc-engine/src/framework/vm.ts

-                    // pieces of the queue are still pending to be rehydrated, those should have priority
-                    if (rehydrateQueue.length === 0) {
-                        addCallbackToNextTick(flushRehydrationQueue);
+    startGlobalMeasure('rehydrate');


the only actual change here was to wrap everything in a try/finally block:

// ... js code ...

to:

startGobalMeasure('rehydrate'); try { // ... js code ... } finally { endGlobalMeasure('rehydrate'); }

I would rather we wrapped the code calling flushRehydrationQueue with a try...catch if we must. This function is already big enough as is so keeping the measures outside would be great if we can. Also, do these measurements need to run in production? Having an extra try...catch will be a perf hit

yes, definitely not a try catch here, it will break error boundaries, and other stuff that depend on this block throwing an error. @davidturissini suggestion is tricky because it is the next tick.

I believe there is room here to add the measurements in this method, but without adding the try/catch, just rely on the existing one.

I'm also fine with this name btw.

i agree with @caridy in both things: (1) the try/finally outside is tricky cause i in the nextTickQueue but (2) we would need to make the measure before throw inside the catch https://github.com/salesforce/lwc/blob/master/packages/lwc-engine/src/framework/vm.ts#L335

going with (2) since solves all the issues.

caridy

I don't agree with this measurements. Honestly, I don't understand how these measurements are useful to anyone. On top of that, there is no clear picture here on which elements do you want to measure.

diervo · 2018-10-23T00:51:28Z

@caridy I suggest you ask for context before stating that you don't understand anything.

This is fundamentally to understand when LWC is doing work (both creating and rendering).
It is both critical and necessary for perf that they can disambiguate between idle time and LWC time.

Not sure about the implementation but the abstractions and where to put the marks have been reviewed by Pierre and I.

davidturissini

Couple changes

davidturissini · 2018-10-23T01:42:52Z

packages/lwc-engine/src/framework/performance-timing.ts

@@ -9,6 +9,11 @@ type MeasurementPhase =
    | 'renderedCallback'
    | 'errorCallback';

+type GlobalMeasurementPhase =


Make this an enum

davidturissini · 2018-10-23T01:46:24Z

packages/lwc-engine/src/framework/vm.ts

-                    // pieces of the queue are still pending to be rehydrated, those should have priority
-                    if (rehydrateQueue.length === 0) {
-                        addCallbackToNextTick(flushRehydrationQueue);
+    startGlobalMeasure('rehydrate');


I would rather we wrapped the code calling flushRehydrationQueue with a try...catch if we must. This function is already big enough as is so keeping the measures outside would be great if we can. Also, do these measurements need to run in production? Having an extra try...catch will be a perf hit

caridy · 2018-10-23T01:53:03Z

I had a chat with Diego about this, will add more comments now that I have more context, but I continue to ask for more information as part of the PR, the description of the PR says little, don't link to any doc, and doesn't explain the why.

caridy · 2018-10-23T01:55:42Z

packages/lwc-engine/src/framework/upgrade.ts

@@ -8,6 +8,7 @@ import { isNativeShadowRootAvailable } from "./dom-api";
 import { patchCustomElementProto } from "./patch";
 import { getComponentDef, setElementProto } from "./def";
 import { patchCustomElementWithRestrictions } from "./restrictions";
+import { endGlobalMeasure, startGlobalMeasure } from "./performance-timing";


upgrade.ts and wc.ts are analog. In aura, we always go thru upgrade.ts, but for web components, we go thru wc.ts, probably worth to keep them analog by implementing the same measurements.

caridy · 2018-10-23T02:00:18Z

packages/lwc-engine/src/framework/upgrade.ts

@@ -59,6 +60,7 @@ assign(Node.prototype, {
 * then it throws a TypeError.
 */
 export function createElement(sel: string, options: any = {}): HTMLElement {
+    startGlobalMeasure('createElement');


I will recommend to change the name of this because createElement as a very specific meaning. I will recommend to keep it shorted as init which includes the createElement + the initialization of the associated components, and everything in between.

So, in the case of wc.ts, ths measurement are a little bit different, but still having an init phase is good enough.

caridy · 2018-10-23T02:08:41Z

packages/lwc-engine/src/framework/upgrade.ts

@@ -94,14 +96,17 @@ export function createElement(sel: string, options: any = {}): HTMLElement {
    createVM(sel, element, Ctor, { mode, fallback, isRoot: true });
    // Handle insertion and removal from the DOM manually
    setInternalField(element, ConnectingSlot, () => {
+        startGlobalMeasure('connectingRootElement');


I will recommend renaming this as well because the connection aspect is just an implementation detail. I will call this hydrate

Adds performance marks for: - createElement - render/patch generated from connecting a root element. - flush rehydrate queue.

- enum - init instead of createElement - hydrate instead of connectedRootElement.

entry point.

jodarove · 2018-10-24T21:13:00Z

markers with the comments:

tariqrafique · 2018-10-24T21:25:16Z

markers with the comments:

Is that from running in prod mode ?

jodarove · 2018-10-24T21:38:01Z

@tariq-sfdc this pr is intended to add these 3 markers in prod: lwc-init, lwc-hydrate and lwc-rehydrate (not the individual ones)

tariqrafique · 2018-10-24T21:51:44Z

@jodarove that's what I mean. What does the timeline look like when you run in PROD mode ?

jodarove · 2018-10-24T22:22:40Z

here is a chrome profile of PROD @tariq-sfdc

attach-event-connected-callback-profile.json.zip

tariqrafique · 2018-10-24T22:30:37Z

profile looks good. Thanks @jodarove

function calls: before in each call to start/endGlobalMeasure the condition !isUserTimingSupported was being executed. But isUserTimingSupported is calculated once when importing the module. Now when isUserTimingSupported is calculated if is true we export the start/endGlobalMeasure without the condition, and if ! isUserTimingSupported, we export a noop function as start/endGlobalMeasure

caridy · 2018-10-25T00:26:12Z

packages/lwc-engine/src/framework/wc.ts


 export function buildCustomElementConstructor(Ctor: ComponentConstructor, options?: ShadowRootInit): HTMLElementConstructor {
+    startGlobalMeasure(GlobalMeasurementPhase.INIT);


no, this goes into the constructor, first line before super() call

caridy · 2018-10-25T00:27:01Z

packages/lwc-engine/src/framework/wc.ts

@@ -70,4 +74,7 @@ export function buildCustomElementConstructor(Ctor: ComponentConstructor, option
        // the reflection from attributes to props via attributeChangedCallback.
        static observedAttributes = ArrayMap.call(getOwnPropertyNames(props), (propName) => props[propName].attr);
    };
+
+    endGlobalMeasure(GlobalMeasurementPhase.INIT);


this goes inside the constructor, last line.

caridy

wrong placement in wc.ts

caridy · 2018-10-25T00:36:09Z

packages/lwc-engine/src/framework/performance-timing.ts

@@ -9,6 +9,12 @@ type MeasurementPhase =
    | 'renderedCallback'
    | 'errorCallback';

+export enum GlobalMeasurementPhase {
+    REHYDRATE = 'rehydrate',


still think we need better names :) but I don't know... talk to @kevinv11n

also @Gr8Gatsby

A couple ideas:

DiffAndPatch

Patch

Render

The markers were added in the incorrect place when building a wc.

salesforce-best-lwc-internal · 2018-10-25T17:26:12Z

Benchmark results

Base commit: 00a13cc | Target commit: d8a1a27

lwc-engine-benchmark

table-append-1k	metric	base(`00a13cc`)	target(`d8a1a27`)	trend
benchmark-table/append/1k	duration	156.25 (±4.80 ms)	149.50 (±3.55 ms)	-6.8ms (4.3%) 👍

table-clear-1k	metric	base(`00a13cc`)	target(`d8a1a27`)	trend
benchmark-table/clear/1k	duration	6.60 (±0.30 ms)	6.00 (±0.30 ms)	-0.6ms (9.1%) 👍

table-create-10k	metric	base(`00a13cc`)	target(`d8a1a27`)	trend
benchmark-table/create/10k	duration	879.85 (±5.55 ms)	867.95 (±5.60 ms)	-11.9ms (1.4%) 👍

table-create-1k	metric	base(`00a13cc`)	target(`d8a1a27`)	trend
benchmark-table/create/1k	duration	114.90 (±2.40 ms)	113.15 (±2.60 ms)	-1.8ms (1.5%) 👌

table-update-10th-1k	metric	base(`00a13cc`)	target(`d8a1a27`)	trend
benchmark-table/update-10th/1k	duration	86.05 (±3.00 ms)	78.55 (±4.00 ms)	-7.5ms (8.7%) 👍

tablecmp-append-1k	metric	base(`00a13cc`)	target(`d8a1a27`)	trend
benchmark-table-component/append/1k	duration	215.90 (±13.20 ms)	220.90 (±16.05 ms)	+5.0ms (2.3%) 👌

tablecmp-clear-1k	metric	base(`00a13cc`)	target(`d8a1a27`)	trend
benchmark-table-component/clear/1k	duration	11.40 (±1.30 ms)	11.60 (±1.65 ms)	+0.2ms (1.8%) 👌

tablecmp-create-10k	metric	base(`00a13cc`)	target(`d8a1a27`)	trend
benchmark-table-component/create/10k	duration	1656.90 (±12.90 ms)	1652.55 (±9.45 ms)	-4.3ms (0.3%) 👌

tablecmp-create-1k	metric	base(`00a13cc`)	target(`d8a1a27`)	trend
benchmark-table-component/create/1k	duration	198.90 (±4.80 ms)	200.25 (±5.95 ms)	+1.4ms (0.7%) 👌

tablecmp-update-10th-1k	metric	base(`00a13cc`)	target(`d8a1a27`)	trend
benchmark-table-component/update-10th/1k	duration	69.35 (±4.25 ms)	71.95 (±3.55 ms)	+2.6ms (3.7%) 👌

wc-append-1k	metric	base(`00a13cc`)	target(`d8a1a27`)	trend
benchmark-table-wc/append/1k	duration	231.25 (±9.40 ms)	260.90 (±11.95 ms)	+29.6ms (12.8%) 👎

wc-clear-1k	metric	base(`00a13cc`)	target(`d8a1a27`)	trend
benchmark-table-wc/clear/1k	duration	22.15 (±2.55 ms)	21.05 (±2.20 ms)	-1.1ms (5.0%) 👌

wc-create-10k	metric	base(`00a13cc`)	target(`d8a1a27`)	trend
benchmark-table-wc/create/10k	duration	1685.95 (±52.35 ms)	3857.80 (±19.25 ms)	+2171.9ms (128.8%) 👎

wc-create-1k	metric	base(`00a13cc`)	target(`d8a1a27`)	trend
benchmark-table-wc/create/1k	duration	206.80 (±5.20 ms)	231.25 (±4.70 ms)	+24.4ms (11.8%) 👎

wc-update-10th-1k	metric	base(`00a13cc`)	target(`d8a1a27`)	trend
benchmark-table-wc/update-10th/1k	duration	75.05 (±6.25 ms)	77.00 (±6.15 ms)	+2.0ms (2.6%) 👌

caridy

still think u should talk to others about the names

jodarove · 2018-10-25T20:37:32Z

@caridy yes, i already talked with @kevinv11n . he will jump when has a chance 👍

dbajric · 2018-10-26T22:43:32Z

The comment I will make here is for existing code, but it is to consider to add into this PR.

The startMeasure and endMeasure functions are exported directly and on every call they check if user timing is supported. I like what you've done with startGlobalMeasure and endGlobalMeasure where you return noop function if user timing is not supported. Can we do the same for startMeasure and endMeasure?

diervo · 2018-10-26T22:50:45Z

@dbajric I dont think we actually even need any of that. @tariq-sfdc and @nolanlawson are working on the polyfill which will endup in COMPAT. Hence I dont think we need noops

diervo

Lets talk to the perf team see if we really need the noops

tariqrafique · 2018-10-26T23:03:45Z

@diervo we don't plan to polyfill performance.mark / measure. We're not using PeformanceObserver in chrome either.

diervo · 2018-10-26T23:09:54Z

@tariq-sfdc tell me more :)

jodarove · 2018-10-26T23:21:25Z

@diervo check pm comment on that: https://github.com/salesforce/lwc/blob/master/packages/lwc-engine/src/framework/performance-timing.ts#L12
i agree with him.

tariqrafique · 2018-10-26T23:24:24Z

@diervo you reviewed and approved the metrics service changes to listen for performance mark/measure: internal link removed by @caridy

tariqrafique · 2018-10-30T21:43:49Z

what's left to do here ?

Gr8Gatsby · 2018-10-31T17:37:31Z

@caridy @kevinv11n

For this pull request we should use lwc-render since this is what is happening, lwc-rehydrate can be easily confused for future generations, as rehydration generally means something was pulled from a cache and re-added to the DOM in this case. These definitions make more sense to me, feel free to correct my understanding, but render works.

lwc-init - The engine has added a root LWC element and called it's constructor.
lwc-hydrate - The engine has completed the connectedCallback for the root LWC element.
lwc-render - The engine has rendered or re-rendered component(s)
lwc-destroy - The engine has removed the root element meaning disconnectedCallback was completed for the root

diervo · 2018-11-01T00:55:10Z

@tariq-sfdc every commit now needs to be merged in a timely manner and test the hell out of it, so little by little :)
🤷‍♂️

caridy · 2018-11-01T16:05:25Z

@Gr8Gatsby I'm fine with those names. render and rehydrate are sometime a subset of the other during insertion.

kevinv11n · 2018-11-01T16:52:59Z

diervo · 2018-11-01T17:05:42Z

I want to do a final pass today before merging please.
I will merge this after I have done so

This reverts commit 24e029a. # Conflicts: # packages/lwc-engine/src/framework/upgrade.ts # packages/lwc-engine/src/framework/vm.ts

jodarove commented Oct 22, 2018

View reviewed changes

jodarove requested a review from diervo October 22, 2018 18:49

This comment has been minimized.

Sign in to view

caridy suggested changes Oct 23, 2018

View reviewed changes

davidturissini suggested changes Oct 23, 2018

View reviewed changes

caridy reviewed Oct 23, 2018

View reviewed changes

jodarove added 3 commits October 24, 2018 13:52

feat(engine): performance marks

6e5c150

Adds performance marks for: - createElement - render/patch generated from connecting a root element. - flush rehydrate queue.

wip: address pr comments

a25a52b

- enum - init instead of createElement - hydrate instead of connectedRootElement.

wip: add measures for wc

2245cbb

entry point.

jodarove force-pushed the jodarove/performance-markers branch from 1bf3645 to 2245cbb Compare October 24, 2018 20:57

This comment has been minimized.

Sign in to view

caridy reviewed Oct 25, 2018

View reviewed changes

caridy suggested changes Oct 25, 2018

View reviewed changes

caridy reviewed Oct 25, 2018

View reviewed changes

fix: incorrect marker placement on wc.ts

d8a1a27

The markers were added in the incorrect place when building a wc.

caridy approved these changes Oct 25, 2018

View reviewed changes

diervo suggested changes Oct 26, 2018

View reviewed changes

kevinv11n approved these changes Nov 1, 2018

View reviewed changes

diervo merged commit 24e029a into master Nov 2, 2018

diervo deleted the jodarove/performance-markers branch November 2, 2018 06:13

jodarove added a commit that referenced this pull request Nov 7, 2018

Revert "feat(engine): performance marks (#756)"

720ff20

This reverts commit 24e029a. # Conflicts: # packages/lwc-engine/src/framework/upgrade.ts # packages/lwc-engine/src/framework/vm.ts

pmdartus mentioned this pull request Nov 12, 2018

Enable lwc-engine performance timing tests #822

Closed


		export function buildCustomElementConstructor(Ctor: ComponentConstructor, options?: ShadowRootInit): HTMLElementConstructor {
		startGlobalMeasure(GlobalMeasurementPhase.INIT);

feat(engine): performance marks #756

feat(engine): performance marks #756

Conversation

jodarove commented Oct 22, 2018 • edited Loading

Does this PR introduce a breaking change?

Choose a reason for hiding this comment

Choose a reason for hiding this comment

caridy Oct 23, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

This comment has been minimized.

caridy left a comment

Choose a reason for hiding this comment

diervo commented Oct 23, 2018

davidturissini left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

caridy commented Oct 23, 2018

caridy Oct 23, 2018 • edited Loading

Choose a reason for hiding this comment

caridy Oct 23, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jodarove commented Oct 24, 2018

tariqrafique commented Oct 24, 2018

jodarove commented Oct 24, 2018

This comment has been minimized.

tariqrafique commented Oct 24, 2018

jodarove commented Oct 24, 2018

tariqrafique commented Oct 24, 2018

This comment has been minimized.

Choose a reason for hiding this comment

Choose a reason for hiding this comment

caridy left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

salesforce-best-lwc-internal bot commented Oct 25, 2018

Benchmark results

lwc-engine-benchmark

caridy left a comment

Choose a reason for hiding this comment

jodarove commented Oct 25, 2018

dbajric commented Oct 26, 2018

diervo commented Oct 26, 2018

diervo left a comment

Choose a reason for hiding this comment

tariqrafique commented Oct 26, 2018

diervo commented Oct 26, 2018

jodarove commented Oct 26, 2018 • edited Loading

tariqrafique commented Oct 26, 2018 • edited by caridy Loading

tariqrafique commented Oct 30, 2018

Gr8Gatsby commented Oct 31, 2018 • edited Loading

diervo commented Nov 1, 2018

caridy commented Nov 1, 2018

kevinv11n commented Nov 1, 2018

diervo commented Nov 1, 2018

jodarove commented Oct 22, 2018 •

edited

Loading

caridy Oct 23, 2018 •

edited

Loading

caridy Oct 23, 2018 •

edited

Loading

caridy Oct 23, 2018 •

edited

Loading

jodarove commented Oct 26, 2018 •

edited

Loading

tariqrafique commented Oct 26, 2018 •

edited by caridy

Loading

Gr8Gatsby commented Oct 31, 2018 •

edited

Loading