Profiler actualDuration bugfix (#13313)
* Simplified profiler actualDuration timing While testing the new DevTools profiler, I noticed that sometimes– in larger, more complicated applications– the actualDuration value was incorrect (either too large, or sometimes negative). I was not able to reproduce this in a smaller application or test (which sucks) but I assume it has something to do with the way I was tracking render times across priorities/roots. So this PR replaces the previous approach with a simpler one. * Changed bubbling logic after chatting out of band with Andrew * Replaced __PROFILE__ with feature-flag conditionals in test * Updated test comment
Brian Vaughn committed
Aug 8, 2018 at 09:42 UTC
067cc24f55ef01a233be9e7564b337e35fed72ea
7 files changed
+127
-283
packages/react-reconciler/src/ReactFiber.js
+3
-2
@@ -162,6 +162,7 @@ export type Fiber = {|
162
163
// Time spent rendering this Fiber and its descendants for the current update.
164
// This tells us how well the tree makes use of sCU for memoization.
165
+ // It is reset to 0 each time we render and only updated when we don't bailout.
166
// This field is only set when the enableProfilerTimer flag is enabled.
167
actualDuration?: number,
168
@@ -238,7 +239,7 @@ function FiberNode(
239
240
if (enableProfilerTimer) {
241
this.actualDuration = 0;
241
- this.actualStartTime = 0;
242
+ this.actualStartTime = -1;
243
this.selfBaseDuration = 0;
244
this.treeBaseDuration = 0;
245
}
@@ -330,7 +331,7 @@ export function createWorkInProgress(
331
// This has the downside of resetting values for different priority renders,
332
// But works for yielding (the common case) and should support resuming.
333
workInProgress.actualDuration = 0;
333
- workInProgress.actualStartTime = 0;
334
+ workInProgress.actualStartTime = -1;
335
}
336
}
337
packages/react-reconciler/src/ReactFiberBeginWork.js
+4
-13
@@ -62,7 +62,7 @@ import {
62
} from './ReactChildFiber';
63
import {processUpdateQueue} from './ReactUpdateQueue';
64
import {NoWork, Never} from './ReactFiberExpirationTime';
65
-import {AsyncMode, ProfileMode, StrictMode} from './ReactTypeOfMode';
65
+import {AsyncMode, StrictMode} from './ReactTypeOfMode';
66
import {
67
shouldSetTextContent,
68
shouldDeprioritizeSubtree,
@@ -75,10 +75,7 @@ import {
75
prepareToReadContext,
76
calculateChangedBits,
77
} from './ReactFiberNewContext';
78
-import {
79
- markActualRenderTimeStarted,
80
- stopBaseRenderTimerIfRunning,
81
-} from './ReactProfilerTimer';
78
+import {stopProfilerTimerIfRunning} from './ReactProfilerTimer';
79
import {
80
getMaskedContext,
81
getUnmaskedContext,
@@ -379,7 +376,7 @@ function finishClassComponent(
376
nextChildren = null;
377
378
if (enableProfilerTimer) {
382
- stopBaseRenderTimerIfRunning();
379
+ stopProfilerTimerIfRunning(workInProgress);
380
}
381
} else {
382
if (__DEV__) {
@@ -954,7 +951,7 @@ function bailoutOnAlreadyFinishedWork(
951
952
if (enableProfilerTimer) {
953
// Don't update "base" render times for bailouts.
957
- stopBaseRenderTimerIfRunning();
954
+ stopProfilerTimerIfRunning(workInProgress);
955
}
956
957
// Check if the children have any pending work.
@@ -991,12 +988,6 @@ function beginWork(
988
workInProgress: Fiber,
989
renderExpirationTime: ExpirationTime,
990
): Fiber | null {
994
- if (enableProfilerTimer) {
995
- if (workInProgress.mode & ProfileMode) {
996
- markActualRenderTimeStarted(workInProgress);
997
- }
998
- }
999
-
991
const updateExpirationTime = workInProgress.expirationTime;
992
if (
993
!hasLegacyContextChanged() &&
packages/react-reconciler/src/ReactFiberCompleteWork.js
-13
@@ -20,7 +20,6 @@ import type {
20
HostContext,
21
} from './ReactFiberHostConfig';
22
23
-import {enableProfilerTimer} from 'shared/ReactFeatureFlags';
23
import {
24
IndeterminateComponent,
25
FunctionalComponent,
@@ -38,7 +37,6 @@ import {
37
PlaceholderComponent,
38
} from 'shared/ReactTypeOfWork';
39
import {Placement, Ref, Update} from 'shared/ReactTypeOfSideEffect';
41
-import {ProfileMode} from './ReactTypeOfMode';
40
import invariant from 'shared/invariant';
41
42
import {
@@ -60,7 +58,6 @@ import {
58
getHostContext,
59
popHostContainer,
60
} from './ReactFiberHostContext';
63
-import {recordElapsedActualRenderTime} from './ReactProfilerTimer';
61
import {
62
popContextProvider as popLegacyContextProvider,
63
popTopLevelContextObject as popTopLevelLegacyContextObject,
@@ -518,16 +515,6 @@ function completeWork(
515
);
516
}
517
521
- if (enableProfilerTimer) {
522
- if (workInProgress.mode & ProfileMode) {
523
- // Don't record elapsed time unless the "complete" phase has succeeded.
524
- // Certain renderers may error during this phase (i.e. ReactNative View/Text nesting validation).
525
- // If an error occurs, we'll mark the time while unwinding.
526
- // This simplifies the unwinding logic and ensures consistency.
527
- recordElapsedActualRenderTime(workInProgress);
528
- }
529
- }
530
-
518
return null;
519
}
520
packages/react-reconciler/src/ReactFiberScheduler.js
+64
-71
@@ -112,15 +112,9 @@ import {
112
import {popProvider, resetContextDependences} from './ReactFiberNewContext';
113
import {popHostContext, popHostContainer} from './ReactFiberHostContext';
114
import {
115
- checkActualRenderTimeStackEmpty,
116
- pauseActualRenderTimerIfRunning,
115
recordCommitTime,
118
- recordElapsedActualRenderTime,
119
- recordElapsedBaseRenderTimeIfRunning,
120
- resetActualRenderTimerStackAfterFatalErrorInDev,
121
- resumeActualRenderTimerIfPaused,
122
- startBaseRenderTimer,
123
- stopBaseRenderTimerIfRunning,
116
+ startProfilerTimer,
117
+ stopProfilerTimerIfRunningAndRecordDelta,
118
} from './ReactProfilerTimer';
119
import {
120
checkThatStackIsEmpty,
@@ -312,15 +306,6 @@ if (__DEV__ && replayFailedUnitOfWorkWithInvokeGuardedCallback) {
306
originalReplayError = null;
307
if (hasCaughtError()) {
308
clearCaughtError();
315
-
316
- if (enableProfilerTimer) {
317
- if (failedUnitOfWork.mode & ProfileMode) {
318
- recordElapsedActualRenderTime(failedUnitOfWork);
319
- }
320
-
321
- // Stop "base" render timer again (after the re-thrown error).
322
- stopBaseRenderTimerIfRunning();
323
- }
309
} else {
310
// If the begin phase did not fail the second time, set this pointer
311
// back to the original value.
@@ -336,12 +321,6 @@ function resetStack() {
321
if (nextUnitOfWork !== null) {
322
let interruptedWork = nextUnitOfWork.return;
323
while (interruptedWork !== null) {
339
- if (enableProfilerTimer) {
340
- if (interruptedWork.mode & ProfileMode) {
341
- // Resume in case we're picking up on work that was paused.
342
- resumeActualRenderTimerIfPaused(false);
343
- }
344
- }
324
unwindInterruptedWork(interruptedWork);
325
interruptedWork = interruptedWork.return;
326
}
@@ -691,17 +670,6 @@ function commitRoot(root: FiberRoot, finishedWork: Fiber): void {
670
}
671
}
672
694
- if (enableProfilerTimer) {
695
- if (__DEV__) {
696
- if (nextRoot === null) {
697
- // Only check this stack once we're done processing async work.
698
- // This prevents a false positive that occurs after a batched commit,
699
- // If there was in-progress async work before the commit.
700
- checkActualRenderTimeStackEmpty();
701
- }
702
- }
703
- }
704
-
673
isCommitting = false;
674
isWorking = false;
675
stopCommitLifeCyclesTimer();
@@ -741,9 +709,22 @@ function resetChildExpirationTime(
709
710
// Bubble up the earliest expiration time.
711
if (enableProfilerTimer && workInProgress.mode & ProfileMode) {
744
- // We're in profiling mode. Let's use this same traversal to update the
745
- // "base" render times.
712
+ // We're in profiling mode.
713
+ // Let's use this same traversal to update the render durations.
714
+ let actualDuration = workInProgress.actualDuration;
715
let treeBaseDuration = workInProgress.selfBaseDuration;
716
+
717
+ // When a fiber is cloned, its actualDuration is reset to 0.
718
+ // This value will only be updated if work is done on the fiber (i.e. it doesn't bailout).
719
+ // When work is done, it should bubble to the parent's actualDuration.
720
+ // If the fiber has not been cloned though, (meaning no work was done),
721
+ // Then this value will reflect the amount of time spent working on a previous render.
722
+ // In that case it should not bubble.
723
+ // We determine whether it was cloned by comparing the child pointer.
724
+ const shouldBubbleActualDurations =
725
+ workInProgress.alternate === null ||
726
+ workInProgress.child !== workInProgress.alternate.child;
727
+
728
let child = workInProgress.child;
729
while (child !== null) {
730
const childUpdateExpirationTime = child.expirationTime;
@@ -762,9 +743,13 @@ function resetChildExpirationTime(
743
) {
744
newChildExpirationTime = childChildExpirationTime;
745
}
746
+ if (shouldBubbleActualDurations) {
747
+ actualDuration += child.actualDuration;
748
+ }
749
treeBaseDuration += child.treeBaseDuration;
750
child = child.sibling;
751
}
752
+ workInProgress.actualDuration = actualDuration;
753
workInProgress.treeBaseDuration = treeBaseDuration;
754
} else {
755
let child = workInProgress.child;
@@ -811,11 +796,28 @@ function completeUnitOfWork(workInProgress: Fiber): Fiber | null {
796
797
if ((workInProgress.effectTag & Incomplete) === NoEffect) {
798
// This fiber completed.
814
- nextUnitOfWork = completeWork(
815
- current,
816
- workInProgress,
817
- nextRenderExpirationTime,
818
- );
799
+ if (enableProfilerTimer) {
800
+ if (workInProgress.mode & ProfileMode) {
801
+ startProfilerTimer(workInProgress);
802
+ }
803
+
804
+ nextUnitOfWork = completeWork(
805
+ current,
806
+ workInProgress,
807
+ nextRenderExpirationTime,
808
+ );
809
+
810
+ if (workInProgress.mode & ProfileMode) {
811
+ // Update render duration assuming we didn't error.
812
+ stopProfilerTimerIfRunningAndRecordDelta(workInProgress, false);
813
+ }
814
+ } else {
815
+ nextUnitOfWork = completeWork(
816
+ current,
817
+ workInProgress,
818
+ nextRenderExpirationTime,
819
+ );
820
+ }
821
let next = nextUnitOfWork;
822
stopWorkTimer(workInProgress);
823
resetChildExpirationTime(workInProgress, nextRenderExpirationTime);
@@ -886,6 +888,11 @@ function completeUnitOfWork(workInProgress: Fiber): Fiber | null {
888
return null;
889
}
890
} else {
891
+ if (workInProgress.mode & ProfileMode) {
892
+ // Record the render duration for the fiber that errored.
893
+ stopProfilerTimerIfRunningAndRecordDelta(workInProgress, false);
894
+ }
895
+
896
// This fiber did not complete because something threw. Pop values off
897
// the stack without entering the complete phase. If this is a boundary,
898
// capture values if possible.
@@ -908,6 +915,19 @@ function completeUnitOfWork(workInProgress: Fiber): Fiber | null {
915
ReactFiberInstrumentation.debugTool.onCompleteWork(workInProgress);
916
}
917
918
+ if (enableProfilerTimer) {
919
+ // Include the time spent working on failed children before continuing.
920
+ if (next.mode & ProfileMode) {
921
+ let actualDuration = next.actualDuration;
922
+ let child = next.child;
923
+ while (child !== null) {
924
+ actualDuration += child.actualDuration;
925
+ child = child.sibling;
926
+ }
927
+ next.actualDuration = actualDuration;
928
+ }
929
+ }
930
+
931
// If completing this work spawned new work, do that next. We'll come
932
// back here again.
933
// Since we're restarting, remove anything that is not a host effect
@@ -968,15 +988,14 @@ function performUnitOfWork(workInProgress: Fiber): Fiber | null {
988
let next;
989
if (enableProfilerTimer) {
990
if (workInProgress.mode & ProfileMode) {
971
- startBaseRenderTimer();
991
+ startProfilerTimer(workInProgress);
992
}
993
994
next = beginWork(current, workInProgress, nextRenderExpirationTime);
995
996
if (workInProgress.mode & ProfileMode) {
977
- // Update "base" time if the render wasn't bailed out on.
978
- recordElapsedBaseRenderTimeIfRunning(workInProgress);
979
- stopBaseRenderTimerIfRunning();
997
+ // Record the render duration assuming we didn't bailout (or error).
998
+ stopProfilerTimerIfRunningAndRecordDelta(workInProgress, true);
999
}
1000
} else {
1001
next = beginWork(current, workInProgress, nextRenderExpirationTime);
@@ -1017,12 +1036,6 @@ function workLoop(isYieldy) {
1036
while (nextUnitOfWork !== null && !shouldYield()) {
1037
nextUnitOfWork = performUnitOfWork(nextUnitOfWork);
1038
}
1020
-
1021
- if (enableProfilerTimer) {
1022
- // If we didn't finish, pause the "actual" render timer.
1023
- // We'll restart it when we resume work.
1024
- pauseActualRenderTimerIfRunning();
1025
- }
1039
}
1040
}
1041
@@ -1068,11 +1081,6 @@ function renderRoot(
1081
try {
1082
workLoop(isYieldy);
1083
} catch (thrownValue) {
1071
- if (enableProfilerTimer) {
1072
- // Stop "base" render timer in the event of an error.
1073
- stopBaseRenderTimerIfRunning();
1074
- }
1075
-
1084
if (nextUnitOfWork === null) {
1085
// This is a fatal error.
1086
didFatal = true;
@@ -1139,10 +1147,6 @@ function renderRoot(
1147
// There was a fatal error.
1148
if (__DEV__) {
1149
resetStackAfterFatalErrorInDev();
1142
-
1143
- // Reset the DEV fiber stack in case we're profiling roots.
1144
- // (We do this for profiling bulds when DevTools is detected.)
1145
- resetActualRenderTimerStackAfterFatalErrorInDev();
1150
}
1151
// `nextRoot` points to the in-progress root. A non-null value indicates
1152
// that we're in the middle of an async render. Set it to null to indicate
@@ -1871,10 +1875,6 @@ function performWork(minExpirationTime: ExpirationTime, dl: Deadline | null) {
1875
// the deadline.
1876
findHighestPriorityRoot();
1877
1874
- if (enableProfilerTimer) {
1875
- resumeActualRenderTimerIfPaused(minExpirationTime === Sync);
1876
- }
1877
-
1878
if (deadline !== null) {
1879
recomputeCurrentRendererTime();
1880
currentSchedulerTime = currentRendererTime;
@@ -1947,7 +1947,6 @@ function flushRoot(root: FiberRoot, expirationTime: ExpirationTime) {
1947
performWorkOnRoot(root, expirationTime, true);
1948
// Flush any sync work that was scheduled by lifecycles
1949
performSyncWork();
1950
- pauseActualRenderTimerIfRunning();
1950
}
1951
1952
function finishRendering() {
@@ -2049,12 +2048,6 @@ function performWorkOnRoot(
2048
// There's no time left. Mark this root as complete. We'll come
2049
// back and commit it later.
2050
root.finishedWork = finishedWork;
2052
-
2053
- if (enableProfilerTimer) {
2054
- // If we didn't finish, pause the "actual" render timer.
2055
- // We'll restart it when we resume work.
2056
- pauseActualRenderTimerIfRunning();
2057
- }
2051
}
2052
}
2053
}
packages/react-reconciler/src/ReactFiberUnwindWork.js
+1
-15
@@ -34,10 +34,9 @@ import {
34
} from 'shared/ReactTypeOfSideEffect';
35
import {
36
enableGetDerivedStateFromCatch,
37
- enableProfilerTimer,
37
enableSuspense,
38
} from 'shared/ReactFeatureFlags';
40
-import {ProfileMode, StrictMode, AsyncMode} from './ReactTypeOfMode';
39
+import {StrictMode, AsyncMode} from './ReactTypeOfMode';
40
41
import {createCapturedValue} from './ReactCapturedValue';
42
import {
@@ -52,7 +51,6 @@ import {
51
popTopLevelContextObject as popTopLevelLegacyContextObject,
52
} from './ReactFiberContext';
53
import {popProvider} from './ReactFiberNewContext';
55
-import {recordElapsedActualRenderTime} from './ReactProfilerTimer';
54
import {
55
renderDidSuspend,
56
renderDidError,
@@ -380,12 +378,6 @@ function unwindWork(
378
workInProgress: Fiber,
379
renderExpirationTime: ExpirationTime,
380
) {
383
- if (enableProfilerTimer) {
384
- if (workInProgress.mode & ProfileMode) {
385
- recordElapsedActualRenderTime(workInProgress);
386
- }
387
- }
388
-
381
switch (workInProgress.tag) {
382
case ClassComponent: {
383
popLegacyContextProvider(workInProgress);
@@ -432,12 +424,6 @@ function unwindWork(
424
}
425
426
function unwindInterruptedWork(interruptedWork: Fiber) {
435
- if (enableProfilerTimer) {
436
- if (interruptedWork.mode & ProfileMode) {
437
- recordElapsedActualRenderTime(interruptedWork);
438
- }
439
- }
440
-
427
switch (interruptedWork.tag) {
428
case ClassComponent: {
429
popLegacyContextProvider(interruptedWork);
packages/react-reconciler/src/ReactProfilerTimer.js
+23
-138
@@ -9,27 +9,20 @@
9
10
import type {Fiber} from './ReactFiber';
11
12
-import getComponentName from 'shared/getComponentName';
12
import {enableProfilerTimer} from 'shared/ReactFeatureFlags';
13
15
-import warningWithoutStack from 'shared/warningWithoutStack';
14
import {now} from './ReactFiberHostConfig';
15
16
export type ProfilerTimer = {
19
- checkActualRenderTimeStackEmpty(): void,
17
getCommitTime(): number,
21
- markActualRenderTimeStarted(fiber: Fiber): void,
22
- pauseActualRenderTimerIfRunning(): void,
23
- recordElapsedActualRenderTime(fiber: Fiber): void,
24
- resumeActualRenderTimerIfPaused(isProcessingBatchCommit: boolean): void,
18
recordCommitTime(): void,
26
- recordElapsedBaseRenderTimeIfRunning(fiber: Fiber): void,
27
- resetActualRenderTimerStackAfterFatalErrorInDev(): void,
28
- startBaseRenderTimer(): void,
29
- stopBaseRenderTimerIfRunning(): void,
19
+ startProfilerTimer(fiber: Fiber): void,
20
+ stopProfilerTimerIfRunning(fiber: Fiber): void,
21
+ stopProfilerTimerIfRunningAndRecordDelta(fiber: Fiber): void,
22
};
23
24
let commitTime: number = 0;
25
+let profilerStartTime: number = -1;
26
27
function getCommitTime(): number {
28
return commitTime;
@@ -42,155 +35,47 @@ function recordCommitTime(): void {
35
commitTime = now();
36
}
37
45
-/**
46
- * The "actual" render time is total time required to render the descendants of a Profiler component.
47
- * This time is stored as a stack, since Profilers can be nested.
48
- * This time is started during the "begin" phase and stopped during the "complete" phase.
49
- * It is paused (and accumulated) in the event of an interruption or an aborted render.
50
- */
51
-
52
-let fiberStack: Array<Fiber | null>;
53
-
54
-if (__DEV__) {
55
- fiberStack = [];
56
-}
57
-
58
-let syncCommitStartTime: number = 0;
59
-let timerPausedAt: number = 0;
60
-let totalElapsedPauseTime: number = 0;
61
-
62
-function checkActualRenderTimeStackEmpty(): void {
63
- if (!enableProfilerTimer) {
64
- return;
65
- }
66
- if (__DEV__) {
67
- warningWithoutStack(
68
- fiberStack.length === 0,
69
- 'Expected an empty stack. Something was not reset properly.',
70
- );
71
- }
72
-}
73
-
74
-function markActualRenderTimeStarted(fiber: Fiber): void {
75
- if (!enableProfilerTimer) {
76
- return;
77
- }
78
- if (__DEV__) {
79
- fiberStack.push(fiber);
80
- }
81
-
82
- fiber.actualDuration =
83
- now() - ((fiber.actualDuration: any): number) - totalElapsedPauseTime;
84
- fiber.actualStartTime = now();
85
-}
86
-
87
-function pauseActualRenderTimerIfRunning(): void {
88
- if (!enableProfilerTimer) {
89
- return;
90
- }
91
- if (timerPausedAt === 0) {
92
- timerPausedAt = now();
93
- }
94
- if (syncCommitStartTime > 0) {
95
- // Don't count the time spent processing sycn work,
96
- // Against yielded async work that will be resumed later.
97
- totalElapsedPauseTime += now() - syncCommitStartTime;
98
- syncCommitStartTime = 0;
99
- } else {
100
- totalElapsedPauseTime = 0;
101
- }
102
-}
103
-
104
-function recordElapsedActualRenderTime(fiber: Fiber): void {
38
+function startProfilerTimer(fiber: Fiber): void {
39
if (!enableProfilerTimer) {
40
return;
41
}
108
- if (__DEV__) {
109
- warningWithoutStack(
110
- fiber === fiberStack.pop(),
111
- 'Unexpected Fiber (%s) popped.',
112
- getComponentName(fiber.type),
113
- );
114
- }
42
116
- fiber.actualDuration =
117
- now() - totalElapsedPauseTime - ((fiber.actualDuration: any): number);
118
-}
43
+ profilerStartTime = now();
44
120
-function resumeActualRenderTimerIfPaused(isProcessingSyncWork: boolean): void {
121
- if (!enableProfilerTimer) {
122
- return;
123
- }
124
- if (isProcessingSyncWork && syncCommitStartTime === 0) {
125
- syncCommitStartTime = now();
126
- }
127
- if (timerPausedAt > 0) {
128
- totalElapsedPauseTime += now() - timerPausedAt;
129
- timerPausedAt = 0;
45
+ if (((fiber.actualStartTime: any): number) < 0) {
46
+ fiber.actualStartTime = now();
47
}
48
}
49
133
-function resetActualRenderTimerStackAfterFatalErrorInDev(): void {
50
+function stopProfilerTimerIfRunning(fiber: Fiber): void {
51
if (!enableProfilerTimer) {
52
return;
53
}
137
- if (__DEV__) {
138
- fiberStack.length = 0;
139
- }
54
+ profilerStartTime = -1;
55
}
56
142
-/**
143
- * The "base" render time is the duration of the “begin” phase of work for a particular fiber.
144
- * This time is measured and stored on each fiber.
145
- * The time for all sibling fibers are accumulated and stored on their parent during the "complete" phase.
146
- * If a fiber bails out (sCU false) then its "base" timer is cancelled and the fiber is not updated.
147
- */
148
-
149
-let baseStartTime: number = -1;
150
-
151
-function recordElapsedBaseRenderTimeIfRunning(fiber: Fiber): void {
57
+function stopProfilerTimerIfRunningAndRecordDelta(
58
+ fiber: Fiber,
59
+ overrideBaseTime: boolean,
60
+): void {
61
if (!enableProfilerTimer) {
62
return;
63
}
155
- if (baseStartTime !== -1) {
156
- fiber.selfBaseDuration = now() - baseStartTime;
157
- }
158
-}
64
160
-function startBaseRenderTimer(): void {
161
- if (!enableProfilerTimer) {
162
- return;
163
- }
164
- if (__DEV__) {
165
- if (baseStartTime !== -1) {
166
- warningWithoutStack(
167
- false,
168
- 'Cannot start base timer that is already running. ' +
169
- 'This error is likely caused by a bug in React. ' +
170
- 'Please file an issue.',
171
- );
65
+ if (profilerStartTime >= 0) {
66
+ const elapsedTime = now() - profilerStartTime;
67
+ fiber.actualDuration += elapsedTime;
68
+ if (overrideBaseTime) {
69
+ fiber.selfBaseDuration = elapsedTime;
70
}
71
+ profilerStartTime = -1;
72
}
174
- baseStartTime = now();
175
-}
176
-
177
-function stopBaseRenderTimerIfRunning(): void {
178
- if (!enableProfilerTimer) {
179
- return;
180
- }
181
- baseStartTime = -1;
73
}
74
75
export {
185
- checkActualRenderTimeStackEmpty,
76
getCommitTime,
187
- markActualRenderTimeStarted,
188
- pauseActualRenderTimerIfRunning,
77
recordCommitTime,
190
- recordElapsedActualRenderTime,
191
- resetActualRenderTimerStackAfterFatalErrorInDev,
192
- resumeActualRenderTimerIfPaused,
193
- recordElapsedBaseRenderTimeIfRunning,
194
- startBaseRenderTimer,
195
- stopBaseRenderTimerIfRunning,
78
+ startProfilerTimer,
79
+ stopProfilerTimerIfRunning,
80
+ stopProfilerTimerIfRunningAndRecordDelta,
81
};
packages/react/src/__tests__/ReactProfiler-test.internal.js
+32
-31
@@ -57,7 +57,7 @@ describe('Profiler', () => {
57
58
// This will throw in production too,
59
// But the test is only interested in verifying the DEV error message.
60
- if (__DEV__) {
60
+ if (__DEV__ && flagEnabled) {
61
it('should warn if required params are missing', () => {
62
expect(() => {
63
ReactTestRenderer.create(<React.unstable_Profiler />);
@@ -196,11 +196,10 @@ describe('Profiler', () => {
196
);
197
198
// Should be called two times:
199
- // 1. To mark the start (resuming) of work
200
- // 2. To compute the update expiration time,
201
- // 3. To record the commit time.
199
+ // 2. To compute the update expiration time
200
+ // 3. To record the commit time
201
// No additional calls from ProfilerTimer are expected.
203
- expect(mockNow).toHaveBeenCalledTimes(3);
202
+ expect(mockNow).toHaveBeenCalledTimes(2);
203
});
204
205
it('logs render times for both mount and update', () => {
@@ -422,19 +421,19 @@ describe('Profiler', () => {
421
const renderer = ReactTestRenderer.create(
422
<React.unstable_Profiler id="test" onRender={callback}>
423
<AdvanceTime byAmount={10}>
425
- <AdvanceTime byAmount={10} shouldComponentUpdate={false} />
424
+ <AdvanceTime byAmount={13} shouldComponentUpdate={false} />
425
</AdvanceTime>
426
</React.unstable_Profiler>,
427
);
428
429
expect(callback).toHaveBeenCalledTimes(1);
430
432
- advanceTimeBy(30); // 25 -> 55
431
+ advanceTimeBy(30); // 28 -> 58
432
433
renderer.update(
434
<React.unstable_Profiler id="test" onRender={callback}>
436
- <AdvanceTime byAmount={10}>
437
- <AdvanceTime byAmount={10} shouldComponentUpdate={false} />
435
+ <AdvanceTime byAmount={4}>
436
+ <AdvanceTime byAmount={7} shouldComponentUpdate={false} />
437
</AdvanceTime>
438
</React.unstable_Profiler>,
439
);
@@ -444,16 +443,16 @@ describe('Profiler', () => {
443
const [mountCall, updateCall] = callback.mock.calls;
444
445
expect(mountCall[1]).toBe('mount');
447
- expect(mountCall[2]).toBe(20); // actual time
448
- expect(mountCall[3]).toBe(20); // base time
446
+ expect(mountCall[2]).toBe(23); // actual time
447
+ expect(mountCall[3]).toBe(23); // base time
448
expect(mountCall[4]).toBe(5); // start time
450
- expect(mountCall[5]).toBe(25); // commit time
449
+ expect(mountCall[5]).toBe(28); // commit time
450
451
expect(updateCall[1]).toBe('update');
453
- expect(updateCall[2]).toBe(10); // actual time
454
- expect(updateCall[3]).toBe(20); // base time
455
- expect(updateCall[4]).toBe(55); // start time
456
- expect(updateCall[5]).toBe(65); // commit time
452
+ expect(updateCall[2]).toBe(4); // actual time
453
+ expect(updateCall[3]).toBe(17); // base time
454
+ expect(updateCall[4]).toBe(58); // start time
455
+ expect(updateCall[5]).toBe(62); // commit time
456
});
457
458
it('includes time spent in render phase lifecycles', () => {
@@ -809,7 +808,7 @@ describe('Profiler', () => {
808
]);
809
810
// The actual time should include only the most recent render (37ms),
812
- // Because this lets us avoid a lot of commit phase reset complexity.
811
+ // Because this greatly simplifies the commit phase logic.
812
// The base time should include the more recent times for the SecondComponent subtree,
813
// As well as the original times for the FirstComponent subtree.
814
expect(callback).toHaveBeenCalledTimes(1);
@@ -856,7 +855,7 @@ describe('Profiler', () => {
855
const callback = jest.fn();
856
857
const ThrowsError = () => {
859
- advanceTimeBy(10);
858
+ advanceTimeBy(3);
859
throw Error('expected error');
860
};
861
@@ -880,7 +879,7 @@ describe('Profiler', () => {
879
ReactTestRenderer.create(
880
<React.unstable_Profiler id="test" onRender={callback}>
881
<ErrorBoundary>
883
- <AdvanceTime byAmount={5} />
882
+ <AdvanceTime byAmount={9} />
883
<ThrowsError />
884
</ErrorBoundary>
885
</React.unstable_Profiler>,
@@ -891,18 +890,19 @@ describe('Profiler', () => {
890
// Callbacks bubble (reverse order).
891
let [mountCall, updateCall] = callback.mock.calls;
892
894
- // The initial mount only includes the ErrorBoundary (which takes 2ms)
893
+ // The initial mount only includes the ErrorBoundary (which takes 2)
894
// But it spends time rendering all of the failed subtree also.
895
expect(mountCall[1]).toBe('mount');
897
- // actual time includes: 2 (ErrorBoundary) + 5 (AdvanceTime) + 10 (ThrowsError)
898
- // If replayFailedUnitOfWorkWithInvokeGuardedCallback is enbaled, ThrowsError is replayed.
899
- expect(mountCall[2]).toBe(flagEnabled && __DEV__ ? 27 : 17);
896
+ // actual time includes: 2 (ErrorBoundary) + 9 (AdvanceTime) + 3 (ThrowsError)
897
+ // We don't count the time spent in replaying the failed unit of work (ThrowsError)
898
+ expect(mountCall[2]).toBe(14);
899
// base time includes: 2 (ErrorBoundary)
900
expect(mountCall[3]).toBe(2);
901
// start time
902
expect(mountCall[4]).toBe(5);
904
- // commit time
905
- expect(mountCall[5]).toBe(flagEnabled && __DEV__ ? 32 : 22);
903
+ // commit time: 5 initially + 14 of work
904
+ // Add an additional 3 (ThrowsError) if we replaced the failed work
905
+ expect(mountCall[5]).toBe(__DEV__ && flagEnabled ? 22 : 19);
906
907
// The update includes the ErrorBoundary and its fallback child
908
expect(updateCall[1]).toBe('update');
@@ -911,9 +911,10 @@ describe('Profiler', () => {
911
// base time includes: 2 (ErrorBoundary) + 20 (AdvanceTime)
912
expect(updateCall[3]).toBe(22);
913
// start time
914
- expect(updateCall[4]).toBe(flagEnabled && __DEV__ ? 32 : 22);
915
- // commit time
916
- expect(updateCall[5]).toBe(flagEnabled && __DEV__ ? 54 : 44);
914
+ expect(updateCall[4]).toBe(__DEV__ && flagEnabled ? 22 : 19);
915
+ // commit time: 19 (startTime) + 2 (ErrorBoundary) + 20 (AdvanceTime)
916
+ // Add an additional 3 (ThrowsError) if we replaced the failed work
917
+ expect(updateCall[5]).toBe(__DEV__ && flagEnabled ? 44 : 41);
918
});
919
920
it('should accumulate actual time after an error handled by getDerivedStateFromCatch()', () => {
@@ -960,14 +961,14 @@ describe('Profiler', () => {
961
expect(mountCall[1]).toBe('mount');
962
// actual time includes: 2 (ErrorBoundary) + 5 (AdvanceTime) + 10 (ThrowsError)
963
// Then the re-render: 2 (ErrorBoundary) + 20 (AdvanceTime)
963
- // If replayFailedUnitOfWorkWithInvokeGuardedCallback is enbaled, ThrowsError is replayed.
964
- expect(mountCall[2]).toBe(flagEnabled && __DEV__ ? 49 : 39);
964
+ // We don't count the time spent in replaying the failed unit of work (ThrowsError)
965
+ expect(mountCall[2]).toBe(39);
966
// base time includes: 2 (ErrorBoundary) + 20 (AdvanceTime)
967
expect(mountCall[3]).toBe(22);
968
// start time
969
expect(mountCall[4]).toBe(5);
970
// commit time
970
- expect(mountCall[5]).toBe(flagEnabled && __DEV__ ? 54 : 44);
971
+ expect(mountCall[5]).toBe(__DEV__ && flagEnabled ? 54 : 44);
972
});
973
974
it('should reset the fiber stack correct after a "complete" phase error', () => {