From 2aa7da19fe7a739df3061e01b6f9539c68324261 Mon Sep 17 00:00:00 2001 From: Brian Vaughn Date: Wed, 23 May 2018 11:10:52 -0700 Subject: [PATCH 1/8] Moved actual time fields from Profiler stateNode to Fiber --- packages/react-reconciler/src/ReactFiber.js | 16 +++++++++------- .../react-reconciler/src/ReactFiberCommitWork.js | 6 +++--- .../react-reconciler/src/ReactProfilerTimer.js | 15 +++++++-------- 3 files changed, 19 insertions(+), 18 deletions(-) diff --git a/packages/react-reconciler/src/ReactFiber.js b/packages/react-reconciler/src/ReactFiber.js index d27a5b6a131..140701844c2 100644 --- a/packages/react-reconciler/src/ReactFiber.js +++ b/packages/react-reconciler/src/ReactFiber.js @@ -153,6 +153,8 @@ export type Fiber = {| alternate: Fiber | null, // Profiling metrics + actualDuration?: number, + actualStartTime?: number, selfBaseTime?: number, treeBaseTime?: number, @@ -211,6 +213,8 @@ function FiberNode( this.alternate = null; if (enableProfilerTimer) { + this.actualDuration = 0; + this.actualStartTime = 0; this.selfBaseTime = 0; this.treeBaseTime = 0; } @@ -310,6 +314,9 @@ export function createWorkInProgress( workInProgress.ref = current.ref; if (enableProfilerTimer) { + // We intentionally do not copy actual duration or start times. + // This would interfere with time tracking during interruptions. + workInProgress.selfBaseTime = current.selfBaseTime; workInProgress.treeBaseTime = current.treeBaseTime; } @@ -460,13 +467,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 +541,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/ReactFiberCommitWork.js b/packages/react-reconciler/src/ReactFiberCommitWork.js index 8f5fa74a5c5..87f2ff474f5 100644 --- a/packages/react-reconciler/src/ReactFiberCommitWork.js +++ b/packages/react-reconciler/src/ReactFiberCommitWork.js @@ -806,15 +806,15 @@ 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; + finishedWork.actualDuration = 0; } return; } diff --git a/packages/react-reconciler/src/ReactProfilerTimer.js b/packages/react-reconciler/src/ReactProfilerTimer.js index bbe1c9bdeae..63a0b7c2ef6 100644 --- a/packages/react-reconciler/src/ReactProfilerTimer.js +++ b/packages/react-reconciler/src/ReactProfilerTimer.js @@ -76,9 +76,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 { @@ -97,11 +98,9 @@ function recordElapsedActualRenderTime(fiber: Fiber): void { if (__DEV__) { warning(fiber === fiberStack.pop(), 'Unexpected Fiber popped.'); } - const stateNode = fiber.stateNode; - stateNode.duration += - now() - - (totalElapsedPauseTime - stateNode.elapsedPauseTimeAtStart) - - stateNode.startTime; + + fiber.actualDuration = + now() - totalElapsedPauseTime - ((fiber.actualDuration: any): number); } function resetActualRenderTimer(): void { From 5005f08655cf6d46f9d1937b02f728e943cd4c9c Mon Sep 17 00:00:00 2001 From: Brian Vaughn Date: Wed, 23 May 2018 11:11:19 -0700 Subject: [PATCH 2/8] Record actual time for all Fibers within a ProfileMode tree --- .../src/ReactFiberBeginWork.js | 18 ++++++--------- .../src/ReactFiberCompleteWork.js | 11 ++++++--- .../src/ReactFiberScheduler.js | 5 ++++ .../src/ReactFiberUnwindWork.js | 23 ++++++++++++------- .../src/ReactProfilerTimer.js | 7 +++++- 5 files changed, 41 insertions(+), 23 deletions(-) diff --git a/packages/react-reconciler/src/ReactFiberBeginWork.js b/packages/react-reconciler/src/ReactFiberBeginWork.js index ad1189d4020..135e85bb0ba 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/ReactFiberCompleteWork.js b/packages/react-reconciler/src/ReactFiberCompleteWork.js index 8ed630b82db..d9b469c94d1 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 87f97dcc617..8517d6ab3ae 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(); } diff --git a/packages/react-reconciler/src/ReactFiberUnwindWork.js b/packages/react-reconciler/src/ReactFiberUnwindWork.js index b4be270162d..19bb46bfa5a 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 63a0b7c2ef6..7877d7d2977 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'; @@ -96,7 +97,11 @@ 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), + ); } fiber.actualDuration = From b66a44af43f12eda89b6ff0867354e5331cc815f Mon Sep 17 00:00:00 2001 From: Brian Vaughn Date: Thu, 24 May 2018 15:50:42 -0700 Subject: [PATCH 3/8] Reset actualDuration for all Fibers (not just Profilers) --- .../src/ReactFiberCommitWork.js | 22 ++++++++++--------- .../__tests__/ReactProfiler-test.internal.js | 22 +++++++++++++++++++ 2 files changed, 34 insertions(+), 10 deletions(-) diff --git a/packages/react-reconciler/src/ReactFiberCommitWork.js b/packages/react-reconciler/src/ReactFiberCommitWork.js index 87f2ff474f5..c4b782a36ec 100644 --- a/packages/react-reconciler/src/ReactFiberCommitWork.js +++ b/packages/react-reconciler/src/ReactFiberCommitWork.js @@ -753,7 +753,7 @@ function commitWork(current: Fiber | null, finishedWork: Fiber): void { switch (finishedWork.tag) { case ClassComponent: { - return; + break; } case HostComponent: { const instance: Instance = finishedWork.stateNode; @@ -779,7 +779,7 @@ function commitWork(current: Fiber | null, finishedWork: Fiber): void { ); } } - return; + break; } case HostText: { invariant( @@ -795,10 +795,10 @@ function commitWork(current: Fiber | null, finishedWork: Fiber): void { const oldText: string = current !== null ? current.memoizedProps : newText; commitTextUpdate(textInstance, oldText, newText); - return; + break; } case HostRoot: { - return; + break; } case Profiler: { if (enableProfilerTimer) { @@ -811,15 +811,11 @@ function commitWork(current: Fiber | null, finishedWork: Fiber): void { finishedWork.actualStartTime, getCommitTime(), ); - - // Reset actualTime after successful commit. - // By default, we append to this time to account for errors and pauses. - finishedWork.actualDuration = 0; } - return; + break; } case TimeoutComponent: { - return; + break; } default: { invariant( @@ -829,6 +825,12 @@ function commitWork(current: Fiber | null, finishedWork: Fiber): void { ); } } + + if (enableProfilerTimer) { + // Reset actualTime after successful commit. + // By default, we append to this time to account for errors and pauses. + finishedWork.actualDuration = 0; + } } function commitResetTextContent(current: Fiber) { diff --git a/packages/react/src/__tests__/ReactProfiler-test.internal.js b/packages/react/src/__tests__/ReactProfiler-test.internal.js index 3e27588816f..ca0f4236d3a 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', () => { From 6473dd6de0e20edf70d81ef7f83e6206f6ce91f7 Mon Sep 17 00:00:00 2001 From: Brian Vaughn Date: Fri, 25 May 2018 09:38:39 -0700 Subject: [PATCH 4/8] Add commit batch ID to Profiler A global 'batch id' is updated during the commit phase. Each (profiled) Fiber has a local batch id. When the Profiler timer is started- the local id is compared to the global one in order to determine whether to reset or accumulate duration. This has the downside of adding an additional field to fibers (for profiling builds only) but the upside of containing the writes to 'render' phase and allowing the DevTools commit hook to run before durations have been cleared out (so it can read them for profiling mode). --- packages/react-reconciler/src/ReactFiber.js | 29 +++++++++++++++++-- .../src/ReactFiberCommitWork.js | 6 ---- .../src/ReactFiberScheduler.js | 8 +++++ .../src/ReactProfilerTimer.js | 12 ++++++++ 4 files changed, 46 insertions(+), 9 deletions(-) diff --git a/packages/react-reconciler/src/ReactFiber.js b/packages/react-reconciler/src/ReactFiber.js index 140701844c2..2dbe7164cc5 100644 --- a/packages/react-reconciler/src/ReactFiber.js +++ b/packages/react-reconciler/src/ReactFiber.js @@ -152,10 +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 @@ -215,6 +235,7 @@ function FiberNode( if (enableProfilerTimer) { this.actualDuration = 0; this.actualStartTime = 0; + this.profilerCommitBatchId = 0; this.selfBaseTime = 0; this.treeBaseTime = 0; } @@ -314,8 +335,9 @@ export function createWorkInProgress( workInProgress.ref = current.ref; if (enableProfilerTimer) { - // We intentionally do not copy actual duration or start times. - // This would interfere with time tracking during interruptions. + // 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; @@ -543,6 +565,7 @@ export function assignFiberPropertiesInDEV( if (enableProfilerTimer) { target.actualDuration = source.actualDuration; target.actualStartTime = source.actualStartTime; + target.profilerCommitBatchId = source.profilerCommitBatchId; target.selfBaseTime = source.selfBaseTime; target.treeBaseTime = source.treeBaseTime; } diff --git a/packages/react-reconciler/src/ReactFiberCommitWork.js b/packages/react-reconciler/src/ReactFiberCommitWork.js index c4b782a36ec..07730b8273a 100644 --- a/packages/react-reconciler/src/ReactFiberCommitWork.js +++ b/packages/react-reconciler/src/ReactFiberCommitWork.js @@ -825,12 +825,6 @@ function commitWork(current: Fiber | null, finishedWork: Fiber): void { ); } } - - if (enableProfilerTimer) { - // Reset actualTime after successful commit. - // By default, we append to this time to account for errors and pauses. - finishedWork.actualDuration = 0; - } } function commitResetTextContent(current: Fiber) { diff --git a/packages/react-reconciler/src/ReactFiberScheduler.js b/packages/react-reconciler/src/ReactFiberScheduler.js index 8517d6ab3ae..a812d5bb06b 100644 --- a/packages/react-reconciler/src/ReactFiberScheduler.js +++ b/packages/react-reconciler/src/ReactFiberScheduler.js @@ -104,6 +104,7 @@ import {popProvider} from './ReactFiberNewContext'; import {popHostContext, popHostContainer} from './ReactFiberHostContext'; import { checkActualRenderTimeStackEmpty, + incrementCommitBatchId, pauseActualRenderTimerIfRunning, recordCommitTime, recordElapsedActualRenderTime, @@ -578,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(); } diff --git a/packages/react-reconciler/src/ReactProfilerTimer.js b/packages/react-reconciler/src/ReactProfilerTimer.js index 7877d7d2977..24bf8eaaca6 100644 --- a/packages/react-reconciler/src/ReactProfilerTimer.js +++ b/packages/react-reconciler/src/ReactProfilerTimer.js @@ -18,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, @@ -30,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; @@ -78,6 +84,11 @@ function markActualRenderTimeStarted(fiber: Fiber): void { fiberStack.push(fiber); } + if (fiber.profilerCommitBatchId !== commitBatchId) { + fiber.profilerCommitBatchId = commitBatchId; + fiber.actualDuration = 0; + } + fiber.actualDuration = now() - ((fiber.actualDuration: any): number) - totalElapsedPauseTime; fiber.actualStartTime = now(); @@ -170,6 +181,7 @@ function stopBaseRenderTimerIfRunning(): void { export { checkActualRenderTimeStackEmpty, getCommitTime, + incrementCommitBatchId, markActualRenderTimeStarted, pauseActualRenderTimerIfRunning, recordCommitTime, From 3c03bb3726410ae7201d5e24024cc599bdd55897 Mon Sep 17 00:00:00 2001 From: Brian Vaughn Date: Fri, 25 May 2018 09:42:53 -0700 Subject: [PATCH 5/8] Reverted unnecessary change to ReactFiberCommitWork --- .../react-reconciler/src/ReactFiberCommitWork.js | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/packages/react-reconciler/src/ReactFiberCommitWork.js b/packages/react-reconciler/src/ReactFiberCommitWork.js index 07730b8273a..f9a3dce2004 100644 --- a/packages/react-reconciler/src/ReactFiberCommitWork.js +++ b/packages/react-reconciler/src/ReactFiberCommitWork.js @@ -753,7 +753,7 @@ function commitWork(current: Fiber | null, finishedWork: Fiber): void { switch (finishedWork.tag) { case ClassComponent: { - break; + return; } case HostComponent: { const instance: Instance = finishedWork.stateNode; @@ -779,7 +779,7 @@ function commitWork(current: Fiber | null, finishedWork: Fiber): void { ); } } - break; + return; } case HostText: { invariant( @@ -795,10 +795,10 @@ function commitWork(current: Fiber | null, finishedWork: Fiber): void { const oldText: string = current !== null ? current.memoizedProps : newText; commitTextUpdate(textInstance, oldText, newText); - break; + return; } case HostRoot: { - break; + return; } case Profiler: { if (enableProfilerTimer) { @@ -812,10 +812,10 @@ function commitWork(current: Fiber | null, finishedWork: Fiber): void { getCommitTime(), ); } - break; + return; } case TimeoutComponent: { - break; + return; } default: { invariant( From 05fa464a31d9abf3e6f864829662585a79bdf368 Mon Sep 17 00:00:00 2001 From: Brian Vaughn Date: Fri, 25 May 2018 10:58:12 -0700 Subject: [PATCH 6/8] Fixed an invalid test flush-through id --- packages/react/src/__tests__/ReactProfiler-test.internal.js | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/packages/react/src/__tests__/ReactProfiler-test.internal.js b/packages/react/src/__tests__/ReactProfiler-test.internal.js index ca0f4236d3a..a31fe8461c9 100644 --- a/packages/react/src/__tests__/ReactProfiler-test.internal.js +++ b/packages/react/src/__tests__/ReactProfiler-test.internal.js @@ -598,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. From a3318ecd5eb7515fd231f0b762cde7c212687e8d Mon Sep 17 00:00:00 2001 From: Brian Vaughn Date: Fri, 25 May 2018 13:58:10 -0700 Subject: [PATCH 7/8] 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 | 15 ++++----------- .../react-reconciler/src/ReactFiberScheduler.js | 6 ------ .../react-reconciler/src/ReactProfilerTimer.js | 12 ------------ .../src/__tests__/ReactProfiler-test.internal.js | 12 +++++++----- 4 files changed, 11 insertions(+), 34 deletions(-) diff --git a/packages/react-reconciler/src/ReactFiber.js b/packages/react-reconciler/src/ReactFiber.js index 2dbe7164cc5..346864c8145 100644 --- a/packages/react-reconciler/src/ReactFiber.js +++ b/packages/react-reconciler/src/ReactFiber.js @@ -162,12 +162,6 @@ export type Fiber = {| // 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. @@ -235,7 +229,6 @@ function FiberNode( if (enableProfilerTimer) { this.actualDuration = 0; this.actualStartTime = 0; - this.profilerCommitBatchId = 0; this.selfBaseTime = 0; this.treeBaseTime = 0; } @@ -335,9 +328,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. + // We intentionally reset, rather than copy, actualDuration & actualStartTime. + // This prevents time from endlessly accumulating in new commits. + workInProgress.actualDuration = 0; + workInProgress.actualStartTime = 0; workInProgress.selfBaseTime = current.selfBaseTime; workInProgress.treeBaseTime = current.treeBaseTime; @@ -565,7 +559,6 @@ export function assignFiberPropertiesInDEV( if (enableProfilerTimer) { target.actualDuration = source.actualDuration; target.actualStartTime = source.actualStartTime; - target.profilerCommitBatchId = source.profilerCommitBatchId; target.selfBaseTime = source.selfBaseTime; target.treeBaseTime = source.treeBaseTime; } diff --git a/packages/react-reconciler/src/ReactFiberScheduler.js b/packages/react-reconciler/src/ReactFiberScheduler.js index a812d5bb06b..70bec86f55e 100644 --- a/packages/react-reconciler/src/ReactFiberScheduler.js +++ b/packages/react-reconciler/src/ReactFiberScheduler.js @@ -104,7 +104,6 @@ import {popProvider} from './ReactFiberNewContext'; import {popHostContext, popHostContainer} from './ReactFiberHostContext'; import { checkActualRenderTimeStackEmpty, - incrementCommitBatchId, pauseActualRenderTimerIfRunning, recordCommitTime, recordElapsedActualRenderTime, @@ -579,11 +578,6 @@ 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(); diff --git a/packages/react-reconciler/src/ReactProfilerTimer.js b/packages/react-reconciler/src/ReactProfilerTimer.js index 24bf8eaaca6..7877d7d2977 100644 --- a/packages/react-reconciler/src/ReactProfilerTimer.js +++ b/packages/react-reconciler/src/ReactProfilerTimer.js @@ -18,7 +18,6 @@ import {now} from './ReactFiberHostConfig'; export type ProfilerTimer = { checkActualRenderTimeStackEmpty(): void, getCommitTime(): number, - incrementCommitBatchId(): void, markActualRenderTimeStarted(fiber: Fiber): void, pauseActualRenderTimerIfRunning(): void, recordElapsedActualRenderTime(fiber: Fiber): void, @@ -31,16 +30,11 @@ 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; @@ -84,11 +78,6 @@ function markActualRenderTimeStarted(fiber: Fiber): void { fiberStack.push(fiber); } - if (fiber.profilerCommitBatchId !== commitBatchId) { - fiber.profilerCommitBatchId = commitBatchId; - fiber.actualDuration = 0; - } - fiber.actualDuration = now() - ((fiber.actualDuration: any): number) - totalElapsedPauseTime; fiber.actualStartTime = now(); @@ -181,7 +170,6 @@ function stopBaseRenderTimerIfRunning(): void { export { checkActualRenderTimeStackEmpty, getCommitTime, - incrementCommitBatchId, markActualRenderTimeStarted, pauseActualRenderTimerIfRunning, recordCommitTime, diff --git a/packages/react/src/__tests__/ReactProfiler-test.internal.js b/packages/react/src/__tests__/ReactProfiler-test.internal.js index a31fe8461c9..ccd3dc3be01 100644 --- a/packages/react/src/__tests__/ReactProfiler-test.internal.js +++ b/packages/react/src/__tests__/ReactProfiler-test.internal.js @@ -705,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 @@ -796,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 From edc7a5df94f89243dc14f90125ac13deb3874090 Mon Sep 17 00:00:00 2001 From: Brian Vaughn Date: Fri, 25 May 2018 14:37:33 -0700 Subject: [PATCH 8/8] Moved duration reset into createWorkInProgress() else block --- packages/react-reconciler/src/ReactFiber.js | 14 +++++++++----- 1 file changed, 9 insertions(+), 5 deletions(-) diff --git a/packages/react-reconciler/src/ReactFiber.js b/packages/react-reconciler/src/ReactFiber.js index 346864c8145..34ee91645d7 100644 --- a/packages/react-reconciler/src/ReactFiber.js +++ b/packages/react-reconciler/src/ReactFiber.js @@ -313,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; @@ -328,11 +337,6 @@ export function createWorkInProgress( workInProgress.ref = current.ref; if (enableProfilerTimer) { - // We intentionally reset, rather than copy, actualDuration & actualStartTime. - // This prevents time from endlessly accumulating in new commits. - workInProgress.actualDuration = 0; - workInProgress.actualStartTime = 0; - workInProgress.selfBaseTime = current.selfBaseTime; workInProgress.treeBaseTime = current.treeBaseTime; }