Skip to content

Profiler actualDuration bugfix #13313

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.

Sign up for GitHub

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

Merged
merged 4 commits into from
Aug 8, 2018
Merged

Profiler actualDuration bugfix #13313

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
523b27d
Simplified profiler actualDuration timing
Aug 2, 2018
6f996da
Changed bubbling logic after chatting out of band with Andrew
Aug 3, 2018
ae7e4fa
Replaced __PROFILE__ with feature-flag conditionals in test
Aug 6, 2018
ccc4f31
Updated test comment
Aug 6, 2018
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
5 changes: 3 additions & 2 deletions packages/react-reconciler/src/ReactFiber.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -162,6 +162,7 @@ export type Fiber = {|

// 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.
// It is reset to 0 each time we render and only updated when we don't bailout.
// This field is only set when the enableProfilerTimer flag is enabled.
actualDuration?: number,

Expand Down Expand Up @@ -238,7 +239,7 @@ function FiberNode(

if (enableProfilerTimer) {
this.actualDuration = 0;
this.actualStartTime = 0;
this.actualStartTime = -1;
this.selfBaseDuration = 0;
this.treeBaseDuration = 0;
}
Expand Down Expand Up @@ -330,7 +331,7 @@ export function createWorkInProgress(
// 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.actualStartTime = -1;
}
}

Expand Down
17 changes: 4 additions & 13 deletions packages/react-reconciler/src/ReactFiberBeginWork.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -62,7 +62,7 @@ import {
} from './ReactChildFiber';
import {processUpdateQueue} from './ReactUpdateQueue';
import {NoWork, Never} from './ReactFiberExpirationTime';
import {AsyncMode, ProfileMode, StrictMode} from './ReactTypeOfMode';
import {AsyncMode, StrictMode} from './ReactTypeOfMode';
import {
shouldSetTextContent,
shouldDeprioritizeSubtree,
Expand All @@ -75,10 +75,7 @@ import {
prepareToReadContext,
calculateChangedBits,
} from './ReactFiberNewContext';
import {
markActualRenderTimeStarted,
stopBaseRenderTimerIfRunning,
} from './ReactProfilerTimer';
import {stopProfilerTimerIfRunning} from './ReactProfilerTimer';
import {
getMaskedContext,
getUnmaskedContext,
Expand Down Expand Up @@ -379,7 +376,7 @@ function finishClassComponent(
nextChildren = null;

if (enableProfilerTimer) {
stopBaseRenderTimerIfRunning();
stopProfilerTimerIfRunning(workInProgress);
}
} else {
if (__DEV__) {
Expand Down Expand Up @@ -954,7 +951,7 @@ function bailoutOnAlreadyFinishedWork(

if (enableProfilerTimer) {
// Don't update "base" render times for bailouts.
stopBaseRenderTimerIfRunning();
stopProfilerTimerIfRunning(workInProgress);
}

// Check if the children have any pending work.
Expand Down Expand Up @@ -991,12 +988,6 @@ function beginWork(
workInProgress: Fiber,
renderExpirationTime: ExpirationTime,
): Fiber | null {
if (enableProfilerTimer) {
if (workInProgress.mode & ProfileMode) {
markActualRenderTimeStarted(workInProgress);
}
}

const updateExpirationTime = workInProgress.expirationTime;
if (
!hasLegacyContextChanged() &&
Expand Down
13 changes: 0 additions & 13 deletions packages/react-reconciler/src/ReactFiberCompleteWork.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -20,7 +20,6 @@ import type {
HostContext,
} from './ReactFiberHostConfig';

import {enableProfilerTimer} from 'shared/ReactFeatureFlags';
import {
IndeterminateComponent,
FunctionalComponent,
Expand All @@ -38,7 +37,6 @@ import {
PlaceholderComponent,
} from 'shared/ReactTypeOfWork';
import {Placement, Ref, Update} from 'shared/ReactTypeOfSideEffect';
import {ProfileMode} from './ReactTypeOfMode';
import invariant from 'shared/invariant';

import {
Expand All @@ -60,7 +58,6 @@ import {
getHostContext,
popHostContainer,
} from './ReactFiberHostContext';
import {recordElapsedActualRenderTime} from './ReactProfilerTimer';
import {
popContextProvider as popLegacyContextProvider,
popTopLevelContextObject as popTopLevelLegacyContextObject,
Expand Down Expand Up @@ -518,16 +515,6 @@ function completeWork(
);
}

if (enableProfilerTimer) {
if (workInProgress.mode & ProfileMode) {
// Don't record elapsed time unless the "complete" phase has succeeded.
// Certain renderers may error during this phase (i.e. ReactNative View/Text nesting validation).
// If an error occurs, we'll mark the time while unwinding.
// This simplifies the unwinding logic and ensures consistency.
recordElapsedActualRenderTime(workInProgress);
}
}

return null;
}

Expand Down
135 changes: 64 additions & 71 deletions packages/react-reconciler/src/ReactFiberScheduler.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -112,15 +112,9 @@ import {
import {popProvider, resetContextDependences} from './ReactFiberNewContext';
import {popHostContext, popHostContainer} from './ReactFiberHostContext';
import {
checkActualRenderTimeStackEmpty,
pauseActualRenderTimerIfRunning,
recordCommitTime,
recordElapsedActualRenderTime,
recordElapsedBaseRenderTimeIfRunning,
resetActualRenderTimerStackAfterFatalErrorInDev,
resumeActualRenderTimerIfPaused,
startBaseRenderTimer,
stopBaseRenderTimerIfRunning,
startProfilerTimer,
stopProfilerTimerIfRunningAndRecordDelta,
} from './ReactProfilerTimer';
import {
checkThatStackIsEmpty,
Expand Down Expand Up @@ -312,15 +306,6 @@ if (__DEV__ && replayFailedUnitOfWorkWithInvokeGuardedCallback) {
originalReplayError = null;
if (hasCaughtError()) {
clearCaughtError();

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

// Stop "base" render timer again (after the re-thrown error).
stopBaseRenderTimerIfRunning();
}
} else {
// If the begin phase did not fail the second time, set this pointer
// back to the original value.
Expand All @@ -336,12 +321,6 @@ function resetStack() {
if (nextUnitOfWork !== null) {
let interruptedWork = nextUnitOfWork.return;
while (interruptedWork !== null) {
if (enableProfilerTimer) {
if (interruptedWork.mode & ProfileMode) {
// Resume in case we're picking up on work that was paused.
resumeActualRenderTimerIfPaused(false);
}
}
unwindInterruptedWork(interruptedWork);
interruptedWork = interruptedWork.return;
}
Expand Down Expand Up @@ -691,17 +670,6 @@ function commitRoot(root: FiberRoot, finishedWork: Fiber): void {
}
}

if (enableProfilerTimer) {
if (__DEV__) {
if (nextRoot === null) {
// Only check this stack once we're done processing async work.
// This prevents a false positive that occurs after a batched commit,
// If there was in-progress async work before the commit.
checkActualRenderTimeStackEmpty();
}
}
}

isCommitting = false;
isWorking = false;
stopCommitLifeCyclesTimer();
Expand Down Expand Up @@ -741,9 +709,22 @@ function resetChildExpirationTime(

// Bubble up the earliest expiration time.
if (enableProfilerTimer && workInProgress.mode & ProfileMode) {
// We're in profiling mode. Let's use this same traversal to update the
// "base" render times.
// We're in profiling mode.
// Let's use this same traversal to update the render durations.
let actualDuration = workInProgress.actualDuration;
let treeBaseDuration = workInProgress.selfBaseDuration;

// When a fiber is cloned, its actualDuration is reset to 0.
// This value will only be updated if work is done on the fiber (i.e. it doesn't bailout).
// When work is done, it should bubble to the parent's actualDuration.
// If the fiber has not been cloned though, (meaning no work was done),
// Then this value will reflect the amount of time spent working on a previous render.
// In that case it should not bubble.
// We determine whether it was cloned by comparing the child pointer.
const shouldBubbleActualDurations =
workInProgress.alternate === null ||
workInProgress.child !== workInProgress.alternate.child;

let child = workInProgress.child;
while (child !== null) {
const childUpdateExpirationTime = child.expirationTime;
Expand All @@ -762,9 +743,13 @@ function resetChildExpirationTime(
) {
newChildExpirationTime = childChildExpirationTime;
}
if (shouldBubbleActualDurations) {
actualDuration += child.actualDuration;
}
treeBaseDuration += child.treeBaseDuration;
child = child.sibling;
}
workInProgress.actualDuration = actualDuration;
workInProgress.treeBaseDuration = treeBaseDuration;
} else {
let child = workInProgress.child;
Expand Down Expand Up @@ -811,11 +796,28 @@ function completeUnitOfWork(workInProgress: Fiber): Fiber | null {

if ((workInProgress.effectTag & Incomplete) === NoEffect) {
// This fiber completed.
nextUnitOfWork = completeWork(
current,
workInProgress,
nextRenderExpirationTime,
);
if (enableProfilerTimer) {
if (workInProgress.mode & ProfileMode) {
Copy link
Collaborator

@acdlite acdlite Aug 3, 2018 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nit: Can you combine the enableProfilerTimer check with these inner checks? Or do we not trust the build system to strip out the dead code?

Copy link
Contributor Author

@bvaughn bvaughn Aug 3, 2018 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nope, this is just something subjective I've done because it seems to read more clearly that the outer conditional is a feature flag. Happy to combine them if you have a preference.

To be fair, there's precedent for this in a lot of other places– but again, I don't feel strongly about it. If you do, I will change it.

startProfilerTimer(workInProgress);
}

nextUnitOfWork = completeWork(
current,
workInProgress,
nextRenderExpirationTime,
);

if (workInProgress.mode & ProfileMode) {
// Update render duration assuming we didn't error.
stopProfilerTimerIfRunningAndRecordDelta(workInProgress, false);
}
} else {
nextUnitOfWork = completeWork(
current,
workInProgress,
nextRenderExpirationTime,
);
}
let next = nextUnitOfWork;
stopWorkTimer(workInProgress);
resetChildExpirationTime(workInProgress, nextRenderExpirationTime);
Expand Down Expand Up @@ -886,6 +888,11 @@ function completeUnitOfWork(workInProgress: Fiber): Fiber | null {
return null;
}
} else {
if (workInProgress.mode & ProfileMode) {
// Record the render duration for the fiber that errored.
stopProfilerTimerIfRunningAndRecordDelta(workInProgress, false);
}

// This fiber did not complete because something threw. Pop values off
// the stack without entering the complete phase. If this is a boundary,
// capture values if possible.
Expand All @@ -908,6 +915,19 @@ function completeUnitOfWork(workInProgress: Fiber): Fiber | null {
ReactFiberInstrumentation.debugTool.onCompleteWork(workInProgress);
}

if (enableProfilerTimer) {
// Include the time spent working on failed children before continuing.
if (next.mode & ProfileMode) {
let actualDuration = next.actualDuration;
let child = next.child;
while (child !== null) {
actualDuration += child.actualDuration;
child = child.sibling;
}
next.actualDuration = actualDuration;
}
}

// If completing this work spawned new work, do that next. We'll come
// back here again.
// Since we're restarting, remove anything that is not a host effect
Expand Down Expand Up @@ -968,15 +988,14 @@ function performUnitOfWork(workInProgress: Fiber): Fiber | null {
let next;
if (enableProfilerTimer) {
if (workInProgress.mode & ProfileMode) {
startBaseRenderTimer();
startProfilerTimer(workInProgress);
}

next = beginWork(current, workInProgress, nextRenderExpirationTime);

if (workInProgress.mode & ProfileMode) {
// Update "base" time if the render wasn't bailed out on.
recordElapsedBaseRenderTimeIfRunning(workInProgress);
stopBaseRenderTimerIfRunning();
// Record the render duration assuming we didn't bailout (or error).
stopProfilerTimerIfRunningAndRecordDelta(workInProgress, true);
}
} else {
next = beginWork(current, workInProgress, nextRenderExpirationTime);
Expand Down Expand Up @@ -1017,12 +1036,6 @@ function workLoop(isYieldy) {
while (nextUnitOfWork !== null && !shouldYield()) {
nextUnitOfWork = performUnitOfWork(nextUnitOfWork);
}

if (enableProfilerTimer) {
// If we didn't finish, pause the "actual" render timer.
// We'll restart it when we resume work.
pauseActualRenderTimerIfRunning();
}
}
}

Expand Down Expand Up @@ -1068,11 +1081,6 @@ function renderRoot(
try {
workLoop(isYieldy);
} catch (thrownValue) {
if (enableProfilerTimer) {
// Stop "base" render timer in the event of an error.
stopBaseRenderTimerIfRunning();
}

if (nextUnitOfWork === null) {
// This is a fatal error.
didFatal = true;
Expand Down Expand Up @@ -1139,10 +1147,6 @@ function renderRoot(
// There was a fatal error.
if (__DEV__) {
resetStackAfterFatalErrorInDev();

// Reset the DEV fiber stack in case we're profiling roots.
// (We do this for profiling bulds when DevTools is detected.)
resetActualRenderTimerStackAfterFatalErrorInDev();
}
// `nextRoot` points to the in-progress root. A non-null value indicates
// that we're in the middle of an async render. Set it to null to indicate
Expand Down Expand Up @@ -1866,10 +1870,6 @@ function performWork(minExpirationTime: ExpirationTime, dl: Deadline | null) {
// the deadline.
findHighestPriorityRoot();

if (enableProfilerTimer) {
resumeActualRenderTimerIfPaused(minExpirationTime === Sync);
}

if (deadline !== null) {
recomputeCurrentRendererTime();
currentSchedulerTime = currentRendererTime;
Expand Down Expand Up @@ -1942,7 +1942,6 @@ function flushRoot(root: FiberRoot, expirationTime: ExpirationTime) {
performWorkOnRoot(root, expirationTime, true);
// Flush any sync work that was scheduled by lifecycles
performSyncWork();
pauseActualRenderTimerIfRunning();
}

function finishRendering() {
Expand Down Expand Up @@ -2044,12 +2043,6 @@ function performWorkOnRoot(
// There's no time left. Mark this root as complete. We'll come
// back and commit it later.
root.finishedWork = finishedWork;

if (enableProfilerTimer) {
// If we didn't finish, pause the "actual" render timer.
// We'll restart it when we resume work.
pauseActualRenderTimerIfRunning();
}
}
}
}
Expand Down
Loading