Skip to content

Commit

Permalink
Update user timing to record when we are about to commit (#12384)
Browse files Browse the repository at this point in the history 
* Update user timing to record when we are about to commit

**what is the change?:**
After repeatedly logging '(React Tree Reconciliation)' we vary the
message slightly for the last reconciliation, which happens right before
we commit.

**why make this change?:**
When debugging performance in the devtools it will be helpful if we can
quickly see where the 'commit' happens in a potentially long list of
sliced '(React Tree Reconciliation)' logs.

**test plan:**
Built and ran one of the fixtures. Also ran the unit test.

(Flarnie will insert a screenshot)

* Ran prettier

* Fixes in response to code review

* Update snapshot tests

* Move isWorking assignment out of branches to top

* Stricter type for stopWorkLoopTimer args
  • Loading branch information
@flarnie
flarnie committed Apr 2, 2018
1 parent 6b99c6f commit 7a27ebd
Show file tree
Hide file tree
Showing 3 changed files with 53 additions and 43 deletions.
14 changes: 8 additions & 6 deletions packages/react-reconciler/src/ReactDebugFiberPerf.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -369,7 +369,10 @@ export function startWorkLoopTimer(nextUnitOfWork: Fiber | null): void {
}
}

export function stopWorkLoopTimer(interruptedBy: Fiber | null): void {
export function stopWorkLoopTimer(
interruptedBy: Fiber | null,
didCompleteRoot: boolean,
): void {
if (enableUserTimingAPI) {
if (!supportsUserTiming) {
return;
Expand All @@ -388,13 +391,12 @@ export function stopWorkLoopTimer(interruptedBy: Fiber | null): void {
warning = 'There were cascading updates';
}
commitCountInCurrentWorkLoop = 0;
let label = didCompleteRoot
? '(React Tree Reconciliation: Completed Root)'
: '(React Tree Reconciliation: Yielded)';
// Pause any measurements until the next loop.
pauseTimers();
endMark(
'(React Tree Reconciliation)',
'(React Tree Reconciliation)',
warning,
);
endMark(label, '(React Tree Reconciliation)', warning);
}
}

Expand Down
12 changes: 10 additions & 2 deletions packages/react-reconciler/src/ReactFiberScheduler.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -958,12 +958,13 @@ export default function<T, P, I, TI, HI, PI, C, CC, CX, PL>(
} while (true);

// We're done performing work. Time to clean up.
stopWorkLoopTimer(interruptedBy);
interruptedBy = null;
let didCompleteRoot = false;
isWorking = false;

// Yield back to main thread.
if (didFatal) {
stopWorkLoopTimer(interruptedBy, didCompleteRoot);
interruptedBy = null;
// There was a fatal error.
if (__DEV__) {
stack.resetStackAfterFatalErrorInDev();
Expand All @@ -972,19 +973,26 @@ export default function<T, P, I, TI, HI, PI, C, CC, CX, PL>(
} else if (nextUnitOfWork === null) {
// We reached the root.
if (isRootReadyForCommit) {
didCompleteRoot = true;
stopWorkLoopTimer(interruptedBy, didCompleteRoot);
interruptedBy = null;
// The root successfully completed. It's ready for commit.
root.pendingCommitExpirationTime = expirationTime;
const finishedWork = root.current.alternate;
return finishedWork;
} else {
// The root did not complete.
stopWorkLoopTimer(interruptedBy, didCompleteRoot);
interruptedBy = null;
invariant(
false,
'Expired work should have completed. This error is likely caused ' +
'by a bug in React. Please file an issue.',
);
}
} else {
stopWorkLoopTimer(interruptedBy, didCompleteRoot);
interruptedBy = null;
// There's more work to do, but we ran out of time. Yield back to
// the renderer.
return null;
Expand Down
70 changes: 35 additions & 35 deletions ...s/react-reconciler/src/__tests__/__snapshots__/ReactIncrementalPerf-test.internal.js.snap
View file
Original file line number Diff line number Diff line change
Expand Up @@ -4,7 +4,7 @@ exports[`ReactDebugFiberPerf captures all lifecycles 1`] = `
"⚛ (Waiting for async callback... will force flush in 5230 ms)
// Mount
⚛ (React Tree Reconciliation)
⚛ (React Tree Reconciliation: Completed Root)
⚛ AllLifecycles [mount]
⚛ AllLifecycles.componentWillMount
⚛ AllLifecycles.getChildContext
Expand All @@ -18,7 +18,7 @@ exports[`ReactDebugFiberPerf captures all lifecycles 1`] = `
⚛ (Waiting for async callback... will force flush in 5230 ms)
// Update
⚛ (React Tree Reconciliation)
⚛ (React Tree Reconciliation: Completed Root)
⚛ AllLifecycles [update]
⚛ AllLifecycles.componentWillReceiveProps
⚛ AllLifecycles.shouldComponentUpdate
Expand All @@ -34,7 +34,7 @@ exports[`ReactDebugFiberPerf captures all lifecycles 1`] = `
⚛ (Waiting for async callback... will force flush in 5230 ms)
// Unmount
⚛ (React Tree Reconciliation)
⚛ (React Tree Reconciliation: Completed Root)
⚛ (Committing Changes)
⚛ (Committing Snapshot Effects: 0 Total)
Expand All @@ -48,7 +48,7 @@ exports[`ReactDebugFiberPerf deduplicates lifecycle names during commit to reduc
"⚛ (Waiting for async callback... will force flush in 5230 ms)
// The commit phase should mention A and B just once
⚛ (React Tree Reconciliation)
⚛ (React Tree Reconciliation: Completed Root)
⚛ Parent [update]
⚛ A [update]
⚛ B [update]
Expand All @@ -66,7 +66,7 @@ exports[`ReactDebugFiberPerf deduplicates lifecycle names during commit to reduc
// Because of deduplication, we don't know B was cascading,
// but we should still see the warning for the commit phase.
⚛ (React Tree Reconciliation)
⚛ (React Tree Reconciliation: Completed Root)
⚛ Parent [update]
⚛ A [update]
⚛ B [update]
Expand All @@ -80,7 +80,7 @@ exports[`ReactDebugFiberPerf deduplicates lifecycle names during commit to reduc
⚛ A.componentDidUpdate
⚛ B.componentDidUpdate
⚛ (React Tree Reconciliation)
⚛ (React Tree Reconciliation: Completed Root)
⚛ B [update]
⚛ (Committing Changes)
Expand All @@ -92,7 +92,7 @@ exports[`ReactDebugFiberPerf deduplicates lifecycle names during commit to reduc
`;

exports[`ReactDebugFiberPerf does not schedule an extra callback if setState is called during a synchronous commit phase 1`] = `
"⚛ (React Tree Reconciliation)
"⚛ (React Tree Reconciliation: Completed Root)
⚛ Component [mount]
⛔ (Committing Changes) Warning: Lifecycle hook scheduled a cascading update
Expand All @@ -101,7 +101,7 @@ exports[`ReactDebugFiberPerf does not schedule an extra callback if setState is
⚛ (Calling Lifecycle Methods: 1 Total)
⛔ Component.componentDidMount Warning: Scheduled a cascading update
⚛ (React Tree Reconciliation)
⚛ (React Tree Reconciliation: Completed Root)
⚛ Component [update]
⚛ (Committing Changes)
Expand All @@ -115,7 +115,7 @@ exports[`ReactDebugFiberPerf does not treat setState from cWM or cWRP as cascadi
"⚛ (Waiting for async callback... will force flush in 5230 ms)
// Should not print a warning
⚛ (React Tree Reconciliation)
⚛ (React Tree Reconciliation: Completed Root)
⚛ Parent [mount]
⚛ NotCascading [mount]
⚛ NotCascading.componentWillMount
Expand All @@ -128,7 +128,7 @@ exports[`ReactDebugFiberPerf does not treat setState from cWM or cWRP as cascadi
⚛ (Waiting for async callback... will force flush in 5230 ms)
// Should not print a warning
⚛ (React Tree Reconciliation)
⚛ (React Tree Reconciliation: Completed Root)
⚛ Parent [update]
⚛ NotCascading [update]
⚛ NotCascading.componentWillReceiveProps
Expand All @@ -144,7 +144,7 @@ exports[`ReactDebugFiberPerf measures a simple reconciliation 1`] = `
"⚛ (Waiting for async callback... will force flush in 5230 ms)
// Mount
⚛ (React Tree Reconciliation)
⚛ (React Tree Reconciliation: Completed Root)
⚛ Parent [mount]
⚛ Child [mount]
Expand All @@ -156,7 +156,7 @@ exports[`ReactDebugFiberPerf measures a simple reconciliation 1`] = `
⚛ (Waiting for async callback... will force flush in 5230 ms)
// Update
⚛ (React Tree Reconciliation)
⚛ (React Tree Reconciliation: Completed Root)
⚛ Parent [update]
⚛ Child [update]
Expand All @@ -168,7 +168,7 @@ exports[`ReactDebugFiberPerf measures a simple reconciliation 1`] = `
⚛ (Waiting for async callback... will force flush in 5230 ms)
// Unmount
⚛ (React Tree Reconciliation)
⚛ (React Tree Reconciliation: Completed Root)
⚛ (Committing Changes)
⚛ (Committing Snapshot Effects: 0 Total)
Expand All @@ -181,22 +181,22 @@ exports[`ReactDebugFiberPerf measures deferred work in chunks 1`] = `
"⚛ (Waiting for async callback... will force flush in 5230 ms)
// Start mounting Parent and A
⚛ (React Tree Reconciliation)
⚛ (React Tree Reconciliation: Yielded)
⚛ Parent [mount]
⚛ A [mount]
⚛ Child [mount]
⚛ (Waiting for async callback... will force flush in 5230 ms)
// Mount B just a little (but not enough to memoize)
⚛ (React Tree Reconciliation)
⚛ (React Tree Reconciliation: Yielded)
⚛ Parent [mount]
⚛ B [mount]
⚛ (Waiting for async callback... will force flush in 5230 ms)
// Complete B and Parent
⚛ (React Tree Reconciliation)
⚛ (React Tree Reconciliation: Completed Root)
⚛ Parent [mount]
⚛ B [mount]
⚛ Child [mount]
Expand All @@ -210,7 +210,7 @@ exports[`ReactDebugFiberPerf measures deferred work in chunks 1`] = `

exports[`ReactDebugFiberPerf measures deprioritized work 1`] = `
"// Flush the parent
⚛ (React Tree Reconciliation)
⚛ (React Tree Reconciliation: Completed Root)
⚛ Parent [mount]
⚛ (Committing Changes)
Expand All @@ -221,7 +221,7 @@ exports[`ReactDebugFiberPerf measures deprioritized work 1`] = `
⚛ (Waiting for async callback... will force flush in 10737418210 ms)
// Flush the child
⚛ (React Tree Reconciliation)
⚛ (React Tree Reconciliation: Completed Root)
⚛ Child [mount]
⚛ (Committing Changes)
Expand All @@ -235,13 +235,13 @@ exports[`ReactDebugFiberPerf recovers from caught errors 1`] = `
"⚛ (Waiting for async callback... will force flush in 5230 ms)
// Stop on Baddie and restart from Boundary
⚛ (React Tree Reconciliation)
⚛ (React Tree Reconciliation: Yielded)
⚛ Parent [mount]
⛔ Boundary [mount] Warning: An error was thrown inside this error boundary
⚛ Parent [mount]
⚛ Baddie [mount]
⚛ (React Tree Reconciliation)
⚛ (React Tree Reconciliation: Completed Root)
⚛ Parent [mount]
⚛ Boundary [mount]
Expand All @@ -250,7 +250,7 @@ exports[`ReactDebugFiberPerf recovers from caught errors 1`] = `
⚛ (Committing Host Effects: 2 Total)
⚛ (Calling Lifecycle Methods: 0 Total)
⚛ (React Tree Reconciliation)
⚛ (React Tree Reconciliation: Completed Root)
⚛ Boundary [update]
⚛ ErrorReport [mount]
Expand All @@ -265,11 +265,11 @@ exports[`ReactDebugFiberPerf recovers from fatal errors 1`] = `
"⚛ (Waiting for async callback... will force flush in 5230 ms)
// Will fatal
⚛ (React Tree Reconciliation)
⚛ (React Tree Reconciliation: Yielded)
⚛ Parent [mount]
⚛ Baddie [mount]
⚛ (React Tree Reconciliation)
⚛ (React Tree Reconciliation: Completed Root)
⚛ (Committing Changes)
⚛ (Committing Snapshot Effects: 0 Total)
Expand All @@ -279,7 +279,7 @@ exports[`ReactDebugFiberPerf recovers from fatal errors 1`] = `
⚛ (Waiting for async callback... will force flush in 5230 ms)
// Will reconcile from a clean state
⚛ (React Tree Reconciliation)
⚛ (React Tree Reconciliation: Completed Root)
⚛ Parent [mount]
⚛ Child [mount]
Expand All @@ -294,7 +294,7 @@ exports[`ReactDebugFiberPerf skips parents during setState 1`] = `
"⚛ (Waiting for async callback... will force flush in 5230 ms)
// Should include just A and B, no Parents
⚛ (React Tree Reconciliation)
⚛ (React Tree Reconciliation: Completed Root)
⚛ A [update]
⚛ B [update]
Expand All @@ -308,7 +308,7 @@ exports[`ReactDebugFiberPerf skips parents during setState 1`] = `
exports[`ReactDebugFiberPerf supports portals 1`] = `
"⚛ (Waiting for async callback... will force flush in 5230 ms)
⚛ (React Tree Reconciliation)
⚛ (React Tree Reconciliation: Completed Root)
⚛ Parent [mount]
⚛ Child [mount]
Expand All @@ -322,7 +322,7 @@ exports[`ReactDebugFiberPerf supports portals 1`] = `
exports[`ReactDebugFiberPerf supports returns 1`] = `
"⚛ (Waiting for async callback... will force flush in 5230 ms)
⚛ (React Tree Reconciliation)
⚛ (React Tree Reconciliation: Completed Root)
⚛ App [mount]
⚛ CoParent [mount]
⚛ Indirection [mount]
Expand All @@ -341,18 +341,18 @@ exports[`ReactDebugFiberPerf supports returns 1`] = `
exports[`ReactDebugFiberPerf warns if an in-progress update is interrupted 1`] = `
"⚛ (Waiting for async callback... will force flush in 5230 ms)
⚛ (React Tree Reconciliation)
⚛ (React Tree Reconciliation: Yielded)
⚛ Foo [mount]
⚛ (Waiting for async callback... will force flush in 5230 ms)
⛔ (React Tree Reconciliation) Warning: A top-level update interrupted the previous render
⛔ (React Tree Reconciliation: Completed Root) Warning: A top-level update interrupted the previous render
⚛ Foo [mount]
⚛ (Committing Changes)
⚛ (Committing Snapshot Effects: 0 Total)
⚛ (Committing Host Effects: 1 Total)
⚛ (Calling Lifecycle Methods: 0 Total)
⚛ (React Tree Reconciliation)
⚛ (React Tree Reconciliation: Completed Root)
⚛ (Committing Changes)
⚛ (Committing Snapshot Effects: 0 Total)
Expand All @@ -364,7 +364,7 @@ exports[`ReactDebugFiberPerf warns if an in-progress update is interrupted 1`] =
exports[`ReactDebugFiberPerf warns if async work expires (starvation) 1`] = `
"⛔ (Waiting for async callback... will force flush in 5230 ms) Warning: React was blocked by main thread
⚛ (React Tree Reconciliation)
⚛ (React Tree Reconciliation: Completed Root)
⚛ Foo [mount]
⚛ (Committing Changes)
Expand All @@ -378,7 +378,7 @@ exports[`ReactDebugFiberPerf warns on cascading renders from setState 1`] = `
"⚛ (Waiting for async callback... will force flush in 5230 ms)
// Should print a warning
⚛ (React Tree Reconciliation)
⚛ (React Tree Reconciliation: Completed Root)
⚛ Parent [mount]
⚛ Cascading [mount]
Expand All @@ -388,7 +388,7 @@ exports[`ReactDebugFiberPerf warns on cascading renders from setState 1`] = `
⚛ (Calling Lifecycle Methods: 1 Total)
⛔ Cascading.componentDidMount Warning: Scheduled a cascading update
⚛ (React Tree Reconciliation)
⚛ (React Tree Reconciliation: Completed Root)
⚛ Cascading [update]
⚛ (Committing Changes)
Expand All @@ -402,7 +402,7 @@ exports[`ReactDebugFiberPerf warns on cascading renders from top-level render 1`
"⚛ (Waiting for async callback... will force flush in 5230 ms)
// Rendering the first root
⚛ (React Tree Reconciliation)
⚛ (React Tree Reconciliation: Completed Root)
⚛ Cascading [mount]
⛔ (Committing Changes) Warning: Lifecycle hook scheduled a cascading update
Expand All @@ -412,7 +412,7 @@ exports[`ReactDebugFiberPerf warns on cascading renders from top-level render 1`
⛔ Cascading.componentDidMount Warning: Scheduled a cascading update
// Scheduling another root from componentDidMount
⚛ (React Tree Reconciliation)
⚛ (React Tree Reconciliation: Completed Root)
⚛ Child [mount]
⚛ (Committing Changes)
Expand Down

0 comments on commit 7a27ebd

Please sign in to comment.