fix(profile): improve profiling

ionic-team · Oct 10, 2019 · fdaa035 · fdaa035
1 parent 31091cd
commit fdaa035
Show file tree

Hide file tree

Showing 9 changed files with 75 additions and 30 deletions.
diff --git a/src/runtime/bootstrap-lazy.ts b/src/runtime/bootstrap-lazy.ts
@@ -138,6 +138,7 @@ export const bootstrapLazy = (lazyBundles: d.LazyBundlesRuntimeData, options: d.
       cmpMeta.$lazyBundleIds$ = lazyBundle[0];
 
       if (!exclude.includes(tagName) && !customElements.get(tagName)) {
+        cmpTags.push(tagName);
         customElements.define(
           tagName,
           proxyComponent(HostElement as any, cmpMeta, PROXY_FLAGS.isElementConstructor) as any

diff --git a/src/runtime/client-hydrate.ts b/src/runtime/client-hydrate.ts
@@ -3,9 +3,11 @@ import { BUILD } from '@build-conditionals';
 import { CONTENT_REF_ID, HYDRATE_CHILD_ID, HYDRATE_ID, NODE_TYPE, ORG_LOCATION_ID, SLOT_NODE_ID, TEXT_NODE_ID } from './runtime-constants';
 import { doc, plt } from '@platform';
 import { newVNode } from './vdom/h';
+import { createTime } from 'profile';
 
 
 export const initializeClientHydrate = (hostElm: d.HostElement, tagName: string, hostId: string, hostRef: d.HostRef) => {
+  const endHydrate = createTime('hydrateClient', tagName);
   const shadowRoot = hostElm.shadowRoot;
   const childRenderNodes: RenderNodeData[] = [];
   const slotNodes: RenderNodeData[] = [];
@@ -52,6 +54,7 @@ export const initializeClientHydrate = (hostElm: d.HostElement, tagName: string,
       }
     });
   }
+  endHydrate();
 };
 
 const clientHydrate = (

diff --git a/src/runtime/connected-callback.ts b/src/runtime/connected-callback.ts
@@ -38,7 +38,7 @@ export const connectedCallback = (elm: d.HostElement, cmpMeta: d.ComponentRuntim
         hostId = elm.getAttribute(HYDRATE_ID);
         if (hostId) {
           if (BUILD.shadowDom && supportsShadowDom && cmpMeta.$flags$ & CMP_FLAGS.shadowDomEncapsulation) {
-            const scopeId = BUILD.mode ?  addStyle(elm.shadowRoot, cmpMeta, elm.getAttribute('s-mode')) : addStyle(elm.shadowRoot, cmpMeta);
+            const scopeId = BUILD.mode ? addStyle(elm.shadowRoot, cmpMeta, elm.getAttribute('s-mode')) : addStyle(elm.shadowRoot, cmpMeta);
             elm.classList.remove(scopeId + '-h');
             elm.classList.remove(scopeId + '-s');
           }

diff --git a/src/runtime/initialize-component.ts b/src/runtime/initialize-component.ts
@@ -8,7 +8,7 @@ import { computeMode } from './mode';
 import { getScopeId, registerStyle } from './styles';
 import { fireConnectedCallback } from './connected-callback';
 import { PROXY_FLAGS } from './runtime-constants';
-import { createTime } from './profile';
+import { createTime, uniqueTime } from './profile';
 
 
 export const initializeComponent = async (elm: d.HostElement, hostRef: d.HostRef, cmpMeta: d.ComponentRuntimeMeta, hmrVersionId?: string, Cstr?: any) => {
@@ -36,13 +36,17 @@ export const initializeComponent = async (elm: d.HostElement, hostRef: d.HostRef
       Cstr = loadModule(cmpMeta, hostRef, hmrVersionId);
       if (Cstr.then) {
         // Await creates a micro-task avoid if possible
+        const endLoad = uniqueTime(
+          `st:load:${cmpMeta.$tagName$}:${hostRef.$modeName$}`,
+          `[Stencil] Load module for <${cmpMeta.$tagName$}>`
+        );
         Cstr = await Cstr;
+        endLoad();
       }
       if ((BUILD.isDev || BUILD.isDebug) && !Cstr) {
         throw new Error(`Constructor for "${cmpMeta.$tagName$}#${hostRef.$modeName$}" was not found`);
       }
       if (BUILD.member && !Cstr.isProxied) {
-        const endProxyInstance = createTime('proxyInstance', cmpMeta.$tagName$);
         // we'eve never proxied this Constructor before
         // let's add the getters/setters to its prototype before
         // the first time we create an instance of the implementation
@@ -51,10 +55,9 @@ export const initializeComponent = async (elm: d.HostElement, hostRef: d.HostRef
         }
         proxyComponent(Cstr, cmpMeta, PROXY_FLAGS.proxyState);
         Cstr.isProxied = true;
-        endProxyInstance();
       }
 
-      const endNewInstance = createTime('newInstance', cmpMeta.$tagName$);
+      const endNewInstance = createTime('createInstance', cmpMeta.$tagName$);
       // ok, time to construct the instance
       // but let's keep track of when we start and stop
       // so that the getters/setters don't incorrectly step on data
@@ -84,9 +87,9 @@ export const initializeComponent = async (elm: d.HostElement, hostRef: d.HostRef
       Cstr = elm.constructor as any;
     }
 
-    const endRegisterStyles = createTime('registerStyles', cmpMeta.$tagName$);
     const scopeId = BUILD.mode ? getScopeId(cmpMeta.$tagName$, hostRef.$modeName$) : getScopeId(cmpMeta.$tagName$);
     if (BUILD.style && !styles.has(scopeId) && Cstr.style) {
+      const endRegisterStyles = createTime('registerStyles', cmpMeta.$tagName$);
       // this component has styles but we haven't registered them yet
       let style = Cstr.style;
 
@@ -99,8 +102,8 @@ export const initializeComponent = async (elm: d.HostElement, hostRef: d.HostRef
       }
 
       registerStyle(scopeId, style, !!(cmpMeta.$flags$ & CMP_FLAGS.shadowDomEncapsulation));
+      endRegisterStyles();
     }
-    endRegisterStyles();
   }
 
   // we've successfully created a lazy instance

diff --git a/src/runtime/profile.ts b/src/runtime/profile.ts
@@ -17,6 +17,21 @@ export const createTime = (fnName: string, tagName = '') => {
   }
 };
 
+export const uniqueTime = (key: string, measureText: string) => {
+  if (BUILD.profile) {
+    if (performance.getEntriesByName(key).length === 0) {
+      performance.mark(key);
+    }
+    return () => {
+      if (performance.getEntriesByName(measureText).length === 0) {
+        performance.measure(measureText, key);
+      }
+    };
+  } else {
+    return () => { return; };
+  }
+};
+
 const inspect = (ref: any) => {
   const hostRef = getHostRef(ref);
   if (!hostRef) {

diff --git a/src/runtime/set-value.ts b/src/runtime/set-value.ts
@@ -23,13 +23,22 @@ export const setValue = (ref: d.RuntimeRef, propName: string, newVal: any, cmpMe
     // set our new value!
     hostRef.$instanceValues$.set(propName, newVal);
 
-    if (BUILD.isDev && hostRef.$flags$ & HOST_FLAGS.dev_stateMutation) {
-      console.warn(
-        `[STENCIL-DEV-MODE] The state/prop "${propName}" changed during rendering. This can potentially lead to infinite-loops and other bugs.`,
-        '\nElement', elm,
-        '\nNew value', newVal,
-        '\nOld value', oldVal
-      );
+    if (BUILD.isDev) {
+      if (hostRef.$flags$ & HOST_FLAGS.dev_onRender) {
+        console.warn(
+          `[STENCIL-DEV-MODE] The state/prop "${propName}" changed during rendering. This can potentially lead to infinite-loops and other bugs.`,
+          '\nElement', elm,
+          '\nNew value', newVal,
+          '\nOld value', oldVal
+        );
+      } else if (hostRef.$flags$ & HOST_FLAGS.dev_onDidLoad) {
+        console.debug(
+          `[STENCIL-DEV-MODE] The state/prop "${propName}" changed during "componentDidLoad()", this triggers extra re-renders, try to setup on "componentWillRender()"`,
+          '\nElement', elm,
+          '\nNew value', newVal,
+          '\nOld value', oldVal
+        );
+      }
     }
 
     if (!BUILD.lazyLoad || instance) {

diff --git a/src/runtime/test/watch.spec.tsx b/src/runtime/test/watch.spec.tsx
@@ -1,4 +1,4 @@
-import { Component, Prop, State, Watch, Method } from '@stencil/core';
+import { Component, Method, Prop, State, Watch } from '@stencil/core';
 import { newSpecPage } from '@stencil/core/testing';
 
 

diff --git a/src/runtime/update-component.ts b/src/runtime/update-component.ts
@@ -84,7 +84,7 @@ const updateComponent = (elm: d.RenderNode, hostRef: d.HostRef, cmpMeta: d.Compo
 
   const endRender = createTime('render', cmpMeta.$tagName$);
   if (BUILD.isDev)  {
-    hostRef.$flags$ |= HOST_FLAGS.dev_stateMutation;
+    hostRef.$flags$ |= HOST_FLAGS.dev_onRender;
   }
 
   if (BUILD.hasRenderFn || BUILD.reflect) {
@@ -111,7 +111,7 @@ const updateComponent = (elm: d.RenderNode, hostRef: d.HostRef, cmpMeta: d.Compo
   }
   if (BUILD.isDev) {
     hostRef.$renderCount$++;
-    hostRef.$flags$ &= ~HOST_FLAGS.dev_stateMutation;
+    hostRef.$flags$ &= ~HOST_FLAGS.dev_onRender;
   }
   if (BUILD.updatable && BUILD.taskQueue) {
     hostRef.$flags$ &= ~HOST_FLAGS.isQueuedForUpdate;
@@ -159,11 +159,14 @@ export const postUpdateComponent = (elm: d.HostElement, hostRef: d.HostRef, cmpM
   const instance = BUILD.lazyLoad ? hostRef.$lazyInstance$ : elm as any;
   const ancestorComponent = hostRef.$ancestorComponent$;
 
-  if (BUILD.isDev) {
-    hostRef.$flags$ |= HOST_FLAGS.dev_stateMutation;
-  }
   if (BUILD.cmpDidRender) {
+    if (BUILD.isDev) {
+      hostRef.$flags$ |= HOST_FLAGS.dev_onRender;
+    }
     safeCall(instance, 'componentDidRender');
+    if (BUILD.isDev) {
+      hostRef.$flags$ &= ~HOST_FLAGS.dev_onRender;
+    }
   }
   emitLifecycleEvent(elm, 'componentDidRender');
 
@@ -177,15 +180,22 @@ export const postUpdateComponent = (elm: d.HostElement, hostRef: d.HostRef, cmpM
     }
 
     if (BUILD.cmpDidLoad) {
+      if (BUILD.isDev)  {
+        hostRef.$flags$ |= HOST_FLAGS.dev_onDidLoad;
+      }
       safeCall(instance, 'componentDidLoad');
+      if (BUILD.isDev)  {
+        hostRef.$flags$ &= ~HOST_FLAGS.dev_onDidLoad;
+      }
     }
 
     emitLifecycleEvent(elm, 'componentDidLoad');
+    endPostUpdate();
 
     if (BUILD.asyncLoading) {
       hostRef.$onReadyResolve$(elm);
       if (!ancestorComponent)  {
-        appDidLoad();
+        appDidLoad(cmpMeta.$tagName$);
       }
     }
 
@@ -195,17 +205,21 @@ export const postUpdateComponent = (elm: d.HostElement, hostRef: d.HostRef, cmpM
       // fire off the user's componentDidUpdate method (if one was provided)
       // componentDidUpdate runs AFTER render() has been called
       // and all child components have finished updating
+      if (BUILD.isDev)  {
+        hostRef.$flags$ |= HOST_FLAGS.dev_onRender;
+      }
       safeCall(instance, 'componentDidUpdate');
+      if (BUILD.isDev) {
+        hostRef.$flags$ &= ~HOST_FLAGS.dev_onRender;
+      }
     }
     emitLifecycleEvent(elm, 'componentDidUpdate');
+    endPostUpdate();
   }
 
   if (BUILD.hotModuleReplacement) {
     elm['s-hmr-load'] && elm['s-hmr-load']();
   }
-  if (BUILD.isDev) {
-    hostRef.$flags$ &= ~HOST_FLAGS.dev_stateMutation;
-  }
 
   if (BUILD.method && BUILD.lazyLoad) {
     hostRef.$onInstanceResolve$(elm);
@@ -222,7 +236,6 @@ export const postUpdateComponent = (elm: d.HostElement, hostRef: d.HostRef, cmpM
     }
     hostRef.$flags$ &= ~(HOST_FLAGS.isWaitingForChildren | HOST_FLAGS.needsRerender);
   }
-  endPostUpdate();
   // ( •_•)
   // ( •_•)>⌐■-■
   // (⌐■_■)
@@ -242,7 +255,7 @@ export const forceUpdate = (elm: d.RenderNode, cmpMeta: d.ComponentRuntimeMeta)
   }
 };
 
-export const appDidLoad = () => {
+export const appDidLoad = (who: string) => {
   // on appload
   // we have finish the first big initial render
   if (BUILD.cssAnnotations) {
@@ -252,9 +265,9 @@ export const appDidLoad = () => {
     plt.$flags$ |= PLATFORM_FLAGS.appLoaded;
   }
   emitLifecycleEvent(doc, 'appload');
-  // if (BUILD.profile) {
-  //   performance.measure('[Stencil] App Did Load', 'st:app:start');
-  // }
+  if (BUILD.profile) {
+    performance.measure(`[Stencil] App Did Load (by ${who})`, 'st:app:start');
+  }
 };
 
 export const safeCall = (instance: any, method: string, arg?: any) => {

diff --git a/src/utils/constants.ts b/src/utils/constants.ts
@@ -48,7 +48,8 @@ export const enum HOST_FLAGS {
   needsRerender = 1 << 9,
 
   // DEV ONLY
-  dev_stateMutation = 1 << 10
+  dev_onRender = 1 << 10,
+  dev_onDidLoad = 1 << 11
 }
 
 export const enum CMP_FLAGS {