diff --git a/fixtures/tracing/test.html b/fixtures/tracing/test.html new file mode 100644 index 0000000000000..df09e7b62d017 --- /dev/null +++ b/fixtures/tracing/test.html @@ -0,0 +1,21 @@ + + + + + Test tracing UMD + + + +
+ + + + + + + + diff --git a/fixtures/tracing/test.js b/fixtures/tracing/test.js new file mode 100644 index 0000000000000..619d60df84ddb --- /dev/null +++ b/fixtures/tracing/test.js @@ -0,0 +1,103 @@ +const {createElement, Component, Placeholder} = React; +const {unstable_createRoot: createRoot} = ReactDOM; +const { + unstable_subscribe: subscribe, + unstable_trace: trace, + unstable_wrap: wrap, +} = SchedulerTracing; + +const createLogger = (backgroundColor, color, enabled) => ( + message, + ...args +) => { + if (enabled === false) return; + console.groupCollapsed( + `%c${message}`, + `background-color: ${backgroundColor}; color: ${color}; padding: 2px 4px;`, + ...args + ); + console.log( + new Error('stack').stack + .split('\n') + .slice(2) + .join('\n') + ); + console.groupEnd(); +}; + +window.log = { + app: createLogger('#37474f', '#fff'), + interaction: createLogger('#6a1b9a', '#fff'), + react: createLogger('#ff5722', '#fff'), + tracing: createLogger('#2962ff', '#fff'), + work: createLogger('#e1bee7', '#000'), +}; + +// Fake suspense +const resolvedValues = {}; +const read = key => { + if (!resolvedValues[key]) { + log.app(`Suspending for "${key}" ...`); + throw new Promise( + wrap(resolve => { + setTimeout( + wrap(() => { + log.app(`Loaded "${key}" ...`); + resolvedValues[key] = true; + resolve(key); + }), + 1000 + ); + }) + ); + } + return key; +}; + +const TestApp = () => + createElement( + Placeholder, + {delayMs: 100, fallback: createElement(PlaceholderText)}, + createElement(SuspendingChild, {text: 'foo'}), + createElement(SuspendingChild, {text: 'bar'}), + createElement(SuspendingChild, {text: 'baz'}) + ); + +const PlaceholderText = () => 'Loading ...'; + +const SuspendingChild = ({text}) => { + const resolvedValue = read(text); + return resolvedValue; +}; + +subscribe({ + onInteractionScheduledWorkCompleted: interaction => + log.interaction( + 'onInteractionScheduledWorkCompleted', + JSON.stringify(interaction) + ), + onInteractionTraced: interaction => + log.interaction('onInteractionTraced', JSON.stringify(interaction)), + onWorkCanceled: interactions => + log.work('onWorkCanceled', JSON.stringify(Array.from(interactions))), + onWorkScheduled: interactions => + log.work('onWorkScheduled', JSON.stringify(Array.from(interactions))), + onWorkStarted: interactions => + log.work('onWorkStarted', JSON.stringify(Array.from(interactions))), + onWorkStopped: interactions => + log.work('onWorkStopped', JSON.stringify(Array.from(interactions))), +}); + +const element = document.getElementById('root'); +trace('initial_render', performance.now(), () => { + const root = createRoot(element); + const batch = root.createBatch(); + log.app('batch.render()'); + batch.render(createElement(TestApp)); + batch.then( + wrap(() => { + log.app('batch.commit()'); + batch.commit(); + }) + ); +}); diff --git a/packages/react-reconciler/src/ReactFiberBeginWork.js b/packages/react-reconciler/src/ReactFiberBeginWork.js index 48ab7bb04800b..e94ae8109781a 100644 --- a/packages/react-reconciler/src/ReactFiberBeginWork.js +++ b/packages/react-reconciler/src/ReactFiberBeginWork.js @@ -41,6 +41,7 @@ import { Update, Ref, } from 'shared/ReactSideEffectTags'; +import {captureWillSyncRenderPlaceholder} from './ReactFiberScheduler'; import ReactSharedInternals from 'shared/ReactSharedInternals'; import { enableGetDerivedStateFromCatch, @@ -48,6 +49,7 @@ import { debugRenderPhaseSideEffects, debugRenderPhaseSideEffectsForStrictMode, enableProfilerTimer, + enableSchedulerTracing, } from 'shared/ReactFeatureFlags'; import invariant from 'shared/invariant'; import getComponentName from 'shared/getComponentName'; @@ -825,6 +827,13 @@ function updatePlaceholderComponent( let nextDidTimeout; if (current !== null && workInProgress.updateQueue !== null) { + if (enableSchedulerTracing) { + // Handle special case of rendering a Placeholder for a sync, suspended tree. + // We flag this to properly trace and count interactions. + // Otherwise interaction pending count will be decremented too many times. + captureWillSyncRenderPlaceholder(); + } + // We're outside strict mode. Something inside this Placeholder boundary // suspended during the last commit. Switch to the placholder. workInProgress.updateQueue = null; diff --git a/packages/react-reconciler/src/ReactFiberScheduler.js b/packages/react-reconciler/src/ReactFiberScheduler.js index 62b99fafddbb1..d312e60be8eb5 100644 --- a/packages/react-reconciler/src/ReactFiberScheduler.js +++ b/packages/react-reconciler/src/ReactFiberScheduler.js @@ -260,7 +260,8 @@ let interruptedBy: Fiber | null = null; // Do not decrement interaction counts in the event of suspense timeouts. // This would lead to prematurely calling the interaction-complete hook. -let suspenseDidTimeout: boolean = false; +// Instead we wait until the suspended promise has resolved. +let nextRenderIncludesTimedOutPlaceholder: boolean = false; let stashedWorkInProgressProperties; let replayUnitOfWork; @@ -566,31 +567,11 @@ function commitRoot(root: FiberRoot, finishedWork: Fiber): void { markCommittedPriorityLevels(root, earliestRemainingTimeBeforeCommit); let prevInteractions: Set = (null: any); - let committedInteractions: Array = enableSchedulerTracing - ? [] - : (null: any); if (enableSchedulerTracing) { // Restore any pending interactions at this point, // So that cascading work triggered during the render phase will be accounted for. prevInteractions = __interactionsRef.current; __interactionsRef.current = root.memoizedInteractions; - - // We are potentially finished with the current batch of interactions. - // So we should clear them out of the pending interaction map. - // We do this at the start of commit in case cascading work is scheduled by commit phase lifecycles. - // In that event, interaction data may be added back into the pending map for a future commit. - // We also store the interactions we are about to commit so that we can notify subscribers after we're done. - // These are stored as an Array rather than a Set, - // Because the same interaction may be pending for multiple expiration times, - // In which case it's important that we decrement the count the right number of times after finishing. - root.pendingInteractionMap.forEach( - (scheduledInteractions, scheduledExpirationTime) => { - if (scheduledExpirationTime <= committedExpirationTime) { - committedInteractions.push(...Array.from(scheduledInteractions)); - root.pendingInteractionMap.delete(scheduledExpirationTime); - } - }, - ); } // Reset this to null before calling lifecycles @@ -789,27 +770,41 @@ function commitRoot(root: FiberRoot, finishedWork: Fiber): void { unhandledError = error; } } finally { - // Don't update interaction counts if we're frozen due to suspense. - // In this case, we can skip the completed-work check entirely. - if (!suspenseDidTimeout) { - // Now that we're done, check the completed batch of interactions. - // If no more work is outstanding for a given interaction, - // We need to notify the subscribers that it's finished. - committedInteractions.forEach(interaction => { - interaction.__count--; - if (subscriber !== null && interaction.__count === 0) { - try { - subscriber.onInteractionScheduledWorkCompleted(interaction); - } catch (error) { - // It's not safe for commitRoot() to throw. - // Store the error for now and we'll re-throw in finishRendering(). - if (!hasUnhandledError) { - hasUnhandledError = true; - unhandledError = error; - } + if (!nextRenderIncludesTimedOutPlaceholder) { + // Clear completed interactions from the pending Map. + // Unless the render was suspended or cascading work was scheduled, + // In which case– leave pending interactions until the subsequent render. + const pendingInteractionMap = root.pendingInteractionMap; + pendingInteractionMap.forEach( + (scheduledInteractions, scheduledExpirationTime) => { + // Only decrement the pending interaction count if we're done. + // If there's still work at the current priority, + // That indicates that we are waiting for suspense data. + if ( + earliestRemainingTimeAfterCommit === NoWork || + scheduledExpirationTime < earliestRemainingTimeAfterCommit + ) { + pendingInteractionMap.delete(scheduledExpirationTime); + + scheduledInteractions.forEach(interaction => { + interaction.__count--; + + if (subscriber !== null && interaction.__count === 0) { + try { + subscriber.onInteractionScheduledWorkCompleted(interaction); + } catch (error) { + // It's not safe for commitRoot() to throw. + // Store the error for now and we'll re-throw in finishRendering(). + if (!hasUnhandledError) { + hasUnhandledError = true; + unhandledError = error; + } + } + } + }); } - } - }); + }, + ); } } } @@ -1174,14 +1169,6 @@ function renderRoot( const expirationTime = root.nextExpirationTimeToWorkOn; - let prevInteractions: Set = (null: any); - if (enableSchedulerTracing) { - // We're about to start new traced work. - // Restore pending interactions so cascading work triggered during the render phase will be accounted for. - prevInteractions = __interactionsRef.current; - __interactionsRef.current = root.memoizedInteractions; - } - // Check if we're starting from a fresh stack, or if we're resuming from // previously yielded work. if ( @@ -1201,6 +1188,11 @@ function renderRoot( root.pendingCommitExpirationTime = NoWork; if (enableSchedulerTracing) { + // Reset this flag once we start rendering a new root or at a new priority. + // This might indicate that suspended work has completed. + // If not, the flag will be reset. + nextRenderIncludesTimedOutPlaceholder = false; + // Determine which interactions this batch of work currently includes, // So that we can accurately attribute time spent working on it, // And so that cascading work triggered during the render phase will be associated with it. @@ -1244,6 +1236,14 @@ function renderRoot( } } + let prevInteractions: Set = (null: any); + if (enableSchedulerTracing) { + // We're about to start new traced work. + // Restore pending interactions so cascading work triggered during the render phase will be accounted for. + prevInteractions = __interactionsRef.current; + __interactionsRef.current = root.memoizedInteractions; + } + let didFatal = false; startWorkLoopTimer(nextUnitOfWork); @@ -1403,6 +1403,9 @@ function renderRoot( if (enableSuspense && !isExpired && nextLatestAbsoluteTimeoutMs !== -1) { // The tree was suspended. + if (enableSchedulerTracing) { + nextRenderIncludesTimedOutPlaceholder = true; + } const suspendedExpirationTime = expirationTime; markSuspendedPriorityLevel(root, suspendedExpirationTime); @@ -1600,6 +1603,7 @@ function retrySuspendedRoot( if (isPriorityLevelSuspended(root, suspendedTime)) { // Ping at the original level retryTime = suspendedTime; + markPingedPriorityLevel(root, retryTime); } else { // Placeholder already timed out. Compute a new expiration time @@ -1611,18 +1615,7 @@ function retrySuspendedRoot( scheduleWorkToRoot(fiber, retryTime); const rootExpirationTime = root.expirationTime; if (rootExpirationTime !== NoWork) { - if (enableSchedulerTracing) { - // Restore previous interactions so that new work is associated with them. - let prevInteractions = __interactionsRef.current; - __interactionsRef.current = root.memoizedInteractions; - // Because suspense timeouts do not decrement the interaction count, - // Continued suspense work should also not increment the count. - storeInteractionsForExpirationTime(root, rootExpirationTime, false); - requestWork(root, rootExpirationTime); - __interactionsRef.current = prevInteractions; - } else { - requestWork(root, rootExpirationTime); - } + requestWork(root, rootExpirationTime); } } } @@ -1677,49 +1670,6 @@ function scheduleWorkToRoot(fiber: Fiber, expirationTime): FiberRoot | null { return null; } -function storeInteractionsForExpirationTime( - root: FiberRoot, - expirationTime: ExpirationTime, - updateInteractionCounts: boolean, -): void { - if (!enableSchedulerTracing) { - return; - } - - const interactions = __interactionsRef.current; - if (interactions.size > 0) { - const pendingInteractions = root.pendingInteractionMap.get(expirationTime); - if (pendingInteractions != null) { - interactions.forEach(interaction => { - if (updateInteractionCounts && !pendingInteractions.has(interaction)) { - // Update the pending async work count for previously unscheduled interaction. - interaction.__count++; - } - - pendingInteractions.add(interaction); - }); - } else { - root.pendingInteractionMap.set(expirationTime, new Set(interactions)); - - // Update the pending async work count for the current interactions. - if (updateInteractionCounts) { - interactions.forEach(interaction => { - interaction.__count++; - }); - } - } - - const subscriber = __subscriberRef.current; - if (subscriber !== null) { - const threadID = computeThreadID( - expirationTime, - root.interactionThreadID, - ); - subscriber.onWorkScheduled(interactions, threadID); - } - } -} - function scheduleWork(fiber: Fiber, expirationTime: ExpirationTime) { recordScheduleUpdate(); @@ -1742,7 +1692,37 @@ function scheduleWork(fiber: Fiber, expirationTime: ExpirationTime) { } if (enableSchedulerTracing) { - storeInteractionsForExpirationTime(root, expirationTime, true); + const interactions = __interactionsRef.current; + if (interactions.size > 0) { + const pendingInteractionMap = root.pendingInteractionMap; + const pendingInteractions = pendingInteractionMap.get(expirationTime); + if (pendingInteractions != null) { + interactions.forEach(interaction => { + if (!pendingInteractions.has(interaction)) { + // Update the pending async work count for previously unscheduled interaction. + interaction.__count++; + } + + pendingInteractions.add(interaction); + }); + } else { + pendingInteractionMap.set(expirationTime, new Set(interactions)); + + // Update the pending async work count for the current interactions. + interactions.forEach(interaction => { + interaction.__count++; + }); + } + + const subscriber = __subscriberRef.current; + if (subscriber !== null) { + const threadID = computeThreadID( + expirationTime, + root.interactionThreadID, + ); + subscriber.onWorkScheduled(interactions, threadID); + } + } } if ( @@ -1935,9 +1915,8 @@ function onTimeout(root, finishedWork, suspendedExpirationTime) { if (enableSchedulerTracing) { // Don't update pending interaction counts for suspense timeouts, // Because we know we still need to do more work in this case. - suspenseDidTimeout = true; + nextRenderIncludesTimedOutPlaceholder = true; flushRoot(root, suspendedExpirationTime); - suspenseDidTimeout = false; } else { flushRoot(root, suspendedExpirationTime); } @@ -2508,6 +2487,12 @@ function flushControlled(fn: () => mixed): void { } } +function captureWillSyncRenderPlaceholder() { + if (enableSchedulerTracing) { + nextRenderIncludesTimedOutPlaceholder = true; + } +} + export { requestCurrentTime, computeExpirationForFiber, @@ -2530,4 +2515,5 @@ export { interactiveUpdates, flushInteractiveUpdates, computeUniqueAsyncExpiration, + captureWillSyncRenderPlaceholder, }; diff --git a/packages/react-reconciler/src/ReactFiberUnwindWork.js b/packages/react-reconciler/src/ReactFiberUnwindWork.js index 35885c8dd06f1..546af6c0e2138 100644 --- a/packages/react-reconciler/src/ReactFiberUnwindWork.js +++ b/packages/react-reconciler/src/ReactFiberUnwindWork.js @@ -36,6 +36,7 @@ import { import { enableGetDerivedStateFromCatch, enableSuspense, + enableSchedulerTracing, } from 'shared/ReactFeatureFlags'; import {StrictMode, AsyncMode} from './ReactTypeOfMode'; @@ -60,6 +61,7 @@ import { markLegacyErrorBoundaryAsFailed, isAlreadyFailedLegacyErrorBoundary, retrySuspendedRoot, + captureWillSyncRenderPlaceholder, } from './ReactFiberScheduler'; import {Sync} from './ReactFiberExpirationTime'; @@ -236,6 +238,13 @@ function throwException( if ((workInProgress.mode & StrictMode) === NoEffect) { workInProgress.effectTag |= UpdateEffect; + if (enableSchedulerTracing) { + // Handles the special case of unwinding a suspended sync render. + // We flag this to properly trace and count interactions. + // Otherwise interaction pending count will be decremented too many times. + captureWillSyncRenderPlaceholder(); + } + // Unmount the source fiber's children const nextChildren = null; reconcileChildren( diff --git a/packages/react/src/__tests__/ReactProfiler-test.internal.js b/packages/react/src/__tests__/ReactProfiler-test.internal.js index bfb4e19bf3650..802aa31c0dd22 100644 --- a/packages/react/src/__tests__/ReactProfiler-test.internal.js +++ b/packages/react/src/__tests__/ReactProfiler-test.internal.js @@ -46,7 +46,9 @@ function loadModules({ if (useNoopRenderer) { ReactNoop = require('react-noop-renderer'); + ReactTestRenderer = null; } else { + ReactNoop = null; ReactTestRenderer = require('react-test-renderer'); ReactTestRenderer.unstable_setNowImplementation(mockNow); } @@ -1229,11 +1231,13 @@ describe('Profiler', () => { const getWorkForReactThreads = mockFn => mockFn.mock.calls.filter(([interactions, threadID]) => threadID > 0); - beforeEach(() => { + function loadModulesForTracing(params) { jest.resetModules(); loadModules({ + enableSuspense: true, enableSchedulerTracing: true, + ...params, }); throwInOnInteractionScheduledWorkCompleted = false; @@ -1273,7 +1277,9 @@ describe('Profiler', () => { onWorkStarted, onWorkStopped, }); - }); + } + + beforeEach(() => loadModulesForTracing()); describe('error handling', () => { it('should cover errors thrown in onWorkScheduled', () => { @@ -1404,6 +1410,34 @@ describe('Profiler', () => { }); }); + it('should properly trace work scheduled during the begin render phase', () => { + const callback = jest.fn(); + let wrapped; + const Component = jest.fn(() => { + wrapped = SchedulerTracing.unstable_wrap(callback); + return null; + }); + + let interaction; + SchedulerTracing.unstable_trace('event', mockNow(), () => { + const interactions = SchedulerTracing.unstable_getCurrent(); + expect(interactions.size).toBe(1); + interaction = Array.from(interactions)[0]; + ReactTestRenderer.create(); + }); + + expect(Component).toHaveBeenCalledTimes(1); + expect(onInteractionScheduledWorkCompleted).not.toHaveBeenCalled(); + expect(callback).not.toHaveBeenCalled(); + + wrapped(); + expect(callback).toHaveBeenCalledTimes(1); + expect(onInteractionScheduledWorkCompleted).toHaveBeenCalledTimes(1); + expect( + onInteractionScheduledWorkCompleted, + ).toHaveBeenLastNotifiedOfInteraction(interaction); + }); + it('should associate traced events with their subsequent commits', () => { let instance = null; @@ -2115,24 +2149,12 @@ describe('Profiler', () => { ]); }); - it('traces both the temporary placeholder and the finished render for an interaction', async () => { - jest.resetModules(); - - loadModules({ - useNoopRenderer: true, - enableSuspense: true, - enableSchedulerTracing: true, - }); - - // Re-register since we've reloaded modules - SchedulerTracing.unstable_subscribe({ - onInteractionScheduledWorkCompleted, - onInteractionTraced, - onWorkCanceled, - onWorkScheduled, - onWorkStarted, - onWorkStopped, - }); + describe('suspense', () => { + let AsyncText; + let Text; + let TextResource; + let cache; + let resourcePromise; function awaitableAdvanceTimers(ms) { jest.advanceTimersByTime(ms); @@ -2142,124 +2164,500 @@ describe('Profiler', () => { }); } - const SimpleCacheProvider = require('simple-cache-provider'); - let cache; - function invalidateCache() { - cache = SimpleCacheProvider.createCache(invalidateCache); + function yieldForRenderer(value) { + if (ReactNoop) { + ReactNoop.yield(value); + } else { + ReactTestRenderer.unstable_yield(value); + } } - invalidateCache(); - const TextResource = SimpleCacheProvider.createResource( - ([text, ms = 0]) => { - return new Promise((resolve, reject) => { + + beforeEach(() => { + const SimpleCacheProvider = require('simple-cache-provider'); + function invalidateCache() { + cache = SimpleCacheProvider.createCache(invalidateCache); + } + invalidateCache(); + + resourcePromise = null; + + TextResource = SimpleCacheProvider.createResource(([text, ms = 0]) => { + resourcePromise = new Promise((resolve, reject) => setTimeout(() => { - ReactNoop.yield(`Promise resolved [${text}]`); + yieldForRenderer(`Promise resolved [${text}]`); resolve(text); - }, ms); - }); - }, - ([text, ms]) => text, - ); + }, ms), + ); + return resourcePromise; + }, ([text, ms]) => text); + + AsyncText = ({ms, text}) => { + try { + TextResource.read(cache, [text, ms]); + yieldForRenderer(`AsyncText [${text}]`); + return text; + } catch (promise) { + if (typeof promise.then === 'function') { + yieldForRenderer(`Suspend [${text}]`); + } else { + yieldForRenderer(`Error [${text}]`); + } + throw promise; + } + }; - function Text(props) { - ReactNoop.yield(props.text); - return ; - } + Text = ({text}) => { + yieldForRenderer(`Text [${text}]`); + return text; + }; + }); - function span(prop) { - return {type: 'span', children: [], prop}; - } + it('traces both the temporary placeholder and the finished render for an interaction', async () => { + loadModulesForTracing({useNoopRenderer: true}); + + const interaction = { + id: 0, + name: 'initial render', + timestamp: mockNow(), + }; + + const onRender = jest.fn(); + SchedulerTracing.unstable_trace(interaction.name, mockNow(), () => { + ReactNoop.render( + + }> + + + + , + ); + }); + + expect(onInteractionTraced).toHaveBeenCalledTimes(1); + expect(onInteractionTraced).toHaveBeenLastNotifiedOfInteraction( + interaction, + ); + expect(onInteractionScheduledWorkCompleted).not.toHaveBeenCalled(); + expect(getWorkForReactThreads(onWorkStarted)).toHaveLength(0); + expect(getWorkForReactThreads(onWorkStopped)).toHaveLength(0); + + expect(ReactNoop.flush()).toEqual([ + 'Suspend [Async]', + 'Text [Loading...]', + 'Text [Sync]', + ]); + // The update hasn't expired yet, so we commit nothing. + expect(ReactNoop.getChildren()).toEqual([]); + expect(onRender).not.toHaveBeenCalled(); + + // Advance both React's virtual time and Jest's timers by enough to expire + // the update, but not by enough to flush the suspending promise. + ReactNoop.expire(10000); + await awaitableAdvanceTimers(10000); + // No additional rendering work is required, since we already prepared + // the placeholder. + expect(ReactNoop.flushExpired()).toEqual([]); + // Should have committed the placeholder. + expect(ReactNoop.getChildren()).toEqual([ + {text: 'Loading...'}, + {text: 'Sync'}, + ]); + expect(onRender).toHaveBeenCalledTimes(1); + + let call = onRender.mock.calls[0]; + expect(call[0]).toEqual('test-profiler'); + expect(call[6]).toMatchInteractions( + ReactFeatureFlags.enableSchedulerTracing ? [interaction] : [], + ); + + expect(onInteractionTraced).toHaveBeenCalledTimes(1); + expect(onInteractionScheduledWorkCompleted).not.toHaveBeenCalled(); + + // Once the promise resolves, we render the suspended view + await awaitableAdvanceTimers(10000); + expect(ReactNoop.flush()).toEqual([ + 'Promise resolved [Async]', + 'AsyncText [Async]', + ]); + expect(ReactNoop.getChildren()).toEqual([ + {text: 'Async'}, + {text: 'Sync'}, + ]); + expect(onRender).toHaveBeenCalledTimes(2); + + call = onRender.mock.calls[1]; + expect(call[0]).toEqual('test-profiler'); + expect(call[6]).toMatchInteractions( + ReactFeatureFlags.enableSchedulerTracing ? [interaction] : [], + ); + + expect(onInteractionTraced).toHaveBeenCalledTimes(1); + expect(onInteractionScheduledWorkCompleted).toHaveBeenCalledTimes(1); + expect( + onInteractionScheduledWorkCompleted, + ).toHaveBeenLastNotifiedOfInteraction(interaction); + }); + + it('does not prematurely complete for suspended sync renders', async () => { + const interaction = { + id: 0, + name: 'initial render', + timestamp: mockNow(), + }; + + const onRender = jest.fn(); + SchedulerTracing.unstable_trace( + interaction.name, + interaction.timestamp, + () => { + ReactTestRenderer.create( + + }> + + + , + ); + }, + ); + + expect(onInteractionScheduledWorkCompleted).not.toHaveBeenCalled(); + + jest.runAllTimers(); + await resourcePromise; + + expect(onInteractionScheduledWorkCompleted).toHaveBeenCalledTimes(1); + expect( + onInteractionScheduledWorkCompleted, + ).toHaveBeenLastNotifiedOfInteraction(interaction); + }); + + it('traces cascading work after suspended sync renders', async () => { + let wrappedCascadingFn; + class AsyncComponentWithCascadingWork extends React.Component { + state = { + hasMounted: false, + }; + + componentDidMount() { + wrappedCascadingFn = SchedulerTracing.unstable_wrap(() => { + this.setState({hasMounted: true}); + }); + } - function AsyncText(props) { - const text = props.text; - try { - TextResource.read(cache, [props.text, props.ms]); - ReactNoop.yield(text); - return ; - } catch (promise) { - if (typeof promise.then === 'function') { - ReactNoop.yield(`Suspend! [${text}]`); - } else { - ReactNoop.yield(`Error! [${text}]`); + render() { + const {ms, text} = this.props; + TextResource.read(cache, [text, ms]); + return {this.state.hasMounted}; } - throw promise; } - } - const interaction = { - id: 0, - name: 'initial render', - timestamp: mockNow(), - }; + const interaction = { + id: 0, + name: 'initial render', + timestamp: mockNow(), + }; - const onRender = jest.fn(); - SchedulerTracing.unstable_trace(interaction.name, mockNow(), () => { - ReactNoop.render( - - }> - - - - , + const onRender = jest.fn(); + SchedulerTracing.unstable_trace( + interaction.name, + interaction.timestamp, + () => { + ReactTestRenderer.create( + + }> + + + , + ); + }, ); + + expect(onInteractionScheduledWorkCompleted).not.toHaveBeenCalled(); + + jest.runAllTimers(); + await resourcePromise; + + expect(onInteractionScheduledWorkCompleted).not.toHaveBeenCalled(); + + wrappedCascadingFn(); + + expect(onInteractionScheduledWorkCompleted).toHaveBeenCalledTimes(1); + expect( + onInteractionScheduledWorkCompleted, + ).toHaveBeenLastNotifiedOfInteraction(interaction); }); - expect(onInteractionTraced).toHaveBeenCalledTimes(1); - expect(onInteractionTraced).toHaveBeenLastNotifiedOfInteraction( - interaction, - ); - expect(onInteractionScheduledWorkCompleted).not.toHaveBeenCalled(); - expect(getWorkForReactThreads(onWorkStarted)).toHaveLength(0); - expect(getWorkForReactThreads(onWorkStopped)).toHaveLength(0); + it('does not prematurely complete for suspended renders that have exceeded their deadline', async () => { + const interaction = { + id: 0, + name: 'initial render', + timestamp: mockNow(), + }; - expect(ReactNoop.flush()).toEqual([ - 'Suspend! [Async]', - 'Loading...', - 'Sync', - ]); - // The update hasn't expired yet, so we commit nothing. - expect(ReactNoop.getChildren()).toEqual([]); - expect(onRender).not.toHaveBeenCalled(); + const onRender = jest.fn(); + let renderer; + SchedulerTracing.unstable_trace( + interaction.name, + interaction.timestamp, + () => { + renderer = ReactTestRenderer.create( + + }> + + + , + { + unstable_isAsync: true, + }, + ); + }, + ); - // Advance both React's virtual time and Jest's timers by enough to expire - // the update, but not by enough to flush the suspending promise. - ReactNoop.expire(10000); - await awaitableAdvanceTimers(10000); - // No additional rendering work is required, since we already prepared - // the placeholder. - expect(ReactNoop.flushExpired()).toEqual([]); - // Should have committed the placeholder. - expect(ReactNoop.getChildren()).toEqual([ - span('Loading...'), - span('Sync'), - ]); - expect(onRender).toHaveBeenCalledTimes(1); + advanceTimeBy(1500); + await awaitableAdvanceTimers(1500); - let call = onRender.mock.calls[0]; - expect(call[0]).toEqual('test-profiler'); - expect(call[6]).toMatchInteractions( - ReactFeatureFlags.enableSchedulerTracing ? [interaction] : [], - ); + expect(renderer).toFlushAll(['Suspend [loaded]', 'Text [loading]']); + expect(onInteractionScheduledWorkCompleted).not.toHaveBeenCalled(); - expect(onInteractionTraced).toHaveBeenCalledTimes(1); - expect(onInteractionScheduledWorkCompleted).not.toHaveBeenCalled(); + advanceTimeBy(2500); + await awaitableAdvanceTimers(2500); - // Once the promise resolves, we render the suspended view - await awaitableAdvanceTimers(10000); - expect(ReactNoop.flush()).toEqual(['Promise resolved [Async]', 'Async']); - expect(ReactNoop.getChildren()).toEqual([span('Async'), span('Sync')]); - expect(onRender).toHaveBeenCalledTimes(2); + expect(renderer).toFlushAll(['AsyncText [loaded]']); + expect(onInteractionScheduledWorkCompleted).toHaveBeenCalledTimes(1); + expect( + onInteractionScheduledWorkCompleted, + ).toHaveBeenLastNotifiedOfInteraction(interaction); + }); - call = onRender.mock.calls[1]; - expect(call[0]).toEqual('test-profiler'); - expect(call[6]).toMatchInteractions( - ReactFeatureFlags.enableSchedulerTracing ? [interaction] : [], - ); + it('decrements interaction count correctly if suspense loads before placeholder is shown', async () => { + const interaction = { + id: 0, + name: 'initial render', + timestamp: mockNow(), + }; - expect(onInteractionTraced).toHaveBeenCalledTimes(1); - expect(onInteractionScheduledWorkCompleted).toHaveBeenCalledTimes(1); - expect( - onInteractionScheduledWorkCompleted, - ).toHaveBeenLastNotifiedOfInteraction(interaction); + const onRender = jest.fn(); + let renderer; + SchedulerTracing.unstable_trace( + interaction.name, + interaction.timestamp, + () => { + renderer = ReactTestRenderer.create( + + }> + + + , + {unstable_isAsync: true}, + ); + }, + ); + renderer.unstable_flushAll(); + + expect(onInteractionScheduledWorkCompleted).not.toHaveBeenCalled(); + + jest.advanceTimersByTime(1000); + await resourcePromise; + renderer.unstable_flushAll(); + + expect(onInteractionScheduledWorkCompleted).toHaveBeenCalledTimes(1); + expect( + onInteractionScheduledWorkCompleted, + ).toHaveBeenLastNotifiedOfInteraction(interaction); + }); + + it('handles high-pri renderers between suspended and resolved (sync) trees', async () => { + const initialRenderInteraction = { + id: 0, + name: 'initial render', + timestamp: mockNow(), + }; + + const onRender = jest.fn(); + let renderer; + SchedulerTracing.unstable_trace( + initialRenderInteraction.name, + initialRenderInteraction.timestamp, + () => { + renderer = ReactTestRenderer.create( + + }> + + + + , + ); + }, + ); + expect(renderer.toJSON()).toEqual(['loading', 'initial']); + + expect(onInteractionScheduledWorkCompleted).not.toHaveBeenCalled(); + expect(onRender).toHaveBeenCalledTimes(2); // Sync null commit, placeholder commit + expect(onRender.mock.calls[0][6]).toMatchInteractions([ + initialRenderInteraction, + ]); + onRender.mockClear(); + + const highPriUpdateInteraction = { + id: 1, + name: 'hiPriUpdate', + timestamp: mockNow(), + }; + + const originalPromise = resourcePromise; + + renderer.unstable_flushSync(() => { + SchedulerTracing.unstable_trace( + highPriUpdateInteraction.name, + highPriUpdateInteraction.timestamp, + () => { + renderer.update( + + }> + + + + , + ); + }, + ); + }); + expect(renderer.toJSON()).toEqual(['loading', 'updated']); + + expect(onRender).toHaveBeenCalledTimes(2); // Sync null commit, placeholder commit + expect(onRender.mock.calls[0][6]).toMatchInteractions([ + initialRenderInteraction, + highPriUpdateInteraction, + ]); + onRender.mockClear(); + + expect(onInteractionScheduledWorkCompleted).not.toHaveBeenCalled(); + + advanceTimeBy(1000); + jest.advanceTimersByTime(1000); + await originalPromise; + expect(renderer.toJSON()).toEqual(['loaded', 'updated']); + + expect(onRender).toHaveBeenCalledTimes(2); + expect(onRender.mock.calls[0][6]).toMatchInteractions([ + initialRenderInteraction, + highPriUpdateInteraction, + ]); + + expect(onInteractionScheduledWorkCompleted).toHaveBeenCalledTimes(2); + expect( + onInteractionScheduledWorkCompleted.mock.calls[0][0], + ).toMatchInteraction(initialRenderInteraction); + expect( + onInteractionScheduledWorkCompleted.mock.calls[1][0], + ).toMatchInteraction(highPriUpdateInteraction); + }); + + it('handles high-pri renderers between suspended and resolved (async) trees', async () => { + const initialRenderInteraction = { + id: 0, + name: 'initial render', + timestamp: mockNow(), + }; + + const onRender = jest.fn(); + let renderer; + SchedulerTracing.unstable_trace( + initialRenderInteraction.name, + initialRenderInteraction.timestamp, + () => { + renderer = ReactTestRenderer.create( + + }> + + + + , + {unstable_isAsync: true}, + ); + }, + ); + expect(renderer).toFlushAll([ + 'Suspend [loaded]', + 'Text [loading]', + 'Text [initial]', + ]); + + expect(onInteractionScheduledWorkCompleted).not.toHaveBeenCalled(); + expect(onRender).not.toHaveBeenCalled(); + + advanceTimeBy(500); + jest.advanceTimersByTime(500); + + const highPriUpdateInteraction = { + id: 1, + name: 'hiPriUpdate', + timestamp: mockNow(), + }; + + const originalPromise = resourcePromise; + + renderer.unstable_flushSync(() => { + SchedulerTracing.unstable_trace( + highPriUpdateInteraction.name, + highPriUpdateInteraction.timestamp, + () => { + renderer.update( + + }> + + + + , + ); + }, + ); + }); + expect(renderer.toJSON()).toEqual(['loading', 'updated']); + + expect(onRender).toHaveBeenCalledTimes(1); + expect(onRender.mock.calls[0][6]).toMatchInteractions([ + highPriUpdateInteraction, + ]); + onRender.mockClear(); + + expect(onInteractionScheduledWorkCompleted).toHaveBeenCalledTimes(1); + expect( + onInteractionScheduledWorkCompleted, + ).toHaveBeenLastNotifiedOfInteraction(highPriUpdateInteraction); + + advanceTimeBy(500); + jest.advanceTimersByTime(500); + await originalPromise; + expect(renderer).toFlushAll(['AsyncText [loaded]']); + expect(renderer.toJSON()).toEqual(['loaded', 'updated']); + + expect(onRender).toHaveBeenCalledTimes(1); + expect(onRender.mock.calls[0][6]).toMatchInteractions([ + initialRenderInteraction, + ]); + + expect(onInteractionScheduledWorkCompleted).toHaveBeenCalledTimes(2); + expect( + onInteractionScheduledWorkCompleted, + ).toHaveBeenLastNotifiedOfInteraction(initialRenderInteraction); + }); }); }); }); diff --git a/packages/react/src/__tests__/ReactProfilerDOM-test.internal.js b/packages/react/src/__tests__/ReactProfilerDOM-test.internal.js new file mode 100644 index 0000000000000..07a7c54da63d8 --- /dev/null +++ b/packages/react/src/__tests__/ReactProfilerDOM-test.internal.js @@ -0,0 +1,174 @@ +/** + * Copyright (c) Facebook, Inc. and its affiliates. + * + * This source code is licensed under the MIT license found in the + * LICENSE file in the root directory of this source tree. + * + * @emails react-core + */ + +'use strict'; + +let React; +let ReactFeatureFlags; +let ReactDOM; +let SchedulerTracing; +let SimpleCacheProvider; + +function initEnvForAsyncTesting() { + // Boilerplate copied from ReactDOMRoot-test + // TODO pull this into helper method, reduce repetition. + const originalDateNow = Date.now; + global.Date.now = function() { + return originalDateNow(); + }; + global.requestAnimationFrame = function(cb) { + return setTimeout(() => { + cb(Date.now()); + }); + }; + const originalAddEventListener = global.addEventListener; + let postMessageCallback; + global.addEventListener = function(eventName, callback, useCapture) { + if (eventName === 'message') { + postMessageCallback = callback; + } else { + originalAddEventListener(eventName, callback, useCapture); + } + }; + global.postMessage = function(messageKey, targetOrigin) { + const postMessageEvent = {source: window, data: messageKey}; + if (postMessageCallback) { + postMessageCallback(postMessageEvent); + } + }; +} + +function loadModules() { + ReactFeatureFlags = require('shared/ReactFeatureFlags'); + ReactFeatureFlags.debugRenderPhaseSideEffects = false; + ReactFeatureFlags.debugRenderPhaseSideEffectsForStrictMode = false; + ReactFeatureFlags.enableProfilerTimer = true; + ReactFeatureFlags.enableSchedulerTracing = true; + ReactFeatureFlags.enableSuspense = true; + + React = require('react'); + SchedulerTracing = require('scheduler/tracing'); + ReactDOM = require('react-dom'); + SimpleCacheProvider = require('simple-cache-provider'); +} + +describe('ProfilerDOM', () => { + let TextResource; + let cache; + let resourcePromise; + let onInteractionScheduledWorkCompleted; + let onInteractionTraced; + + beforeEach(() => { + initEnvForAsyncTesting(); + loadModules(); + + onInteractionScheduledWorkCompleted = jest.fn(); + onInteractionTraced = jest.fn(); + + // Verify interaction subscriber methods are called as expected. + SchedulerTracing.unstable_subscribe({ + onInteractionScheduledWorkCompleted, + onInteractionTraced, + onWorkCanceled: () => {}, + onWorkScheduled: () => {}, + onWorkStarted: () => {}, + onWorkStopped: () => {}, + }); + + cache = SimpleCacheProvider.createCache(() => {}); + + resourcePromise = null; + + TextResource = SimpleCacheProvider.createResource(([text, ms = 0]) => { + resourcePromise = new Promise( + SchedulerTracing.unstable_wrap((resolve, reject) => { + setTimeout( + SchedulerTracing.unstable_wrap(() => { + resolve(text); + }), + ms, + ); + }), + ); + return resourcePromise; + }, ([text, ms]) => text); + }); + + const AsyncText = ({ms, text}) => { + TextResource.read(cache, [text, ms]); + return text; + }; + + const Text = ({text}) => text; + + it('should correctly trace interactions for async roots', async done => { + let batch, element, interaction; + + SchedulerTracing.unstable_trace('initial_event', performance.now(), () => { + const interactions = SchedulerTracing.unstable_getCurrent(); + expect(interactions.size).toBe(1); + interaction = Array.from(interactions)[0]; + + element = document.createElement('div'); + const root = ReactDOM.unstable_createRoot(element); + batch = root.createBatch(); + batch.render( + }> + + , + ); + batch.then( + SchedulerTracing.unstable_wrap(() => { + batch.commit(); + + expect(element.textContent).toBe('Loading...'); + expect(onInteractionTraced).toHaveBeenCalledTimes(1); + expect(onInteractionScheduledWorkCompleted).not.toHaveBeenCalled(); + + resourcePromise.then( + SchedulerTracing.unstable_wrap(() => { + jest.runAllTimers(); + + expect(element.textContent).toBe('Text'); + expect(onInteractionTraced).toHaveBeenCalledTimes(1); + expect( + onInteractionScheduledWorkCompleted, + ).not.toHaveBeenCalled(); + + // Evaluate in an unwrapped callback, + // Because trace/wrap won't decrement the count within the wrapped callback. + setImmediate(() => { + expect(onInteractionTraced).toHaveBeenCalledTimes(1); + expect( + onInteractionScheduledWorkCompleted, + ).toHaveBeenCalledTimes(1); + expect( + onInteractionScheduledWorkCompleted, + ).toHaveBeenLastNotifiedOfInteraction(interaction); + + expect(interaction.__count).toBe(0); + + done(); + }); + }), + ); + }), + ); + }); + + expect(onInteractionTraced).toHaveBeenCalledTimes(1); + expect(onInteractionTraced).toHaveBeenLastNotifiedOfInteraction( + interaction, + ); + expect(onInteractionScheduledWorkCompleted).not.toHaveBeenCalled(); + + jest.runAllTimers(); + }); +});