From 55787006710bd8ef89a01d60c4a9cfa58c71035d Mon Sep 17 00:00:00 2001 From: Brian Vaughn Date: Fri, 25 May 2018 14:51:13 -0700 Subject: [PATCH] Record "actual" times for all Fibers within a Profiler tree (alt) (#12910) * Moved actual time fields from Profiler stateNode to Fiber * Record actual time for all Fibers within a ProfileMode tree * Changed how profiler accumulates time This change gives up on accumulating time across renders of different priority, but in exchange- simplifies how the commit phase (reset) code works, and perhaps also makes the profiling code more compatible with future resuming behavior --- packages/react-reconciler/src/ReactFiber.js | 38 +++++++++++++++---- .../src/ReactFiberBeginWork.js | 18 ++++----- .../src/ReactFiberCommitWork.js | 8 +--- .../src/ReactFiberCompleteWork.js | 11 ++++-- .../src/ReactFiberScheduler.js | 7 ++++ .../src/ReactFiberUnwindWork.js | 23 +++++++---- .../src/ReactProfilerTimer.js | 22 ++++++----- .../__tests__/ReactProfiler-test.internal.js | 38 ++++++++++++++++--- 8 files changed, 114 insertions(+), 51 deletions(-) diff --git a/packages/react-reconciler/src/ReactFiber.js b/packages/react-reconciler/src/ReactFiber.js index d27a5b6a1313d..34ee91645d79f 100644 --- a/packages/react-reconciler/src/ReactFiber.js +++ b/packages/react-reconciler/src/ReactFiber.js @@ -152,8 +152,24 @@ export type Fiber = {| // memory if we need to. alternate: Fiber | null, - // Profiling metrics + // Time spent rendering this Fiber and its descendants for the current update. + // This tells us how well the tree makes use of sCU for memoization. + // This field is only set when the enableProfilerTimer flag is enabled. + actualDuration?: number, + + // If the Fiber is currently active in the "render" phase, + // This marks the time at which the work began. + // This field is only set when the enableProfilerTimer flag is enabled. + actualStartTime?: number, + + // Duration of the most recent render time for this Fiber. + // This value is not updated when we bailout for memoization purposes. + // This field is only set when the enableProfilerTimer flag is enabled. selfBaseTime?: number, + + // Sum of base times for all descedents of this Fiber. + // This value bubbles up during the "complete" phase. + // This field is only set when the enableProfilerTimer flag is enabled. treeBaseTime?: number, // Conceptual aliases @@ -211,6 +227,8 @@ function FiberNode( this.alternate = null; if (enableProfilerTimer) { + this.actualDuration = 0; + this.actualStartTime = 0; this.selfBaseTime = 0; this.treeBaseTime = 0; } @@ -295,6 +313,15 @@ export function createWorkInProgress( workInProgress.nextEffect = null; workInProgress.firstEffect = null; workInProgress.lastEffect = null; + + if (enableProfilerTimer) { + // We intentionally reset, rather than copy, actualDuration & actualStartTime. + // This prevents time from endlessly accumulating in new commits. + // This has the downside of resetting values for different priority renders, + // But works for yielding (the common case) and should support resuming. + workInProgress.actualDuration = 0; + workInProgress.actualStartTime = 0; + } } workInProgress.expirationTime = expirationTime; @@ -460,13 +487,6 @@ export function createFiberFromProfiler( const fiber = createFiber(Profiler, pendingProps, key, mode | ProfileMode); fiber.type = REACT_PROFILER_TYPE; fiber.expirationTime = expirationTime; - if (enableProfilerTimer) { - fiber.stateNode = { - elapsedPauseTimeAtStart: 0, - duration: 0, - startTime: 0, - }; - } return fiber; } @@ -541,6 +561,8 @@ export function assignFiberPropertiesInDEV( target.expirationTime = source.expirationTime; target.alternate = source.alternate; if (enableProfilerTimer) { + target.actualDuration = source.actualDuration; + target.actualStartTime = source.actualStartTime; target.selfBaseTime = source.selfBaseTime; target.treeBaseTime = source.treeBaseTime; } diff --git a/packages/react-reconciler/src/ReactFiberBeginWork.js b/packages/react-reconciler/src/ReactFiberBeginWork.js index ad1189d402032..135e85bb0ba6c 100644 --- a/packages/react-reconciler/src/ReactFiberBeginWork.js +++ b/packages/react-reconciler/src/ReactFiberBeginWork.js @@ -61,7 +61,7 @@ import { } from './ReactChildFiber'; import {processUpdateQueue} from './ReactUpdateQueue'; import {NoWork, Never} from './ReactFiberExpirationTime'; -import {AsyncMode, StrictMode} from './ReactTypeOfMode'; +import {AsyncMode, ProfileMode, StrictMode} from './ReactTypeOfMode'; import { shouldSetTextContent, shouldDeprioritizeSubtree, @@ -214,11 +214,6 @@ function updateMode(current, workInProgress) { function updateProfiler(current, workInProgress) { const nextProps = workInProgress.pendingProps; if (enableProfilerTimer) { - // Start render timer here and push start time onto queue - markActualRenderTimeStarted(workInProgress); - - // Let the "complete" phase know to stop the timer, - // And the scheduler to record the measured time. workInProgress.effectTag |= Update; } if (workInProgress.memoizedProps === nextProps) { @@ -1111,11 +1106,6 @@ function bailoutOnLowPriority(current, workInProgress) { case ContextProvider: pushProvider(workInProgress); break; - case Profiler: - if (enableProfilerTimer) { - markActualRenderTimeStarted(workInProgress); - } - break; } // TODO: What if this is currently in progress? // How can that happen? How is this not being cloned? @@ -1138,6 +1128,12 @@ function beginWork( workInProgress: Fiber, renderExpirationTime: ExpirationTime, ): Fiber | null { + if (enableProfilerTimer) { + if (workInProgress.mode & ProfileMode) { + markActualRenderTimeStarted(workInProgress); + } + } + if ( workInProgress.expirationTime === NoWork || workInProgress.expirationTime > renderExpirationTime diff --git a/packages/react-reconciler/src/ReactFiberCommitWork.js b/packages/react-reconciler/src/ReactFiberCommitWork.js index 8f5fa74a5c5b5..f9a3dce20044d 100644 --- a/packages/react-reconciler/src/ReactFiberCommitWork.js +++ b/packages/react-reconciler/src/ReactFiberCommitWork.js @@ -806,15 +806,11 @@ function commitWork(current: Fiber | null, finishedWork: Fiber): void { onRender( finishedWork.memoizedProps.id, current === null ? 'mount' : 'update', - finishedWork.stateNode.duration, + finishedWork.actualDuration, finishedWork.treeBaseTime, - finishedWork.stateNode.startTime, + finishedWork.actualStartTime, getCommitTime(), ); - - // Reset actualTime after successful commit. - // By default, we append to this time to account for errors and pauses. - finishedWork.stateNode.duration = 0; } return; } diff --git a/packages/react-reconciler/src/ReactFiberCompleteWork.js b/packages/react-reconciler/src/ReactFiberCompleteWork.js index 8ed630b82db25..d9b469c94d1bc 100644 --- a/packages/react-reconciler/src/ReactFiberCompleteWork.js +++ b/packages/react-reconciler/src/ReactFiberCompleteWork.js @@ -38,6 +38,7 @@ import { TimeoutComponent, } from 'shared/ReactTypeOfWork'; import {Placement, Ref, Update} from 'shared/ReactTypeOfSideEffect'; +import {ProfileMode} from './ReactTypeOfMode'; import invariant from 'fbjs/lib/invariant'; import { @@ -312,6 +313,13 @@ function completeWork( renderExpirationTime: ExpirationTime, ): Fiber | null { const newProps = workInProgress.pendingProps; + + if (enableProfilerTimer) { + if (workInProgress.mode & ProfileMode) { + recordElapsedActualRenderTime(workInProgress); + } + } + switch (workInProgress.tag) { case FunctionalComponent: return null; @@ -489,9 +497,6 @@ function completeWork( case Mode: return null; case Profiler: - if (enableProfilerTimer) { - recordElapsedActualRenderTime(workInProgress); - } return null; case HostPortal: popHostContainer(workInProgress); diff --git a/packages/react-reconciler/src/ReactFiberScheduler.js b/packages/react-reconciler/src/ReactFiberScheduler.js index 87f97dcc617bf..70bec86f55e4c 100644 --- a/packages/react-reconciler/src/ReactFiberScheduler.js +++ b/packages/react-reconciler/src/ReactFiberScheduler.js @@ -106,6 +106,7 @@ import { checkActualRenderTimeStackEmpty, pauseActualRenderTimerIfRunning, recordCommitTime, + recordElapsedActualRenderTime, recordElapsedBaseRenderTimeIfRunning, resetActualRenderTimer, resumeActualRenderTimerIfPaused, @@ -311,6 +312,10 @@ if (__DEV__ && replayFailedUnitOfWorkWithInvokeGuardedCallback) { clearCaughtError(); if (enableProfilerTimer) { + if (failedUnitOfWork.mode & ProfileMode) { + recordElapsedActualRenderTime(failedUnitOfWork); + } + // Stop "base" render timer again (after the re-thrown error). stopBaseRenderTimerIfRunning(); } @@ -573,6 +578,8 @@ function commitRoot(finishedWork: Fiber): ExpirationTime { stopCommitSnapshotEffectsTimer(); if (enableProfilerTimer) { + // Mark the current commit time to be shared by all Profilers in this batch. + // This enables them to be grouped later. recordCommitTime(); } diff --git a/packages/react-reconciler/src/ReactFiberUnwindWork.js b/packages/react-reconciler/src/ReactFiberUnwindWork.js index b4be270162dcc..19bb46bfa5a98 100644 --- a/packages/react-reconciler/src/ReactFiberUnwindWork.js +++ b/packages/react-reconciler/src/ReactFiberUnwindWork.js @@ -20,7 +20,6 @@ import { HostComponent, HostPortal, ContextProvider, - Profiler, TimeoutComponent, } from 'shared/ReactTypeOfWork'; import { @@ -34,6 +33,7 @@ import { enableProfilerTimer, enableSuspense, } from 'shared/ReactFeatureFlags'; +import {ProfileMode} from './ReactTypeOfMode'; import {createCapturedValue} from './ReactCapturedValue'; import { @@ -301,6 +301,12 @@ function unwindWork( renderIsExpired: boolean, renderExpirationTime: ExpirationTime, ) { + if (enableProfilerTimer) { + if (workInProgress.mode & ProfileMode) { + recordElapsedActualRenderTime(workInProgress); + } + } + switch (workInProgress.tag) { case ClassComponent: { popLegacyContextProvider(workInProgress); @@ -345,6 +351,14 @@ function unwindWork( } function unwindInterruptedWork(interruptedWork: Fiber) { + if (enableProfilerTimer) { + if (interruptedWork.mode & ProfileMode) { + // Resume in case we're picking up on work that was paused. + resumeActualRenderTimerIfPaused(); + recordElapsedActualRenderTime(interruptedWork); + } + } + switch (interruptedWork.tag) { case ClassComponent: { popLegacyContextProvider(interruptedWork); @@ -365,13 +379,6 @@ function unwindInterruptedWork(interruptedWork: Fiber) { case ContextProvider: popProvider(interruptedWork); break; - case Profiler: - if (enableProfilerTimer) { - // Resume in case we're picking up on work that was paused. - resumeActualRenderTimerIfPaused(); - recordElapsedActualRenderTime(interruptedWork); - } - break; default: break; } diff --git a/packages/react-reconciler/src/ReactProfilerTimer.js b/packages/react-reconciler/src/ReactProfilerTimer.js index bbe1c9bdeae19..7877d7d2977ac 100644 --- a/packages/react-reconciler/src/ReactProfilerTimer.js +++ b/packages/react-reconciler/src/ReactProfilerTimer.js @@ -9,6 +9,7 @@ import type {Fiber} from './ReactFiber'; +import getComponentName from 'shared/getComponentName'; import {enableProfilerTimer} from 'shared/ReactFeatureFlags'; import warning from 'fbjs/lib/warning'; @@ -76,9 +77,10 @@ function markActualRenderTimeStarted(fiber: Fiber): void { if (__DEV__) { fiberStack.push(fiber); } - const stateNode = fiber.stateNode; - stateNode.elapsedPauseTimeAtStart = totalElapsedPauseTime; - stateNode.startTime = now(); + + fiber.actualDuration = + now() - ((fiber.actualDuration: any): number) - totalElapsedPauseTime; + fiber.actualStartTime = now(); } function pauseActualRenderTimerIfRunning(): void { @@ -95,13 +97,15 @@ function recordElapsedActualRenderTime(fiber: Fiber): void { return; } if (__DEV__) { - warning(fiber === fiberStack.pop(), 'Unexpected Fiber popped.'); + warning( + fiber === fiberStack.pop(), + 'Unexpected Fiber (%s) popped.', + getComponentName(fiber), + ); } - const stateNode = fiber.stateNode; - stateNode.duration += - now() - - (totalElapsedPauseTime - stateNode.elapsedPauseTimeAtStart) - - stateNode.startTime; + + fiber.actualDuration = + now() - totalElapsedPauseTime - ((fiber.actualDuration: any): number); } function resetActualRenderTimer(): void { diff --git a/packages/react/src/__tests__/ReactProfiler-test.internal.js b/packages/react/src/__tests__/ReactProfiler-test.internal.js index 3e27588816fef..ccd3dc3be01a9 100644 --- a/packages/react/src/__tests__/ReactProfiler-test.internal.js +++ b/packages/react/src/__tests__/ReactProfiler-test.internal.js @@ -228,6 +228,28 @@ describe('Profiler', () => { expect(call[3]).toBe(10); // base time expect(call[4]).toBe(35); // start time expect(call[5]).toBe(45); // commit time + + callback.mockReset(); + + advanceTimeBy(20); // 45 -> 65 + + renderer.update( + + + , + ); + + expect(callback).toHaveBeenCalledTimes(1); + + [call] = callback.mock.calls; + + expect(call).toHaveLength(6); + expect(call[0]).toBe('test'); + expect(call[1]).toBe('update'); + expect(call[2]).toBe(4); // actual time + expect(call[3]).toBe(4); // base time + expect(call[4]).toBe(65); // start time + expect(call[5]).toBe(69); // commit time }); it('includes render times of nested Profilers in their parent times', () => { @@ -576,7 +598,9 @@ describe('Profiler', () => { , {unstable_isAsync: true}, ); - expect(renderer.unstable_flushThrough(['first'])).toEqual(['Yield:10']); + expect(renderer.unstable_flushThrough(['Yield:10'])).toEqual([ + 'Yield:10', + ]); expect(callback).toHaveBeenCalledTimes(0); // Simulate time moving forward while frame is paused. @@ -681,11 +705,12 @@ describe('Profiler', () => { }), ).toEqual(['Yield:11']); - // Verify that the actual time includes all three durations above. - // And the base time includes only the final rendered tree times. + // The actual time should include only the most recent render, + // Because this lets us avoid a lot of commit phase reset complexity. + // The base time includes only the final rendered tree times. expect(callback).toHaveBeenCalledTimes(1); call = callback.mock.calls[0]; - expect(call[2]).toBe(19); // actual time + expect(call[2]).toBe(11); // actual time expect(call[3]).toBe(11); // base time expect(call[4]).toBe(264); // start time expect(call[5]).toBe(275); // commit time @@ -772,12 +797,13 @@ describe('Profiler', () => { renderer.unstable_flushSync(() => second.setState({renderTime: 30})), ).toEqual(['SecondComponent:30', 'Yield:7']); - // Verify that the actual time includes time spent in the both renders so far (10ms and 37ms). + // The actual time should include only the most recent render (37ms), + // Because this lets us avoid a lot of commit phase reset complexity. // The base time should include the more recent times for the SecondComponent subtree, // As well as the original times for the FirstComponent subtree. expect(callback).toHaveBeenCalledTimes(1); call = callback.mock.calls[0]; - expect(call[2]).toBe(47); // actual time + expect(call[2]).toBe(37); // actual time expect(call[3]).toBe(42); // base time expect(call[4]).toBe(229); // start time expect(call[5]).toBe(266); // commit time