feat: add mutation logging to DevTools profiler (#4544)

Co-authored-by: Will Harney <[email protected]>

packages/@lwc/engine-core/src/framework/component.ts

@@ -25,6 +25,7 @@ import { LightningElementConstructor } from './base-lightning-element';
 import { Template, isUpdatingTemplate, getVMBeingRendered } from './template';
 import { VNodes } from './vnodes';
 import { checkVersionMismatch } from './check-version-mismatch';
+import { associateReactiveObserverWithVM } from './mutation-logger';
 
 type ComponentConstructorMetadata = {
  tmpl: Template;
@@ -83,13 +84,19 @@ export function getComponentAPIVersion(Ctor: LightningElementConstructor): APIVe
 }
 
 export function getTemplateReactiveObserver(vm: VM): ReactiveObserver {
- return createReactiveObserver(() => {
+ const reactiveObserver = createReactiveObserver(() => {
  const { isDirty } = vm;
  if (isFalse(isDirty)) {
  markComponentAsDirty(vm);
  scheduleRehydration(vm);
  }
  });
+
+ if (process.env.NODE_ENV !== 'production') {
+ associateReactiveObserverWithVM(reactiveObserver, vm);
+ }
+
+ return reactiveObserver;
 }
 
 export function resetTemplateObserverAndUnsubscribe(vm: VM) {

packages/@lwc/engine-core/src/framework/decorators/track.ts

@@ -5,6 +5,7 @@
  * For full license text, see the LICENSE file in the repo root or https://opensource.org/licenses/MIT
  */
 import { assert, toString } from '@lwc/shared';
+import { trackTargetForMutationLogging } from '../mutation-logger';
 import { componentValueObserved } from '../mutation-tracker';
 import { isInvokingRender } from '../invoker';
 import { getAssociatedVM } from '../vm';
@@ -65,6 +66,9 @@ export function internalTrackDecorator(key: string): PropertyDescriptor {
  }
  }
  const reactiveOrAnyValue = getReactiveProxy(newValue);
+ if (process.env.NODE_ENV !== 'production') {
+ trackTargetForMutationLogging(key, newValue);
+ }
  updateComponentValue(vm, key, reactiveOrAnyValue);
  },
  enumerable: true,

packages/@lwc/engine-core/src/framework/mutation-logger.ts

@@ -0,0 +1,147 @@
+/*
+ * Copyright (c) 2024, Salesforce, Inc.
+ * All rights reserved.
+ * SPDX-License-Identifier: MIT
+ * For full license text, see the LICENSE file in the repo root or https://opensource.org/licenses/MIT
+ */
+//
+// Do additional mutation tracking for DevTools performance profiling, in dev mode only.
+//
+import {
+ ArrayPush,
+ isUndefined,
+ toString,
+ isObject,
+ isNull,
+ isArray,
+ ArrayFilter,
+ getOwnPropertyNames,
+ getOwnPropertySymbols,
+ isString,
+} from '@lwc/shared';
+import { ReactiveObserver } from '../libs/mutation-tracker';
+import { VM } from './vm';
+import { assertNotProd } from './utils';
+
+export interface MutationLog {
+ vm: VM;
+ prop: string;
+}
+
+const reactiveObserversToVMs = new WeakMap<ReactiveObserver, VM>();
+const targetsToPropertyKeys = new WeakMap<object, PropertyKey>();
+let mutationLogs: MutationLog[] = [];
+
+// Create a human-readable member access notation like `obj.foo` or `arr[1]`,
+// handling edge cases like `obj[Symbol("bar")]` and `obj["spaces here"]`
+function toPrettyMemberNotation(parent: PropertyKey | undefined, child: PropertyKey) {
+ if (isUndefined(parent)) {
+ // Bare prop, just stringify the child
+ return toString(child);
+ } else if (!isString(child)) {
+ // Symbol/number, e.g. `obj[Symbol("foo")]` or `obj[1234]`
+ return `${toString(parent)}[${toString(child)}]`;
+ } else if (/^\w+$/.test(child)) {
+ // Dot-notation-safe string, e.g. `obj.foo`
+ return `${toString(parent)}.${child}`;
+ } else {
+ // Bracket-notation-requiring string, e.g. `obj["prop with spaces"]`
+ return `${toString(parent)}[${JSON.stringify(child)}]`;
+ }
+}
+
+/**
+ * Flush all the logs we've written so far and return the current logs.
+ */
+export function getAndFlushMutationLogs() {
+ assertNotProd();
+ const result = mutationLogs;
+ mutationLogs = [];
+ return result;
+}
+
+/**
+ * Log a new mutation for this reactive observer.
+ * @param reactiveObserver - relevant ReactiveObserver
+ * @param target - target object that is being observed
+ * @param key - key (property) that was mutated
+ */
+export function logMutation(reactiveObserver: ReactiveObserver, target: object, key: PropertyKey) {
+ assertNotProd();
+ const parentKey = targetsToPropertyKeys.get(target);
+ const vm = reactiveObserversToVMs.get(reactiveObserver);
+
+ /* istanbul ignore if */
+ if (isUndefined(vm)) {
+ // VM should only be undefined in Vitest tests, where a reactive observer is not always associated with a VM
+ // because the unit tests just create Reactive Observers on-the-fly.
+ // Note we could explicitly target Vitest with `process.env.NODE_ENV === 'test'`, but then that would also
+ // affect our downstream consumers' Jest/Vitest tests, and we don't want to throw an error just for a logger.
+ if (process.env.NODE_ENV === 'test-karma-lwc') {
+ throw new Error('The VM should always be defined except possibly in unit tests');
+ }
+ } else {
+ const prop = toPrettyMemberNotation(parentKey, key);
+ ArrayPush.call(mutationLogs, { vm, prop });
+ }
+}
+
+/**
+ * Flush logs associated with a given VM.
+ * @param vm - given VM
+ */
+export function flushMutationLogsForVM(vm: VM) {
+ assertNotProd();
+ mutationLogs = ArrayFilter.call(mutationLogs, (log) => log.vm !== vm);
+}
+
+/**
+ * Mark this ReactiveObserver as related to this VM. This is only needed for mutation tracking in dev mode.
+ * @param reactiveObserver
+ * @param vm
+ */
+export function associateReactiveObserverWithVM(reactiveObserver: ReactiveObserver, vm: VM) {
+ assertNotProd();
+ reactiveObserversToVMs.set(reactiveObserver, vm);
+}
+
+/**
+ * Deeply track all objects in a target and associate with a given key.
+ * @param key - key associated with the object in the component
+ * @param target - tracked target object
+ */
+export function trackTargetForMutationLogging(key: PropertyKey, target: any) {
+ assertNotProd();
+ if (targetsToPropertyKeys.has(target)) {
+ // Guard against recursive objects - don't traverse forever
+ return;
+ }
+ if (isObject(target) && !isNull(target)) {
+ // only track non-primitives; others are invalid as WeakMap keys
+ targetsToPropertyKeys.set(target, key);
+
+ // Deeply traverse arrays and objects to track every object within
+ if (isArray(target)) {
+ for (let i = 0; i < target.length; i++) {
+ trackTargetForMutationLogging(toPrettyMemberNotation(key, i), target[i]);
+ }
+ } else {
+ // Track only own property names and symbols (including non-enumerated)
+ // This is consistent with what observable-membrane does:
+ // https:/salesforce/observable-membrane/blob/b85417f/src/base-handler.ts#L142-L143
+ // Note this code path is very hot, hence doing two separate for-loops rather than creating a new array.
+ for (const prop of getOwnPropertyNames(target)) {
+ trackTargetForMutationLogging(
+ toPrettyMemberNotation(key, prop),
+ (target as any)[prop]
+ );
+ }
+ for (const prop of getOwnPropertySymbols(target)) {
+ trackTargetForMutationLogging(
+ toPrettyMemberNotation(key, prop),
+ (target as any)[prop]
+ );
+ }
+ }
+ }
+}

packages/@lwc/engine-core/src/framework/mutation-tracker.ts

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2018, salesforce.com, inc.
+ * Copyright (c) 2024, Salesforce, Inc.
  * All rights reserved.
  * SPDX-License-Identifier: MIT
  * For full license text, see the LICENSE file in the repo root or https://opensource.org/licenses/MIT

packages/@lwc/engine-core/src/framework/profiler.ts

@@ -1,13 +1,15 @@
 /*
- * Copyright (c) 2018, salesforce.com, inc.
+ * Copyright (c) 2024, Salesforce, Inc.
  * All rights reserved.
  * SPDX-License-Identifier: MIT
  * For full license text, see the LICENSE file in the repo root or https://opensource.org/licenses/MIT
  */
-import { noop } from '@lwc/shared';
+import { ArrayJoin, ArrayMap, ArrayPush, ArraySort, isUndefined, noop } from '@lwc/shared';
 
 import { getComponentTag } from '../shared/format';
 import { RenderMode, ShadowMode, VM } from './vm';
+import { EmptyArray } from './utils';
+import type { MutationLog } from './mutation-logger';
 
 export const enum OperationId {
  Constructor = 0,
@@ -37,6 +39,18 @@ type LogDispatcher = (
  shadowMode?: ShadowMode
 ) => void;
 
+type TrackColor =
+ | 'primary'
+ | 'primary-light'
+ | 'primary-dark'
+ | 'secondary'
+ | 'secondary-light'
+ | 'secondary-dark'
+ | 'tertiary'
+ | 'tertiary-light'
+ | 'tertiary-dark'
+ | 'error';
+
 const operationIdNameMapping = [
  'constructor',
  'render',
@@ -91,17 +105,7 @@ const end = !isUserTimingSupported
  measureName: string,
  markName: string,
  devtools?: {
- color?:
- | 'primary'
- | 'primary-light'
- | 'primary-dark'
- | 'secondary'
- | 'secondary-light'
- | 'secondary-dark'
- | 'tertiary'
- | 'tertiary-light'
- | 'tertiary-dark'
- | 'error';
+ color?: TrackColor;
  properties?: [string, string][];
  tooltipText?: string;
  }
@@ -146,6 +150,86 @@ 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:
+ case OperationId.Constructor:
+ return 'primary';
+ // GlobalRehydrate 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:
+ return 'tertiary';
+ // Everything else (patch/render/callbacks)
+ default:
+ return 'secondary';
+ }
+}
+
+// Create a list of tag names to the properties that were mutated, to help answer the question of
+// "why did this component re-render?"
+function getMutationProperties(mutationLogs: MutationLog[] | undefined): [string, string][] {
+ // `mutationLogs` should never have length 0, but bail out if it does for whatever reason
+ if (isUndefined(mutationLogs)) {
+ return EmptyArray;
+ }
+
+ if (!mutationLogs.length) {
+ // Currently this only occurs for experimental signals, because those mutations are not triggered by accessors
+ // TODO [#4546]: support signals in mutation logging
+ return EmptyArray;
+ }
+
+ // Keep track of unique IDs per tag name so we can just report a raw count at the end, e.g.
+ // `<x-foo> (x2)` to indicate that two instances of `<x-foo>` were rendered.
+ const tagNamesToIdsAndProps = new Map<string, { ids: Set<number>; keys: Set<string> }>();
+ for (const {
+ vm: { tagName, idx },
+ prop,
+ } of mutationLogs) {
+ let idsAndProps = tagNamesToIdsAndProps.get(tagName);
+ if (isUndefined(idsAndProps)) {
+ idsAndProps = { ids: new Set(), keys: new Set() };
+ tagNamesToIdsAndProps.set(tagName, idsAndProps);
+ }
+ idsAndProps.ids.add(idx);
+ idsAndProps.keys.add(prop);
+ }
+
+ // Sort by tag name
+ const entries = ArraySort.call([...tagNamesToIdsAndProps], (a, b) => a[0].localeCompare(b[0]));
+ const tagNames = ArrayMap.call(entries, (item) => item[0]) as string[];
+
+ // Show e.g. `<x-foo>` for one instance, or `<x-foo> (x2)` for two instances. (\u00D7 is multiplication symbol)
+ const tagNamesToDisplayTagNames = new Map<string, string>();
+ for (const tagName of tagNames) {
+ const { ids } = tagNamesToIdsAndProps.get(tagName)!;
+ const displayTagName = `<${tagName}>${ids.size > 1 ? ` (\u00D7${ids.size})` : ''}`;
+ tagNamesToDisplayTagNames.set(tagName, displayTagName);
+ }
+
+ // Summary row
+ const usePlural = tagNames.length > 1 || tagNamesToIdsAndProps.get(tagNames[0])!.ids.size > 1;
+ const result: [string, string][] = [
+ [
+ `Component${usePlural ? 's' : ''}`,
+ ArrayJoin.call(
+ ArrayMap.call(tagNames, (_) => tagNamesToDisplayTagNames.get(_)),
+ ', '
+ ),
+ ],
+ ];
+
+ // Detail rows
+ for (const [prettyTagName, { keys }] of entries) {
+ const displayTagName = tagNamesToDisplayTagNames.get(prettyTagName)!;
+ ArrayPush.call(result, [displayTagName, ArrayJoin.call(ArraySort.call([...keys]), ', ')]);
+ }
+
+ return result;
+}
+
 function getTooltipText(measureName: string, opId: OperationId) {
  return `${measureName} - ${operationTooltipMapping[opId]}`;
 }
@@ -197,9 +281,9 @@ export function logOperationEnd(opId: OperationId, vm: VM) {
  const markName = getMarkName(opId, vm);
  const measureName = getMeasureName(opId, vm);
  end(measureName, markName, {
- properties: getProperties(vm),
+ color: getColor(opId),
  tooltipText: getTooltipText(measureName, opId),
- color: opId === OperationId.Render ? 'primary' : 'secondary',
+ properties: getProperties(vm),
  });
  }
 
@@ -230,13 +314,17 @@ export function logGlobalOperationStartWithVM(opId: GlobalOperationId, vm: VM) {
  }
 }
 
-export function logGlobalOperationEnd(opId: GlobalOperationId) {
+export function logGlobalOperationEnd(
+ opId: GlobalOperationId,
+ mutationLogs: MutationLog[] | undefined
+) {
  if (isMeasureEnabled) {
  const opName = getOperationName(opId);
  const markName = opName;
  end(opName, markName, {
+ color: getColor(opId),
  tooltipText: getTooltipText(opName, opId),
- color: 'tertiary',
+ properties: getMutationProperties(mutationLogs),
  });
  }
 
@@ -250,9 +338,9 @@ export function logGlobalOperationEndWithVM(opId: GlobalOperationId, vm: VM) {
  const opName = getOperationName(opId);
  const markName = getMarkName(opId, vm);
  end(opName, markName, {
- properties: getProperties(vm),
+ color: getColor(opId),
  tooltipText: getTooltipText(opName, opId),
- color: 'tertiary',
+ properties: getProperties(vm),
  });
  }