Skip to content

Record "actual" times for all Fibers within a Profiler tree #12891

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
wants to merge 6 commits into from
Closed
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
41 changes: 33 additions & 8 deletions packages/react-reconciler/src/ReactFiber.js
Original file line number Diff line number Diff line change
Expand Up @@ -152,8 +152,30 @@ 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,

// Batch ID groups profile timings for a given commit.
// This allows durations to acculate across interrupts or yields,
// And reset between commits.
// This field is only set when the enableProfilerTimer flag is enabled.
profilerCommitBatchId?: 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
Expand Down Expand Up @@ -211,6 +233,9 @@ function FiberNode(
this.alternate = null;

if (enableProfilerTimer) {
this.actualDuration = 0;
this.actualStartTime = 0;
this.profilerCommitBatchId = 0;
this.selfBaseTime = 0;
this.treeBaseTime = 0;
}
Expand Down Expand Up @@ -310,6 +335,10 @@ export function createWorkInProgress(
workInProgress.ref = current.ref;

if (enableProfilerTimer) {
// We intentionally do not copy the following attributes:
// actualDuration, actualStartTime, profilerCommitBatchId
// This would interfere with accumulating render times after interruptions.

workInProgress.selfBaseTime = current.selfBaseTime;
workInProgress.treeBaseTime = current.treeBaseTime;
}
Expand Down Expand Up @@ -460,13 +489,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;
}
Expand Down Expand Up @@ -541,6 +563,9 @@ export function assignFiberPropertiesInDEV(
target.expirationTime = source.expirationTime;
target.alternate = source.alternate;
if (enableProfilerTimer) {
target.actualDuration = source.actualDuration;
target.actualStartTime = source.actualStartTime;
target.profilerCommitBatchId = source.profilerCommitBatchId;
target.selfBaseTime = source.selfBaseTime;
target.treeBaseTime = source.treeBaseTime;
}
Expand Down
18 changes: 7 additions & 11 deletions packages/react-reconciler/src/ReactFiberBeginWork.js
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down Expand Up @@ -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) {
Expand Down Expand Up @@ -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?
Expand All @@ -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
Expand Down
8 changes: 2 additions & 6 deletions packages/react-reconciler/src/ReactFiberCommitWork.js
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}
Expand Down
11 changes: 8 additions & 3 deletions packages/react-reconciler/src/ReactFiberCompleteWork.js
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -489,9 +497,6 @@ function completeWork(
case Mode:
return null;
case Profiler:
if (enableProfilerTimer) {
recordElapsedActualRenderTime(workInProgress);
}
return null;
case HostPortal:
popHostContainer(workInProgress);
Expand Down
13 changes: 13 additions & 0 deletions packages/react-reconciler/src/ReactFiberScheduler.js
Original file line number Diff line number Diff line change
Expand Up @@ -104,8 +104,10 @@ import {popProvider} from './ReactFiberNewContext';
import {popHostContext, popHostContainer} from './ReactFiberHostContext';
import {
checkActualRenderTimeStackEmpty,
incrementCommitBatchId,
pauseActualRenderTimerIfRunning,
recordCommitTime,
recordElapsedActualRenderTime,
recordElapsedBaseRenderTimeIfRunning,
resetActualRenderTimer,
resumeActualRenderTimerIfPaused,
Expand Down Expand Up @@ -311,6 +313,10 @@ if (__DEV__ && replayFailedUnitOfWorkWithInvokeGuardedCallback) {
clearCaughtError();

if (enableProfilerTimer) {
if (failedUnitOfWork.mode & ProfileMode) {
recordElapsedActualRenderTime(failedUnitOfWork);
}

// Stop "base" render timer again (after the re-thrown error).
stopBaseRenderTimerIfRunning();
}
Expand Down Expand Up @@ -573,6 +579,13 @@ function commitRoot(finishedWork: Fiber): ExpirationTime {
stopCommitSnapshotEffectsTimer();

if (enableProfilerTimer) {
// Batch ID groups profile timings for a given commit.
// This allows durations to acculate across interrupts or yields,
// And reset between commits.
incrementCommitBatchId();

// Mark the current commit time to be shared by all Profilers in this batch.
// This enables them to be grouped later.
recordCommitTime();
}

Expand Down
23 changes: 15 additions & 8 deletions packages/react-reconciler/src/ReactFiberUnwindWork.js
Original file line number Diff line number Diff line change
Expand Up @@ -20,7 +20,6 @@ import {
HostComponent,
HostPortal,
ContextProvider,
Profiler,
TimeoutComponent,
} from 'shared/ReactTypeOfWork';
import {
Expand All @@ -34,6 +33,7 @@ import {
enableProfilerTimer,
enableSuspense,
} from 'shared/ReactFeatureFlags';
import {ProfileMode} from './ReactTypeOfMode';

import {createCapturedValue} from './ReactCapturedValue';
import {
Expand Down Expand Up @@ -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);
Expand Down Expand Up @@ -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);
Expand All @@ -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;
}
Expand Down
34 changes: 25 additions & 9 deletions packages/react-reconciler/src/ReactProfilerTimer.js
Original file line number Diff line number Diff line change
Expand Up @@ -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';
Expand All @@ -17,6 +18,7 @@ import {now} from './ReactFiberHostConfig';
export type ProfilerTimer = {
checkActualRenderTimeStackEmpty(): void,
getCommitTime(): number,
incrementCommitBatchId(): void,
markActualRenderTimeStarted(fiber: Fiber): void,
pauseActualRenderTimerIfRunning(): void,
recordElapsedActualRenderTime(fiber: Fiber): void,
Expand All @@ -29,11 +31,16 @@ export type ProfilerTimer = {
};

let commitTime: number = 0;
let commitBatchId: number = 0;

function getCommitTime(): number {
return commitTime;
}

function incrementCommitBatchId(): void {
commitBatchId++;
}

function recordCommitTime(): void {
if (!enableProfilerTimer) {
return;
Expand Down Expand Up @@ -76,9 +83,15 @@ function markActualRenderTimeStarted(fiber: Fiber): void {
if (__DEV__) {
fiberStack.push(fiber);
}
const stateNode = fiber.stateNode;
stateNode.elapsedPauseTimeAtStart = totalElapsedPauseTime;
stateNode.startTime = now();

if (fiber.profilerCommitBatchId !== commitBatchId) {
fiber.profilerCommitBatchId = commitBatchId;
fiber.actualDuration = 0;
}

fiber.actualDuration =
now() - ((fiber.actualDuration: any): number) - totalElapsedPauseTime;
fiber.actualStartTime = now();
}

function pauseActualRenderTimerIfRunning(): void {
Expand All @@ -95,13 +108,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 {
Expand Down Expand Up @@ -166,6 +181,7 @@ function stopBaseRenderTimerIfRunning(): void {
export {
checkActualRenderTimeStackEmpty,
getCommitTime,
incrementCommitBatchId,
markActualRenderTimeStarted,
pauseActualRenderTimerIfRunning,
recordCommitTime,
Expand Down
26 changes: 25 additions & 1 deletion packages/react/src/__tests__/ReactProfiler-test.internal.js
Original file line number Diff line number Diff line change
Expand Up @@ -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(
<React.unstable_Profiler id="test" onRender={callback}>
<AdvanceTime byAmount={4} />
</React.unstable_Profiler>,
);

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', () => {
Expand Down Expand Up @@ -576,7 +598,9 @@ describe('Profiler', () => {
</React.unstable_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.
Expand Down