diff --git a/packages/react-client/src/ReactFlightPerformanceTrack.js b/packages/react-client/src/ReactFlightPerformanceTrack.js index 7e48709b9f0dc..3e38bb16a07ba 100644 --- a/packages/react-client/src/ReactFlightPerformanceTrack.js +++ b/packages/react-client/src/ReactFlightPerformanceTrack.js @@ -103,10 +103,10 @@ export function logComponentRender( if (__DEV__ && debugTask) { const properties: Array<[string, string]> = []; if (componentInfo.key != null) { - addValueToProperties('key', componentInfo.key, properties, 0); + addValueToProperties('key', componentInfo.key, properties, 0, ''); } if (componentInfo.props != null) { - addObjectToProperties(componentInfo.props, properties, 0); + addObjectToProperties(componentInfo.props, properties, 0, ''); } debugTask.run( // $FlowFixMe[method-unbinding] @@ -158,10 +158,10 @@ export function logComponentAborted( ], ]; if (componentInfo.key != null) { - addValueToProperties('key', componentInfo.key, properties, 0); + addValueToProperties('key', componentInfo.key, properties, 0, ''); } if (componentInfo.props != null) { - addObjectToProperties(componentInfo.props, properties, 0); + addObjectToProperties(componentInfo.props, properties, 0, ''); } performance.measure(entryName, { start: startTime < 0 ? 0 : startTime, @@ -215,10 +215,10 @@ export function logComponentErrored( String(error); const properties = [['Error', message]]; if (componentInfo.key != null) { - addValueToProperties('key', componentInfo.key, properties, 0); + addValueToProperties('key', componentInfo.key, properties, 0, ''); } if (componentInfo.props != null) { - addObjectToProperties(componentInfo.props, properties, 0); + addObjectToProperties(componentInfo.props, properties, 0, ''); } performance.measure(entryName, { start: startTime < 0 ? 0 : startTime, @@ -423,9 +423,9 @@ export function logComponentAwait( if (__DEV__ && debugTask) { const properties: Array<[string, string]> = []; if (typeof value === 'object' && value !== null) { - addObjectToProperties(value, properties, 0); + addObjectToProperties(value, properties, 0, ''); } else if (value !== undefined) { - addValueToProperties('Resolved', value, properties, 0); + addValueToProperties('Resolved', value, properties, 0, ''); } debugTask.run( // $FlowFixMe[method-unbinding] @@ -525,9 +525,9 @@ export function logIOInfo( if (__DEV__ && debugTask) { const properties: Array<[string, string]> = []; if (typeof value === 'object' && value !== null) { - addObjectToProperties(value, properties, 0); + addObjectToProperties(value, properties, 0, ''); } else if (value !== undefined) { - addValueToProperties('Resolved', value, properties, 0); + addValueToProperties('Resolved', value, properties, 0, ''); } debugTask.run( // $FlowFixMe[method-unbinding] diff --git a/packages/react-reconciler/src/ReactFiberPerformanceTrack.js b/packages/react-reconciler/src/ReactFiberPerformanceTrack.js index 48a403a8b63bd..faec8c63410f4 100644 --- a/packages/react-reconciler/src/ReactFiberPerformanceTrack.js +++ b/packages/react-reconciler/src/ReactFiberPerformanceTrack.js @@ -29,6 +29,7 @@ import { import { addValueToProperties, addObjectToProperties, + addObjectDiffToProperties, } from 'shared/ReactPerformanceTrackProperties'; import {enableProfilerTimer} from 'shared/ReactFeatureFlags'; @@ -36,26 +37,18 @@ import {enableProfilerTimer} from 'shared/ReactFeatureFlags'; const supportsUserTiming = enableProfilerTimer && typeof console !== 'undefined' && - typeof console.timeStamp === 'function'; + typeof console.timeStamp === 'function' && + (!__DEV__ || + // In DEV we also rely on performance.measure + (typeof performance !== 'undefined' && + // $FlowFixMe[method-unbinding] + typeof performance.measure === 'function')); const COMPONENTS_TRACK = 'Components ⚛'; const LANES_TRACK_GROUP = 'Scheduler ⚛'; let currentTrack: string = 'Blocking'; // Lane -const reusableLaneDevToolDetails = { - color: 'primary', - track: 'Blocking', // Lane - trackGroup: LANES_TRACK_GROUP, -}; -const reusableLaneOptions = { - start: -0, - end: -0, - detail: { - devtools: reusableLaneDevToolDetails, - }, -}; - export function setCurrentTrackFromLanes(lanes: Lanes): void { currentTrack = getGroupNameOfHighestPriorityLane(lanes); } @@ -108,28 +101,22 @@ function logComponentTrigger( trigger: string, ) { if (supportsUserTiming) { + reusableComponentOptions.start = startTime; + reusableComponentOptions.end = endTime; + reusableComponentDevToolDetails.color = 'warning'; + reusableComponentDevToolDetails.properties = null; const debugTask = fiber._debugTask; if (__DEV__ && debugTask) { debugTask.run( - console.timeStamp.bind( - console, + // $FlowFixMe[method-unbinding] + performance.measure.bind( + performance, trigger, - startTime, - endTime, - COMPONENTS_TRACK, - undefined, - 'warning', + reusableComponentOptions, ), ); } else { - console.timeStamp( - trigger, - startTime, - endTime, - COMPONENTS_TRACK, - undefined, - 'warning', - ); + performance.measure(trigger, reusableComponentOptions); } } } @@ -166,6 +153,21 @@ export function logComponentDisappeared( logComponentTrigger(fiber, startTime, endTime, 'Disconnect'); } +const reusableComponentDevToolDetails = { + color: 'primary', + properties: (null: null | Array<[string, string]>), + track: COMPONENTS_TRACK, +}; +const reusableComponentOptions = { + start: -0, + end: -0, + detail: { + devtools: reusableComponentDevToolDetails, + }, +}; + +const resuableChangedPropsEntry = ['Changed Props', '']; + export function logComponentRender( fiber: Fiber, startTime: number, @@ -178,8 +180,9 @@ export function logComponentRender( return; } if (supportsUserTiming) { + const alternate = fiber.alternate; let selfTime: number = (fiber.actualDuration: any); - if (fiber.alternate === null || fiber.alternate.child !== fiber.child) { + if (alternate === null || alternate.child !== fiber.child) { for (let child = fiber.child; child !== null; child = child.sibling) { selfTime -= (child.actualDuration: any); } @@ -200,6 +203,36 @@ export function logComponentRender( : 'error'; const debugTask = fiber._debugTask; if (__DEV__ && debugTask) { + const props = fiber.memoizedProps; + if ( + props !== null && + alternate !== null && + alternate.memoizedProps !== props + ) { + // If this is an update, we'll diff the props and emit which ones changed. + const properties: Array<[string, string]> = [resuableChangedPropsEntry]; + addObjectDiffToProperties( + alternate.memoizedProps, + props, + properties, + 0, + ); + if (properties.length > 1) { + reusableComponentOptions.start = startTime; + reusableComponentOptions.end = endTime; + reusableComponentDevToolDetails.color = color; + reusableComponentDevToolDetails.properties = properties; + debugTask.run( + // $FlowFixMe[method-unbinding] + performance.measure.bind( + performance, + name, + reusableComponentOptions, + ), + ); + return; + } + } debugTask.run( // $FlowFixMe[method-unbinding] console.timeStamp.bind( @@ -237,12 +270,7 @@ export function logComponentErrored( // Skip return; } - if ( - __DEV__ && - typeof performance !== 'undefined' && - // $FlowFixMe[method-unbinding] - typeof performance.measure === 'function' - ) { + if (__DEV__) { let debugTask: ?ConsoleTask = null; const properties: Array<[string, string]> = []; for (let i = 0; i < errors.length; i++) { @@ -267,10 +295,10 @@ export function logComponentErrored( properties.push(['Error', message]); } if (fiber.key !== null) { - addValueToProperties('key', fiber.key, properties, 0); + addValueToProperties('key', fiber.key, properties, 0, ''); } if (fiber.memoizedProps !== null) { - addObjectToProperties(fiber.memoizedProps, properties, 0); + addObjectToProperties(fiber.memoizedProps, properties, 0, ''); } if (debugTask == null) { // If the captured values don't have a debug task, fallback to the @@ -325,12 +353,7 @@ function logComponentEffectErrored( // Skip return; } - if ( - __DEV__ && - typeof performance !== 'undefined' && - // $FlowFixMe[method-unbinding] - typeof performance.measure === 'function' - ) { + if (__DEV__) { const properties: Array<[string, string]> = []; for (let i = 0; i < errors.length; i++) { const capturedValue = errors[i]; @@ -346,10 +369,10 @@ function logComponentEffectErrored( properties.push(['Error', message]); } if (fiber.key !== null) { - addValueToProperties('key', fiber.key, properties, 0); + addValueToProperties('key', fiber.key, properties, 0, ''); } if (fiber.memoizedProps !== null) { - addObjectToProperties(fiber.memoizedProps, properties, 0); + addObjectToProperties(fiber.memoizedProps, properties, 0, ''); } const options = { start: startTime, @@ -549,7 +572,8 @@ export function logBlockingStart( // If a blocking update was spawned within render or an effect, that's considered a cascading render. // If you have a second blocking update within the same event, that suggests multiple flushSync or // setState in a microtask which is also considered a cascade. - if (eventTime > 0 && eventType !== null) { + const eventEndTime = updateTime > 0 ? updateTime : renderStartTime; + if (eventTime > 0 && eventType !== null && eventEndTime > eventTime) { // Log the time from the event timeStamp until we called setState. const color = eventIsRepeat ? 'secondary-light' : 'warning'; if (__DEV__ && debugTask) { @@ -559,7 +583,7 @@ export function logBlockingStart( console, eventIsRepeat ? '' : 'Event: ' + eventType, eventTime, - updateTime > 0 ? updateTime : renderStartTime, + eventEndTime, currentTrack, LANES_TRACK_GROUP, color, @@ -569,14 +593,14 @@ export function logBlockingStart( console.timeStamp( eventIsRepeat ? '' : 'Event: ' + eventType, eventTime, - updateTime > 0 ? updateTime : renderStartTime, + eventEndTime, currentTrack, LANES_TRACK_GROUP, color, ); } } - if (updateTime > 0) { + if (updateTime > 0 && renderStartTime > updateTime) { // Log the time from when we called setState until we started rendering. const color = isSpawnedUpdate ? 'error' @@ -629,15 +653,11 @@ export function logTransitionStart( ): void { if (supportsUserTiming) { currentTrack = 'Transition'; - if (eventTime > 0 && eventType !== null) { + const eventEndTime = + startTime > 0 ? startTime : updateTime > 0 ? updateTime : renderStartTime; + if (eventTime > 0 && eventEndTime > eventTime && eventType !== null) { // Log the time from the event timeStamp until we started a transition. const color = eventIsRepeat ? 'secondary-light' : 'warning'; - const endTime = - startTime > 0 - ? startTime - : updateTime > 0 - ? updateTime - : renderStartTime; if (__DEV__ && debugTask) { debugTask.run( // $FlowFixMe[method-unbinding] @@ -645,7 +665,7 @@ export function logTransitionStart( console, eventIsRepeat ? '' : 'Event: ' + eventType, eventTime, - endTime, + eventEndTime, currentTrack, LANES_TRACK_GROUP, color, @@ -655,14 +675,15 @@ export function logTransitionStart( console.timeStamp( eventIsRepeat ? '' : 'Event: ' + eventType, eventTime, - endTime, + eventEndTime, currentTrack, LANES_TRACK_GROUP, color, ); } } - if (startTime > 0) { + const startEndTime = updateTime > 0 ? updateTime : renderStartTime; + if (startTime > 0 && startEndTime > startTime) { // Log the time from when we started an async transition until we called setState or started rendering. // TODO: Ideally this would use the debugTask of the startTransition call perhaps. if (__DEV__ && debugTask) { @@ -672,7 +693,7 @@ export function logTransitionStart( console, 'Action', startTime, - updateTime > 0 ? updateTime : renderStartTime, + startEndTime, currentTrack, LANES_TRACK_GROUP, 'primary-dark', @@ -682,14 +703,14 @@ export function logTransitionStart( console.timeStamp( 'Action', startTime, - updateTime > 0 ? updateTime : renderStartTime, + startEndTime, currentTrack, LANES_TRACK_GROUP, 'primary-dark', ); } } - if (updateTime > 0) { + if (updateTime > 0 && renderStartTime > updateTime) { // Log the time from when we called setState until we started rendering. if (__DEV__ && debugTask) { debugTask.run( @@ -815,12 +836,7 @@ export function logRecoveredRenderPhase( hydrationFailed: boolean, ): void { if (supportsUserTiming) { - if ( - __DEV__ && - typeof performance !== 'undefined' && - // $FlowFixMe[method-unbinding] - typeof performance.measure === 'function' - ) { + if (__DEV__) { const properties: Array<[string, string]> = []; for (let i = 0; i < recoverableErrors.length; i++) { const capturedValue = recoverableErrors[i]; @@ -939,12 +955,7 @@ export function logCommitErrored( passive: boolean, ): void { if (supportsUserTiming) { - if ( - __DEV__ && - typeof performance !== 'undefined' && - // $FlowFixMe[method-unbinding] - typeof performance.measure === 'function' - ) { + if (__DEV__) { const properties: Array<[string, string]> = []; for (let i = 0; i < errors.length; i++) { const capturedValue = errors[i]; @@ -997,8 +1008,6 @@ export function logCommitPhase( return; } if (supportsUserTiming) { - reusableLaneOptions.start = startTime; - reusableLaneOptions.end = endTime; console.timeStamp( 'Commit', startTime, diff --git a/packages/shared/ReactPerformanceTrackProperties.js b/packages/shared/ReactPerformanceTrackProperties.js index 8b5f980856b8e..0f7d9677de0a8 100644 --- a/packages/shared/ReactPerformanceTrackProperties.js +++ b/packages/shared/ReactPerformanceTrackProperties.js @@ -53,11 +53,12 @@ export function addObjectToProperties( object: Object, properties: Array<[string, string]>, indent: number, + prefix: string, ): void { for (const key in object) { if (hasOwnProperty.call(object, key) && key[0] !== '_') { const value = object[key]; - addValueToProperties(key, value, properties, indent); + addValueToProperties(key, value, properties, indent, prefix); } } } @@ -67,6 +68,7 @@ export function addValueToProperties( value: mixed, properties: Array<[string, string]>, indent: number, + prefix: string, ): void { let desc; switch (typeof value) { @@ -94,11 +96,11 @@ export function addValueToProperties( break; } properties.push([ - '\xa0\xa0'.repeat(indent) + propertyName, + prefix + '\xa0\xa0'.repeat(indent) + propertyName, '<' + typeName, ]); if (key !== null) { - addValueToProperties('key', key, properties, indent + 1); + addValueToProperties('key', key, properties, indent + 1, prefix); } let hasChildren = false; for (const propKey in props) { @@ -118,6 +120,7 @@ export function addValueToProperties( props[propKey], properties, indent + 1, + prefix, ); } } @@ -137,10 +140,19 @@ export function addValueToProperties( desc = JSON.stringify(array); break; } else if (kind === ENTRIES_ARRAY) { - properties.push(['\xa0\xa0'.repeat(indent) + propertyName, '']); + properties.push([ + prefix + '\xa0\xa0'.repeat(indent) + propertyName, + '', + ]); for (let i = 0; i < array.length; i++) { const entry = array[i]; - addValueToProperties(entry[0], entry[1], properties, indent + 1); + addValueToProperties( + entry[0], + entry[1], + properties, + indent + 1, + prefix, + ); } return; } @@ -152,11 +164,11 @@ export function addValueToProperties( } } properties.push([ - '\xa0\xa0'.repeat(indent) + propertyName, + prefix + '\xa0\xa0'.repeat(indent) + propertyName, objectName === 'Object' ? (indent < 3 ? '' : '\u2026') : objectName, ]); if (indent < 3) { - addObjectToProperties(value, properties, indent + 1); + addObjectToProperties(value, properties, indent + 1, prefix); } return; } @@ -184,5 +196,128 @@ export function addValueToProperties( // eslint-disable-next-line react-internal/safe-string-coercion desc = String(value); } - properties.push(['\xa0\xa0'.repeat(indent) + propertyName, desc]); + properties.push([prefix + '\xa0\xa0'.repeat(indent) + propertyName, desc]); +} + +const REMOVED = '\u2013\xa0'; +const ADDED = '+\xa0'; +const UNCHANGED = '\u2007\xa0'; + +export function addObjectDiffToProperties( + prev: Object, + next: Object, + properties: Array<[string, string]>, + indent: number, +): void { + // Note: We diff even non-owned properties here but things that are shared end up just the same. + // If a property is added or removed, we just emit the property name and omit the value it had. + // Mainly for performance. We need to minimize to only relevant information. + for (const key in prev) { + if (!(key in next)) { + properties.push([REMOVED + '\xa0\xa0'.repeat(indent) + key, '\u2026']); + } + } + for (const key in next) { + if (key in prev) { + const prevValue = prev[key]; + const nextValue = next[key]; + if (prevValue !== nextValue) { + if (indent === 0 && key === 'children') { + // Omit any change inside the top level children prop since it's expected to change + // with any change to children of the component and their props will be logged + // elsewhere but still mark it as a cause of render. + const line = '\xa0\xa0'.repeat(indent) + key; + properties.push([REMOVED + line, '\u2026'], [ADDED + line, '\u2026']); + continue; + } + if (indent >= 3) { + // Just fallthrough to print the two values if we're deep. + // This will skip nested properties of the objects. + } else if ( + typeof prevValue === 'object' && + typeof nextValue === 'object' && + prevValue !== null && + nextValue !== null && + prevValue.$$typeof === nextValue.$$typeof + ) { + if (nextValue.$$typeof === REACT_ELEMENT_TYPE) { + if ( + prevValue.type === nextValue.type && + prevValue.key === nextValue.key + ) { + // If the only thing that has changed is the props of a nested element, then + // we omit the props because it is likely to be represented as a diff elsewhere. + const typeName = + getComponentNameFromType(nextValue.type) || '\u2026'; + const line = '\xa0\xa0'.repeat(indent) + key; + const desc = '<' + typeName + ' \u2026 />'; + properties.push([REMOVED + line, desc], [ADDED + line, desc]); + continue; + } + } else { + // $FlowFixMe[method-unbinding] + const prevKind = Object.prototype.toString.call(prevValue); + // $FlowFixMe[method-unbinding] + const nextKind = Object.prototype.toString.call(nextValue); + if ( + prevKind === nextKind && + (nextKind === '[object Object]' || nextKind === '[object Array]') + ) { + // Diff nested object + const entry = [ + UNCHANGED + '\xa0\xa0'.repeat(indent) + key, + nextKind === '[object Array]' ? 'Array' : '', + ]; + properties.push(entry); + const prevLength = properties.length; + addObjectDiffToProperties( + prevValue, + nextValue, + properties, + indent + 1, + ); + if (prevLength === properties.length) { + // Nothing notably changed inside the nested object. So this is only a change in reference + // equality. Let's note it. + entry[1] = + 'Referentially unequal but deeply equal objects. Consider memoization.'; + } + continue; + } + } + } else if ( + typeof prevValue === 'function' && + typeof nextValue === 'function' && + prevValue.name === nextValue.name && + prevValue.length === nextValue.length + ) { + // $FlowFixMe[method-unbinding] + const prevSrc = Function.prototype.toString.call(prevValue); + // $FlowFixMe[method-unbinding] + const nextSrc = Function.prototype.toString.call(nextValue); + if (prevSrc === nextSrc) { + // This looks like it might be the same function but different closures. + let desc; + if (nextValue.name === '') { + desc = '() => {}'; + } else { + desc = nextValue.name + '() {}'; + } + properties.push([ + UNCHANGED + '\xa0\xa0'.repeat(indent) + key, + desc + + ' Referentially unequal function closure. Consider memoization.', + ]); + continue; + } + } + + // Otherwise, emit the change in property and the values. + addValueToProperties(key, prevValue, properties, indent, REMOVED); + addValueToProperties(key, nextValue, properties, indent, ADDED); + } + } else { + properties.push([ADDED + '\xa0\xa0'.repeat(indent) + key, '\u2026']); + } + } }