From 3ea9417781b79aad356fd8e31ea9dc0042df43cd Mon Sep 17 00:00:00 2001 From: Brian Vaughn Date: Tue, 16 Jun 2020 15:16:15 -0400 Subject: [PATCH] Re-enabled DebugTracing feature for old reconciler fork (#19142) It was temporarily removed by @sebmarkbage via PR #18697. Newly re-added tracing is simplified, since the lane(s) data type does not require the (lossy) conversion between priority and expiration time values. @sebmarkbage mentioned that he removed this because it might get in the way of his planned discrete/sync refactor. I'm not sure if that concern still applies, but just in case- I have only re-added it to the old reconciler fork for now. --- packages/react-reconciler/src/DebugTracing.js | 29 +++--- .../src/ReactFiberClassComponent.old.js | 31 ++++++- .../src/ReactFiberHooks.old.js | 17 +++- .../src/ReactFiberThrow.old.js | 13 ++- .../src/ReactFiberWorkLoop.old.js | 88 ++++++++++++++++++- .../__tests__/DebugTracing-test.internal.js | 54 ++++++------ .../shared/forks/ReactFeatureFlags.www.js | 4 +- 7 files changed, 189 insertions(+), 47 deletions(-) diff --git a/packages/react-reconciler/src/DebugTracing.js b/packages/react-reconciler/src/DebugTracing.js index 5ecb696b575da..075a705f03bd3 100644 --- a/packages/react-reconciler/src/DebugTracing.js +++ b/packages/react-reconciler/src/DebugTracing.js @@ -7,6 +7,7 @@ * @flow */ +import type {Lane, Lanes} from './ReactFiberLane'; import type {Wakeable} from 'shared/ReactTypes'; import {enableDebugTracing} from 'shared/ReactFeatureFlags'; @@ -17,6 +18,10 @@ let nativeConsoleLog: null | Function = null; const pendingGroupArgs: Array = []; let printedGroupIndex: number = -1; +function formatLanes(laneOrLanes: Lane | Lanes): string { + return '0b' + (laneOrLanes: any).toString(2).padStart(31, '0'); +} + function group(...groupArgs): void { pendingGroupArgs.push(groupArgs); @@ -57,11 +62,11 @@ function log(...logArgs): void { const REACT_LOGO_STYLE = 'background-color: #20232a; color: #61dafb; padding: 0 2px;'; -export function logCommitStarted(priorityLabel: string): void { +export function logCommitStarted(lanes: Lanes): void { if (__DEV__) { if (enableDebugTracing) { group( - `%c⚛️%c commit%c (priority: ${priorityLabel})`, + `%c⚛️%c commit%c (${formatLanes(lanes)})`, REACT_LOGO_STYLE, '', 'font-weight: normal;', @@ -128,11 +133,11 @@ export function logComponentSuspended( } } -export function logLayoutEffectsStarted(priorityLabel: string): void { +export function logLayoutEffectsStarted(lanes: Lanes): void { if (__DEV__) { if (enableDebugTracing) { group( - `%c⚛️%c layout effects%c (priority: ${priorityLabel})`, + `%c⚛️%c layout effects%c (${formatLanes(lanes)})`, REACT_LOGO_STYLE, '', 'font-weight: normal;', @@ -149,11 +154,11 @@ export function logLayoutEffectsStopped(): void { } } -export function logPassiveEffectsStarted(priorityLabel: string): void { +export function logPassiveEffectsStarted(lanes: Lanes): void { if (__DEV__) { if (enableDebugTracing) { group( - `%c⚛️%c passive effects%c (priority: ${priorityLabel})`, + `%c⚛️%c passive effects%c (${formatLanes(lanes)})`, REACT_LOGO_STYLE, '', 'font-weight: normal;', @@ -170,11 +175,11 @@ export function logPassiveEffectsStopped(): void { } } -export function logRenderStarted(priorityLabel: string): void { +export function logRenderStarted(lanes: Lanes): void { if (__DEV__) { if (enableDebugTracing) { group( - `%c⚛️%c render%c (priority: ${priorityLabel})`, + `%c⚛️%c render%c (${formatLanes(lanes)})`, REACT_LOGO_STYLE, '', 'font-weight: normal;', @@ -193,12 +198,12 @@ export function logRenderStopped(): void { export function logForceUpdateScheduled( componentName: string, - priorityLabel: string, + lane: Lane, ): void { if (__DEV__) { if (enableDebugTracing) { log( - `%c⚛️%c ${componentName} forced update %c(priority: ${priorityLabel})`, + `%c⚛️%c ${componentName} forced update %c(${formatLanes(lane)})`, REACT_LOGO_STYLE, 'color: #db2e1f; font-weight: bold;', '', @@ -209,13 +214,13 @@ export function logForceUpdateScheduled( export function logStateUpdateScheduled( componentName: string, - priorityLabel: string, + lane: Lane, payloadOrAction: any, ): void { if (__DEV__) { if (enableDebugTracing) { log( - `%c⚛️%c ${componentName} updated state %c(priority: ${priorityLabel})`, + `%c⚛️%c ${componentName} updated state %c(${formatLanes(lane)})`, REACT_LOGO_STYLE, 'color: #01a252; font-weight: bold;', '', diff --git a/packages/react-reconciler/src/ReactFiberClassComponent.old.js b/packages/react-reconciler/src/ReactFiberClassComponent.old.js index 329e9cb9bb89e..175f8fd246b8c 100644 --- a/packages/react-reconciler/src/ReactFiberClassComponent.old.js +++ b/packages/react-reconciler/src/ReactFiberClassComponent.old.js @@ -16,6 +16,7 @@ import {Update, Snapshot} from './ReactSideEffectTags'; import { debugRenderPhaseSideEffectsForStrictMode, disableLegacyContext, + enableDebugTracing, warnAboutDeprecatedLifecycles, } from 'shared/ReactFeatureFlags'; import ReactStrictModeWarnings from './ReactStrictModeWarnings.old'; @@ -27,7 +28,7 @@ import invariant from 'shared/invariant'; import {REACT_CONTEXT_TYPE, REACT_PROVIDER_TYPE} from 'shared/ReactSymbols'; import {resolveDefaultProps} from './ReactFiberLazyComponent.old'; -import {StrictMode} from './ReactTypeOfMode'; +import {DebugTracingMode, StrictMode} from './ReactTypeOfMode'; import { enqueueUpdate, @@ -55,6 +56,7 @@ import { scheduleUpdateOnFiber, } from './ReactFiberWorkLoop.old'; import {requestCurrentSuspenseConfig} from './ReactFiberSuspenseConfig'; +import {logForceUpdateScheduled, logStateUpdateScheduled} from './DebugTracing'; import {disableLogs, reenableLogs} from 'shared/ConsolePatchingDev'; @@ -203,6 +205,15 @@ const classComponentUpdater = { enqueueUpdate(fiber, update); scheduleUpdateOnFiber(fiber, lane, eventTime); + + if (__DEV__) { + if (enableDebugTracing) { + if (fiber.mode & DebugTracingMode) { + const name = getComponentName(fiber.type) || 'Unknown'; + logStateUpdateScheduled(name, lane, payload); + } + } + } }, enqueueReplaceState(inst, payload, callback) { const fiber = getInstance(inst); @@ -223,6 +234,15 @@ const classComponentUpdater = { enqueueUpdate(fiber, update); scheduleUpdateOnFiber(fiber, lane, eventTime); + + if (__DEV__) { + if (enableDebugTracing) { + if (fiber.mode & DebugTracingMode) { + const name = getComponentName(fiber.type) || 'Unknown'; + logStateUpdateScheduled(name, lane, payload); + } + } + } }, enqueueForceUpdate(inst, callback) { const fiber = getInstance(inst); @@ -242,6 +262,15 @@ const classComponentUpdater = { enqueueUpdate(fiber, update); scheduleUpdateOnFiber(fiber, lane, eventTime); + + if (__DEV__) { + if (enableDebugTracing) { + if (fiber.mode & DebugTracingMode) { + const name = getComponentName(fiber.type) || 'Unknown'; + logForceUpdateScheduled(name, lane); + } + } + } }, }; diff --git a/packages/react-reconciler/src/ReactFiberHooks.old.js b/packages/react-reconciler/src/ReactFiberHooks.old.js index 771d91f62b78a..44522a725966d 100644 --- a/packages/react-reconciler/src/ReactFiberHooks.old.js +++ b/packages/react-reconciler/src/ReactFiberHooks.old.js @@ -24,9 +24,12 @@ import type {FiberRoot} from './ReactInternalTypes'; import type {OpaqueIDType} from './ReactFiberHostConfig'; import ReactSharedInternals from 'shared/ReactSharedInternals'; -import {enableNewReconciler} from 'shared/ReactFeatureFlags'; +import { + enableDebugTracing, + enableNewReconciler, +} from 'shared/ReactFeatureFlags'; -import {NoMode, BlockingMode} from './ReactTypeOfMode'; +import {NoMode, BlockingMode, DebugTracingMode} from './ReactTypeOfMode'; import { NoLane, NoLanes, @@ -83,6 +86,7 @@ import { warnAboutMultipleRenderersDEV, } from './ReactMutableSource.old'; import {getIsRendering} from './ReactCurrentFiber'; +import {logStateUpdateScheduled} from './DebugTracing'; const {ReactCurrentDispatcher, ReactCurrentBatchConfig} = ReactSharedInternals; @@ -1737,6 +1741,15 @@ function dispatchAction( } scheduleUpdateOnFiber(fiber, lane, eventTime); } + + if (__DEV__) { + if (enableDebugTracing) { + if (fiber.mode & DebugTracingMode) { + const name = getComponentName(fiber.type) || 'Unknown'; + logStateUpdateScheduled(name, lane, action); + } + } + } } export const ContextOnlyDispatcher: Dispatcher = { diff --git a/packages/react-reconciler/src/ReactFiberThrow.old.js b/packages/react-reconciler/src/ReactFiberThrow.old.js index ebe7e61c1afe0..2d273b0b72c97 100644 --- a/packages/react-reconciler/src/ReactFiberThrow.old.js +++ b/packages/react-reconciler/src/ReactFiberThrow.old.js @@ -30,7 +30,8 @@ import { LifecycleEffectMask, } from './ReactSideEffectTags'; import {shouldCaptureSuspense} from './ReactFiberSuspenseComponent.old'; -import {NoMode, BlockingMode} from './ReactTypeOfMode'; +import {NoMode, BlockingMode, DebugTracingMode} from './ReactTypeOfMode'; +import {enableDebugTracing} from 'shared/ReactFeatureFlags'; import {createCapturedValue} from './ReactCapturedValue'; import { enqueueCapturedUpdate, @@ -53,6 +54,7 @@ import { pingSuspendedRoot, } from './ReactFiberWorkLoop.old'; import {logCapturedError} from './ReactFiberErrorLogger'; +import {logComponentSuspended} from './DebugTracing'; import { SyncLane, @@ -189,6 +191,15 @@ function throwException( // This is a wakeable. const wakeable: Wakeable = (value: any); + if (__DEV__) { + if (enableDebugTracing) { + if (sourceFiber.mode & DebugTracingMode) { + const name = getComponentName(sourceFiber.type) || 'Unknown'; + logComponentSuspended(name, wakeable); + } + } + } + if ((sourceFiber.mode & BlockingMode) === NoMode) { // Reset the memoizedState to what it was before we attempted // to render it. diff --git a/packages/react-reconciler/src/ReactFiberWorkLoop.old.js b/packages/react-reconciler/src/ReactFiberWorkLoop.old.js index a1a12b66ce219..0ccca00ae8c3e 100644 --- a/packages/react-reconciler/src/ReactFiberWorkLoop.old.js +++ b/packages/react-reconciler/src/ReactFiberWorkLoop.old.js @@ -26,6 +26,7 @@ import { enableSchedulerTracing, warnAboutUnmockedScheduler, deferRenderPhaseUpdateToNextBatch, + enableDebugTracing, } from 'shared/ReactFeatureFlags'; import ReactSharedInternals from 'shared/ReactSharedInternals'; import invariant from 'shared/invariant'; @@ -45,6 +46,16 @@ import { flushSyncCallbackQueue, scheduleSyncCallback, } from './SchedulerWithReactIntegration.old'; +import { + logCommitStarted, + logCommitStopped, + logLayoutEffectsStarted, + logLayoutEffectsStopped, + logPassiveEffectsStarted, + logPassiveEffectsStopped, + logRenderStarted, + logRenderStopped, +} from './DebugTracing'; // The scheduler is imported here *only* to detect whether it's been mocked import * as Scheduler from 'scheduler'; @@ -1444,6 +1455,12 @@ function renderRootSync(root: FiberRoot, lanes: Lanes) { const prevInteractions = pushInteractions(root); + if (__DEV__) { + if (enableDebugTracing) { + logRenderStarted(lanes); + } + } + do { try { workLoopSync(); @@ -1469,6 +1486,12 @@ function renderRootSync(root: FiberRoot, lanes: Lanes) { ); } + if (__DEV__) { + if (enableDebugTracing) { + logRenderStopped(); + } + } + // Set this to null to indicate there's no in-progress render. workInProgressRoot = null; workInProgressRootRenderLanes = NoLanes; @@ -1499,6 +1522,12 @@ function renderRootConcurrent(root: FiberRoot, lanes: Lanes) { const prevInteractions = pushInteractions(root); + if (__DEV__) { + if (enableDebugTracing) { + logRenderStarted(lanes); + } + } + do { try { workLoopConcurrent(); @@ -1515,6 +1544,12 @@ function renderRootConcurrent(root: FiberRoot, lanes: Lanes) { popDispatcher(prevDispatcher); executionContext = prevExecutionContext; + if (__DEV__) { + if (enableDebugTracing) { + logRenderStopped(); + } + } + // Check if the tree has completed. if (workInProgress !== null) { // Still work remaining. @@ -1785,6 +1820,15 @@ function commitRoot(root) { } function commitRootImpl(root, renderPriorityLevel) { + const finishedWork = root.finishedWork; + const lanes = root.finishedLanes; + + if (__DEV__) { + if (enableDebugTracing) { + logCommitStarted(lanes); + } + } + do { // `flushPassiveEffects` will call `flushSyncUpdateQueue` at the end, which // means `flushPassiveEffects` will sometimes result in additional @@ -1801,9 +1845,13 @@ function commitRootImpl(root, renderPriorityLevel) { 'Should not already be working.', ); - const finishedWork = root.finishedWork; - const lanes = root.finishedLanes; if (finishedWork === null) { + if (__DEV__) { + if (enableDebugTracing) { + logCommitStopped(); + } + } + return null; } root.finishedWork = null; @@ -2088,6 +2136,12 @@ function commitRootImpl(root, renderPriorityLevel) { } if ((executionContext & LegacyUnbatchedContext) !== NoContext) { + if (__DEV__) { + if (enableDebugTracing) { + logCommitStopped(); + } + } + // This is a legacy edge case. We just committed the initial mount of // a ReactDOM.render-ed root inside of batchedUpdates. The commit fired // synchronously, but layout updates should be deferred until the end @@ -2098,6 +2152,12 @@ function commitRootImpl(root, renderPriorityLevel) { // If layout work was scheduled, flush it now. flushSyncCallbackQueue(); + if (__DEV__) { + if (enableDebugTracing) { + logCommitStopped(); + } + } + return null; } @@ -2222,6 +2282,12 @@ function commitMutationEffects(root: FiberRoot, renderPriorityLevel) { } function commitLayoutEffects(root: FiberRoot, committedLanes: Lanes) { + if (__DEV__) { + if (enableDebugTracing) { + logLayoutEffectsStarted(committedLanes); + } + } + // TODO: Should probably move the bulk of this function to commitWork. while (nextEffect !== null) { setCurrentDebugFiberInDEV(nextEffect); @@ -2240,6 +2306,12 @@ function commitLayoutEffects(root: FiberRoot, committedLanes: Lanes) { resetCurrentDebugFiberInDEV(); nextEffect = nextEffect.nextEffect; } + + if (__DEV__) { + if (enableDebugTracing) { + logLayoutEffectsStopped(); + } + } } export function flushPassiveEffects() { @@ -2321,6 +2393,12 @@ function flushPassiveEffectsImpl() { 'Cannot flush passive effects while already rendering.', ); + if (__DEV__) { + if (enableDebugTracing) { + logPassiveEffectsStarted(lanes); + } + } + if (__DEV__) { isFlushingPassiveEffects = true; } @@ -2477,6 +2555,12 @@ function flushPassiveEffectsImpl() { isFlushingPassiveEffects = false; } + if (__DEV__) { + if (enableDebugTracing) { + logPassiveEffectsStopped(); + } + } + executionContext = prevExecutionContext; flushSyncCallbackQueue(); diff --git a/packages/react-reconciler/src/__tests__/DebugTracing-test.internal.js b/packages/react-reconciler/src/__tests__/DebugTracing-test.internal.js index 99d6c4237f26e..14960c36811c0 100644 --- a/packages/react-reconciler/src/__tests__/DebugTracing-test.internal.js +++ b/packages/react-reconciler/src/__tests__/DebugTracing-test.internal.js @@ -85,9 +85,9 @@ describe('DebugTracing', () => { ); expect(logs).toEqual([ - 'group: ⚛️ render (priority: immediate)', + 'group: ⚛️ render (0b0000000000000000000000000000001)', 'log: ⚛️ Example suspended', - 'groupEnd: ⚛️ render (priority: immediate)', + 'groupEnd: ⚛️ render (0b0000000000000000000000000000001)', ]); logs.splice(0); @@ -119,9 +119,9 @@ describe('DebugTracing', () => { expect(Scheduler).toFlushUntilNextPaint([]); expect(logs).toEqual([ - 'group: ⚛️ render (priority: normal)', + 'group: ⚛️ render (0b0000000000000000000001000000000)', 'log: ⚛️ Example suspended', - 'groupEnd: ⚛️ render (priority: normal)', + 'groupEnd: ⚛️ render (0b0000000000000000000001000000000)', ]); logs.splice(0); @@ -156,11 +156,11 @@ describe('DebugTracing', () => { expect(Scheduler).toFlushUntilNextPaint([]); expect(logs).toEqual([ - 'group: ⚛️ commit (priority: normal)', - 'group: ⚛️ layout effects (priority: immediate)', - 'log: ⚛️ Example updated state (priority: immediate)', - 'groupEnd: ⚛️ layout effects (priority: immediate)', - 'groupEnd: ⚛️ commit (priority: normal)', + 'group: ⚛️ commit (0b0000000000000000000001000000000)', + 'group: ⚛️ layout effects (0b0000000000000000000001000000000)', + 'log: ⚛️ Example updated state (0b0000000000000000000000000000001)', + 'groupEnd: ⚛️ layout effects (0b0000000000000000000001000000000)', + 'groupEnd: ⚛️ commit (0b0000000000000000000001000000000)', ]); }); @@ -192,10 +192,10 @@ describe('DebugTracing', () => { }).toErrorDev('Cannot update during an existing state transition'); expect(logs).toEqual([ - 'group: ⚛️ render (priority: normal)', - 'log: ⚛️ Example updated state (priority: normal)', - 'log: ⚛️ Example updated state (priority: normal)', - 'groupEnd: ⚛️ render (priority: normal)', + 'group: ⚛️ render (0b0000000000000000000001000000000)', + 'log: ⚛️ Example updated state (0b0000000000000000000010000000000)', + 'log: ⚛️ Example updated state (0b0000000000000000000010000000000)', + 'groupEnd: ⚛️ render (0b0000000000000000000001000000000)', ]); }); @@ -223,11 +223,11 @@ describe('DebugTracing', () => { expect(Scheduler).toFlushUntilNextPaint([]); expect(logs).toEqual([ - 'group: ⚛️ commit (priority: normal)', - 'group: ⚛️ layout effects (priority: immediate)', - 'log: ⚛️ Example updated state (priority: immediate)', - 'groupEnd: ⚛️ layout effects (priority: immediate)', - 'groupEnd: ⚛️ commit (priority: normal)', + 'group: ⚛️ commit (0b0000000000000000000001000000000)', + 'group: ⚛️ layout effects (0b0000000000000000000001000000000)', + 'log: ⚛️ Example updated state (0b0000000000000000000000000000001)', + 'groupEnd: ⚛️ layout effects (0b0000000000000000000001000000000)', + 'groupEnd: ⚛️ commit (0b0000000000000000000001000000000)', ]); }); @@ -250,9 +250,9 @@ describe('DebugTracing', () => { ); }); expect(logs).toEqual([ - 'group: ⚛️ passive effects (priority: normal)', - 'log: ⚛️ Example updated state (priority: normal)', - 'groupEnd: ⚛️ passive effects (priority: normal)', + 'group: ⚛️ passive effects (0b0000000000000000000001000000000)', + 'log: ⚛️ Example updated state (0b0000000000000000000010000000000)', + 'groupEnd: ⚛️ passive effects (0b0000000000000000000001000000000)', ]); }); @@ -275,10 +275,10 @@ describe('DebugTracing', () => { ); }); expect(logs).toEqual([ - 'group: ⚛️ render (priority: normal)', - 'log: ⚛️ Example updated state (priority: normal)', - 'log: ⚛️ Example updated state (priority: normal)', // debugRenderPhaseSideEffectsForStrictMode - 'groupEnd: ⚛️ render (priority: normal)', + 'group: ⚛️ render (0b0000000000000000000001000000000)', + 'log: ⚛️ Example updated state (0b0000000000000000000010000000000)', + 'log: ⚛️ Example updated state (0b0000000000000000000010000000000)', // debugRenderPhaseSideEffectsForStrictMode + 'groupEnd: ⚛️ render (0b0000000000000000000001000000000)', ]); }); @@ -303,9 +303,9 @@ describe('DebugTracing', () => { expect(Scheduler).toFlushUntilNextPaint([]); expect(logs).toEqual([ - 'group: ⚛️ render (priority: normal)', + 'group: ⚛️ render (0b0000000000000000000001000000000)', 'log: Hello from user code', - 'groupEnd: ⚛️ render (priority: normal)', + 'groupEnd: ⚛️ render (0b0000000000000000000001000000000)', ]); }); diff --git a/packages/shared/forks/ReactFeatureFlags.www.js b/packages/shared/forks/ReactFeatureFlags.www.js index ad64100da2fcc..657c2508443b5 100644 --- a/packages/shared/forks/ReactFeatureFlags.www.js +++ b/packages/shared/forks/ReactFeatureFlags.www.js @@ -78,8 +78,8 @@ export const enableModernEventSystem = true; // to the correct value. export const enableNewReconciler = __VARIANT__; -// TODO: This does not currently exist in the Lanes implementation. -export const enableDebugTracing = false; +// TODO: This does not currently exist in the new reconciler fork. +export const enableDebugTracing = !__VARIANT__; // Flow magic to verify the exports of this file match the original version. // eslint-disable-next-line no-unused-vars