Pass "start time" and "commit time" to Profiler callback (#12852)
* Added start time parameter to Profiler onRender callback * Profiler also captures commit time * Only init Profiler stateNode if enableProfilerTimer feature flag enabled
Brian Vaughn committed
May 21, 2018 at 09:49 UTC
13003654e79f9fa65ee833afeec86d668f35d31d
5 files changed
+229
-96
packages/react-reconciler/src/ReactFiber.js
+7
-4
@@ -460,10 +460,13 @@ export function createFiberFromProfiler(
460
const fiber = createFiber(Profiler, pendingProps, key, mode | ProfileMode);
461
fiber.type = REACT_PROFILER_TYPE;
462
fiber.expirationTime = expirationTime;
463
- fiber.stateNode = {
464
- duration: 0,
465
- startTime: 0,
466
- };
463
+ if (enableProfilerTimer) {
464
+ fiber.stateNode = {
465
+ elapsedPauseTimeAtStart: 0,
466
+ duration: 0,
467
+ startTime: 0,
468
+ };
469
+ }
470
471
return fiber;
472
}
packages/react-reconciler/src/ReactFiberCommitWork.js
+3
@@ -20,6 +20,7 @@ import type {ExpirationTime} from './ReactFiberExpirationTime';
20
import type {CapturedValue, CapturedError} from './ReactCapturedValue';
21
22
import {enableProfilerTimer} from 'shared/ReactFeatureFlags';
23
+import {getCommitTime} from './ReactProfilerTimer';
24
import {
25
ClassComponent,
26
HostRoot,
@@ -807,6 +808,8 @@ function commitWork(current: Fiber | null, finishedWork: Fiber): void {
808
current === null ? 'mount' : 'update',
809
finishedWork.stateNode.duration,
810
finishedWork.treeBaseTime,
811
+ finishedWork.stateNode.startTime,
812
+ getCommitTime(),
813
);
814
815
// Reset actualTime after successful commit.
packages/react-reconciler/src/ReactFiberScheduler.js
+5
@@ -104,6 +104,7 @@ import {popHostContext, popHostContainer} from './ReactFiberHostContext';
104
import {
105
checkActualRenderTimeStackEmpty,
106
pauseActualRenderTimerIfRunning,
107
+ recordCommitTime,
108
recordElapsedBaseRenderTimeIfRunning,
109
resetActualRenderTimer,
110
resumeActualRenderTimerIfPaused,
@@ -566,6 +567,10 @@ function commitRoot(finishedWork: Fiber): ExpirationTime {
567
}
568
stopCommitSnapshotEffectsTimer();
569
570
+ if (enableProfilerTimer) {
571
+ recordCommitTime();
572
+ }
573
+
574
// Commit all the side-effects within a tree. We'll do this in two passes.
575
// The first pass performs all the host insertions, updates, deletions and
576
// ref unmounts.
packages/react-reconciler/src/ReactProfilerTimer.js
+32
-10
@@ -14,25 +14,40 @@ import {enableProfilerTimer} from 'shared/ReactFeatureFlags';
14
import warning from 'fbjs/lib/warning';
15
import {now} from './ReactFiberHostConfig';
16
17
-/**
18
- * The "actual" render time is total time required to render the descendants of a Profiler component.
19
- * This time is stored as a stack, since Profilers can be nested.
20
- * This time is started during the "begin" phase and stopped during the "complete" phase.
21
- * It is paused (and accumulated) in the event of an interruption or an aborted render.
22
- */
23
-
17
export type ProfilerTimer = {
18
checkActualRenderTimeStackEmpty(): void,
19
+ getCommitTime(): number,
20
markActualRenderTimeStarted(fiber: Fiber): void,
21
pauseActualRenderTimerIfRunning(): void,
22
recordElapsedActualRenderTime(fiber: Fiber): void,
23
resetActualRenderTimer(): void,
24
resumeActualRenderTimerIfPaused(): void,
25
+ recordCommitTime(): void,
26
recordElapsedBaseRenderTimeIfRunning(fiber: Fiber): void,
27
startBaseRenderTimer(): void,
28
stopBaseRenderTimerIfRunning(): void,
29
};
30
31
+let commitTime: number = 0;
32
+
33
+function getCommitTime(): number {
34
+ return commitTime;
35
+}
36
+
37
+function recordCommitTime(): void {
38
+ if (!enableProfilerTimer) {
39
+ return;
40
+ }
41
+ commitTime = now();
42
+}
43
+
44
+/**
45
+ * The "actual" render time is total time required to render the descendants of a Profiler component.
46
+ * This time is stored as a stack, since Profilers can be nested.
47
+ * This time is started during the "begin" phase and stopped during the "complete" phase.
48
+ * It is paused (and accumulated) in the event of an interruption or an aborted render.
49
+ */
50
+
51
let fiberStack: Array<Fiber | null>;
52
53
if (__DEV__) {
@@ -61,7 +76,9 @@ function markActualRenderTimeStarted(fiber: Fiber): void {
76
if (__DEV__) {
77
fiberStack.push(fiber);
78
}
64
- fiber.stateNode.startTime = now() - totalElapsedPauseTime;
79
+ const stateNode = fiber.stateNode;
80
+ stateNode.elapsedPauseTimeAtStart = totalElapsedPauseTime;
81
+ stateNode.startTime = now();
82
}
83
84
function pauseActualRenderTimerIfRunning(): void {
@@ -80,8 +97,11 @@ function recordElapsedActualRenderTime(fiber: Fiber): void {
97
if (__DEV__) {
98
warning(fiber === fiberStack.pop(), 'Unexpected Fiber popped.');
99
}
83
- fiber.stateNode.duration +=
84
- now() - totalElapsedPauseTime - fiber.stateNode.startTime;
100
+ const stateNode = fiber.stateNode;
101
+ stateNode.duration +=
102
+ now() -
103
+ (totalElapsedPauseTime - stateNode.elapsedPauseTimeAtStart) -
104
+ stateNode.startTime;
105
}
106
107
function resetActualRenderTimer(): void {
@@ -145,8 +165,10 @@ function stopBaseRenderTimerIfRunning(): void {
165
166
export {
167
checkActualRenderTimeStackEmpty,
168
+ getCommitTime,
169
markActualRenderTimeStarted,
170
pauseActualRenderTimerIfRunning,
171
+ recordCommitTime,
172
recordElapsedActualRenderTime,
173
resetActualRenderTimer,
174
resumeActualRenderTimerIfPaused,
packages/react/src/__tests__/ReactProfiler-test.internal.js
+182
-82
@@ -177,14 +177,18 @@ describe('Profiler', () => {
177
</div>,
178
);
179
180
- // Should only be called twice, for normal expiration time purposes.
180
+ // Should only be called three times:
181
+ // Twice for normal expiration time purposes,
182
+ // And once to capture the commit time.
183
// No additional calls from ProfilerTimer are expected.
182
- expect(mockNow).toHaveBeenCalledTimes(2);
184
+ expect(mockNow).toHaveBeenCalledTimes(3);
185
});
186
187
it('logs render times for both mount and update', () => {
188
const callback = jest.fn();
189
190
+ advanceTimeBy(5); // 0 -> 5
191
+
192
const renderer = ReactTestRenderer.create(
193
<React.unstable_Profiler id="test" onRender={callback}>
194
<AdvanceTime />
@@ -195,14 +199,18 @@ describe('Profiler', () => {
199
200
let [call] = callback.mock.calls;
201
198
- expect(call).toHaveLength(4);
202
+ expect(call).toHaveLength(6);
203
expect(call[0]).toBe('test');
204
expect(call[1]).toBe('mount');
201
- expect(call[2]).toBe(10); // "actual" time
202
- expect(call[3]).toBe(10); // "base" time
205
+ expect(call[2]).toBe(10); // actual time
206
+ expect(call[3]).toBe(10); // base time
207
+ expect(call[4]).toBe(5); // start time
208
+ expect(call[5]).toBe(15); // commit time
209
210
callback.mockReset();
211
212
+ advanceTimeBy(20); // 15 -> 35
213
+
214
renderer.update(
215
<React.unstable_Profiler id="test" onRender={callback}>
216
<AdvanceTime />
@@ -213,16 +221,20 @@ describe('Profiler', () => {
221
222
[call] = callback.mock.calls;
223
216
- expect(call).toHaveLength(4);
224
+ expect(call).toHaveLength(6);
225
expect(call[0]).toBe('test');
226
expect(call[1]).toBe('update');
219
- expect(call[2]).toBe(10); // "actual" time
220
- expect(call[3]).toBe(10); // "base" time
227
+ expect(call[2]).toBe(10); // actual time
228
+ expect(call[3]).toBe(10); // base time
229
+ expect(call[4]).toBe(35); // start time
230
+ expect(call[5]).toBe(45); // commit time
231
});
232
233
it('includes render times of nested Profilers in their parent times', () => {
234
const callback = jest.fn();
235
236
+ advanceTimeBy(5); // 0 -> 5
237
+
238
ReactTestRenderer.create(
239
<React.Fragment>
240
<React.unstable_Profiler id="parent" onRender={callback}>
@@ -243,15 +255,21 @@ describe('Profiler', () => {
255
expect(parentCall[0]).toBe('parent');
256
257
// Parent times should include child times
246
- expect(childCall[2]).toBe(20); // "actual" time
247
- expect(childCall[3]).toBe(20); // "base" time
248
- expect(parentCall[2]).toBe(30); // "actual" time
249
- expect(parentCall[3]).toBe(30); // "base" time
258
+ expect(childCall[2]).toBe(20); // actual time
259
+ expect(childCall[3]).toBe(20); // base time
260
+ expect(childCall[4]).toBe(15); // start time
261
+ expect(childCall[5]).toBe(35); // commit time
262
+ expect(parentCall[2]).toBe(30); // actual time
263
+ expect(parentCall[3]).toBe(30); // base time
264
+ expect(parentCall[4]).toBe(5); // start time
265
+ expect(parentCall[5]).toBe(35); // commit time
266
});
267
268
it('tracks sibling Profilers separately', () => {
269
const callback = jest.fn();
270
271
+ advanceTimeBy(5); // 0 -> 5
272
+
273
ReactTestRenderer.create(
274
<React.Fragment>
275
<React.unstable_Profiler id="first" onRender={callback}>
@@ -270,15 +288,21 @@ describe('Profiler', () => {
288
expect(secondCall[0]).toBe('second');
289
290
// Parent times should include child times
273
- expect(firstCall[2]).toBe(20); // "actual" time
274
- expect(firstCall[3]).toBe(20); // "base" time
275
- expect(secondCall[2]).toBe(5); // "actual" time
276
- expect(secondCall[3]).toBe(5); // "base" time
291
+ expect(firstCall[2]).toBe(20); // actual time
292
+ expect(firstCall[3]).toBe(20); // base time
293
+ expect(firstCall[4]).toBe(5); // start time
294
+ expect(firstCall[5]).toBe(30); // commit time
295
+ expect(secondCall[2]).toBe(5); // actual time
296
+ expect(secondCall[3]).toBe(5); // base time
297
+ expect(secondCall[4]).toBe(25); // start time
298
+ expect(secondCall[5]).toBe(30); // commit time
299
});
300
301
it('does not include time spent outside of profile root', () => {
302
const callback = jest.fn();
303
304
+ advanceTimeBy(5); // 0 -> 5
305
+
306
ReactTestRenderer.create(
307
<React.Fragment>
308
<AdvanceTime byAmount={20} />
@@ -293,8 +317,10 @@ describe('Profiler', () => {
317
318
const [call] = callback.mock.calls;
319
expect(call[0]).toBe('test');
296
- expect(call[2]).toBe(5); // "actual" time
297
- expect(call[3]).toBe(5); // "base" time
320
+ expect(call[2]).toBe(5); // actual time
321
+ expect(call[3]).toBe(5); // base time
322
+ expect(call[4]).toBe(25); // start time
323
+ expect(call[5]).toBe(50); // commit time
324
});
325
326
it('is not called when blocked by sCU false', () => {
@@ -347,23 +373,27 @@ describe('Profiler', () => {
373
expect(callback.mock.calls[1][0]).toBe('outer');
374
});
375
350
- it('decreases "actual" time but not "base" time when sCU prevents an update', () => {
376
+ it('decreases actual time but not base time when sCU prevents an update', () => {
377
const callback = jest.fn();
378
379
+ advanceTimeBy(5); // 0 -> 5
380
+
381
const renderer = ReactTestRenderer.create(
382
<React.unstable_Profiler id="test" onRender={callback}>
355
- <AdvanceTime>
356
- <AdvanceTime shouldComponentUpdate={false} />
383
+ <AdvanceTime byAmount={10}>
384
+ <AdvanceTime byAmount={10} shouldComponentUpdate={false} />
385
</AdvanceTime>
386
</React.unstable_Profiler>,
387
);
388
389
expect(callback).toHaveBeenCalledTimes(1);
390
391
+ advanceTimeBy(30); // 25 -> 55
392
+
393
renderer.update(
394
<React.unstable_Profiler id="test" onRender={callback}>
365
- <AdvanceTime>
366
- <AdvanceTime shouldComponentUpdate={false} />
395
+ <AdvanceTime byAmount={10}>
396
+ <AdvanceTime byAmount={10} shouldComponentUpdate={false} />
397
</AdvanceTime>
398
</React.unstable_Profiler>,
399
);
@@ -373,12 +403,16 @@ describe('Profiler', () => {
403
const [mountCall, updateCall] = callback.mock.calls;
404
405
expect(mountCall[1]).toBe('mount');
376
- expect(mountCall[2]).toBe(20); // "actual" time
377
- expect(mountCall[3]).toBe(20); // "base" time
406
+ expect(mountCall[2]).toBe(20); // actual time
407
+ expect(mountCall[3]).toBe(20); // base time
408
+ expect(mountCall[4]).toBe(5); // start time
409
+ expect(mountCall[5]).toBe(25); // commit time
410
411
expect(updateCall[1]).toBe('update');
380
- expect(updateCall[2]).toBe(10); // "actual" time
381
- expect(updateCall[3]).toBe(20); // "base" time
412
+ expect(updateCall[2]).toBe(10); // actual time
413
+ expect(updateCall[3]).toBe(20); // base time
414
+ expect(updateCall[4]).toBe(55); // start time
415
+ expect(updateCall[5]).toBe(65); // commit time
416
});
417
418
it('includes time spent in render phase lifecycles', () => {
@@ -400,12 +434,16 @@ describe('Profiler', () => {
434
435
const callback = jest.fn();
436
437
+ advanceTimeBy(5); // 0 -> 5
438
+
439
const renderer = ReactTestRenderer.create(
440
<React.unstable_Profiler id="test" onRender={callback}>
441
<WithLifecycles />
442
</React.unstable_Profiler>,
443
);
444
445
+ advanceTimeBy(15); // 13 -> 28
446
+
447
renderer.update(
448
<React.unstable_Profiler id="test" onRender={callback}>
449
<WithLifecycles />
@@ -417,16 +455,20 @@ describe('Profiler', () => {
455
const [mountCall, updateCall] = callback.mock.calls;
456
457
expect(mountCall[1]).toBe('mount');
420
- expect(mountCall[2]).toBe(8); // "actual" time
421
- expect(mountCall[3]).toBe(8); // "base" time
458
+ expect(mountCall[2]).toBe(8); // actual time
459
+ expect(mountCall[3]).toBe(8); // base time
460
+ expect(mountCall[4]).toBe(5); // start time
461
+ expect(mountCall[5]).toBe(13); // commit time
462
463
expect(updateCall[1]).toBe('update');
424
- expect(updateCall[2]).toBe(15); // "actual" time
425
- expect(updateCall[3]).toBe(15); // "base" time
464
+ expect(updateCall[2]).toBe(15); // actual time
465
+ expect(updateCall[3]).toBe(15); // base time
466
+ expect(updateCall[4]).toBe(28); // start time
467
+ expect(updateCall[5]).toBe(43); // commit time
468
});
469
470
describe('with regard to interruptions', () => {
429
- it('should accumulate "actual" time after a scheduling interruptions', () => {
471
+ it('should accumulate actual time after a scheduling interruptions', () => {
472
const callback = jest.fn();
473
474
const Yield = ({renderTime}) => {
@@ -435,6 +477,8 @@ describe('Profiler', () => {
477
return null;
478
};
479
480
+ advanceTimeBy(5); // 0 -> 5
481
+
482
// Render partially, but run out of time before completing.
483
const renderer = ReactTestRenderer.create(
484
<React.unstable_Profiler id="test" onRender={callback}>
@@ -453,8 +497,11 @@ describe('Profiler', () => {
497
498
// Verify that logged times include both durations above.
499
expect(callback).toHaveBeenCalledTimes(1);
456
- expect(callback.mock.calls[0][2]).toBe(5); // "actual" time
457
- expect(callback.mock.calls[0][3]).toBe(5); // "base" time
500
+ const [call] = callback.mock.calls;
501
+ expect(call[2]).toBe(5); // actual time
502
+ expect(call[3]).toBe(5); // base time
503
+ expect(call[4]).toBe(5); // start time
504
+ expect(call[5]).toBe(10); // commit time
505
});
506
507
it('should not include time between frames', () => {
@@ -466,6 +513,8 @@ describe('Profiler', () => {
513
return null;
514
};
515
516
+ advanceTimeBy(5); // 0 -> 5
517
+
518
// Render partially, but don't finish.
519
// This partial render should take 5ms of simulated time.
520
const renderer = ReactTestRenderer.create(
@@ -484,7 +533,7 @@ describe('Profiler', () => {
533
expect(callback).toHaveBeenCalledTimes(0);
534
535
// Simulate time moving forward while frame is paused.
487
- advanceTimeBy(50);
536
+ advanceTimeBy(50); // 10 -> 60
537
538
// Flush the remaninig work,
539
// Which should take an additional 10ms of simulated time.
@@ -493,14 +542,18 @@ describe('Profiler', () => {
542
543
const [innerCall, outerCall] = callback.mock.calls;
544
496
- // Verify that the "actual" time includes all work times,
545
+ // Verify that the actual time includes all work times,
546
// But not the time that elapsed between frames.
547
expect(innerCall[0]).toBe('inner');
499
- expect(innerCall[2]).toBe(17); // "actual" time
500
- expect(innerCall[3]).toBe(17); // "base" time
548
+ expect(innerCall[2]).toBe(17); // actual time
549
+ expect(innerCall[3]).toBe(17); // base time
550
+ expect(innerCall[4]).toBe(70); // start time
551
+ expect(innerCall[5]).toBe(87); // commit time
552
expect(outerCall[0]).toBe('outer');
502
- expect(outerCall[2]).toBe(32); // "actual" time
503
- expect(outerCall[3]).toBe(32); // "base" time
553
+ expect(outerCall[2]).toBe(32); // actual time
554
+ expect(outerCall[3]).toBe(32); // base time
555
+ expect(outerCall[4]).toBe(5); // start time
556
+ expect(outerCall[5]).toBe(87); // commit time
557
});
558
559
it('should report the expected times when a high-priority update replaces an in-progress initial render', () => {
@@ -512,6 +565,8 @@ describe('Profiler', () => {
565
return null;
566
};
567
568
+ advanceTimeBy(5); // 0 -> 5
569
+
570
// Render a partially update, but don't finish.
571
// This partial render should take 10ms of simulated time.
572
const renderer = ReactTestRenderer.create(
@@ -525,7 +580,7 @@ describe('Profiler', () => {
580
expect(callback).toHaveBeenCalledTimes(0);
581
582
// Simulate time moving forward while frame is paused.
528
- advanceTimeBy(100);
583
+ advanceTimeBy(100); // 15 -> 115
584
585
// Interrupt with higher priority work.
586
// The interrupted work simulates an additional 5ms of time.
@@ -540,11 +595,13 @@ describe('Profiler', () => {
595
).toEqual(['Yield:5']);
596
597
// The initial work was thrown away in this case,
543
- // So the "actual" and "base" times should only include the final rendered tree times.
598
+ // So the actual and base times should only include the final rendered tree times.
599
expect(callback).toHaveBeenCalledTimes(1);
600
let call = callback.mock.calls[0];
546
- expect(call[2]).toBe(5); // "actual" time
547
- expect(call[3]).toBe(5); // "base" time
601
+ expect(call[2]).toBe(5); // actual time
602
+ expect(call[3]).toBe(5); // base time
603
+ expect(call[4]).toBe(115); // start time
604
+ expect(call[5]).toBe(120); // commit time
605
606
callback.mockReset();
607
@@ -562,6 +619,8 @@ describe('Profiler', () => {
619
return null;
620
};
621
622
+ advanceTimeBy(5); // 0 -> 5
623
+
624
const renderer = ReactTestRenderer.create(
625
<React.unstable_Profiler id="test" onRender={callback}>
626
<Yield renderTime={6} />
@@ -571,15 +630,19 @@ describe('Profiler', () => {
630
);
631
632
// Render everything initially.
574
- // This should take 21 seconds of "actual" and "base" time.
633
+ // This should take 21 seconds of actual and base time.
634
expect(renderer.unstable_flushAll()).toEqual(['Yield:6', 'Yield:15']);
635
expect(callback).toHaveBeenCalledTimes(1);
636
let call = callback.mock.calls[0];
578
- expect(call[2]).toBe(21); // "actual" time
579
- expect(call[3]).toBe(21); // "base" time
637
+ expect(call[2]).toBe(21); // actual time
638
+ expect(call[3]).toBe(21); // base time
639
+ expect(call[4]).toBe(5); // start time
640
+ expect(call[5]).toBe(26); // commit time
641
642
callback.mockReset();
643
644
+ advanceTimeBy(30); // 26 -> 56
645
+
646
// Render a partially update, but don't finish.
647
// This partial render should take 3ms of simulated time.
648
renderer.update(
@@ -595,7 +658,7 @@ describe('Profiler', () => {
658
expect(callback).toHaveBeenCalledTimes(0);
659
660
// Simulate time moving forward while frame is paused.
598
- advanceTimeBy(100);
661
+ advanceTimeBy(100); // 59 -> 159
662
663
// Render another 5ms of simulated time.
664
expect(renderer.unstable_flushThrough(['Yield:5'])).toEqual([
@@ -604,7 +667,7 @@ describe('Profiler', () => {
667
expect(callback).toHaveBeenCalledTimes(0);
668
669
// Simulate time moving forward while frame is paused.
607
- advanceTimeBy(100);
670
+ advanceTimeBy(100); // 164 -> 264
671
672
// Interrupt with higher priority work.
673
// The interrupted work simulates an additional 11ms of time.
@@ -618,12 +681,14 @@ describe('Profiler', () => {
681
}),
682
).toEqual(['Yield:11']);
683
621
- // Verify that the "actual" time includes all three durations above.
622
- // And the "base" time includes only the final rendered tree times.
684
+ // Verify that the actual time includes all three durations above.
685
+ // And the base time includes only the final rendered tree times.
686
expect(callback).toHaveBeenCalledTimes(1);
687
call = callback.mock.calls[0];
625
- expect(call[2]).toBe(19); // "actual" time
626
- expect(call[3]).toBe(11); // "base" time
688
+ expect(call[2]).toBe(19); // actual time
689
+ expect(call[3]).toBe(11); // base time
690
+ expect(call[4]).toBe(264); // start time
691
+ expect(call[5]).toBe(275); // commit time
692
693
// Verify no more unexpected callbacks from low priority work
694
expect(renderer.unstable_flushAll()).toEqual([]);
@@ -660,6 +725,8 @@ describe('Profiler', () => {
725
}
726
}
727
728
+ advanceTimeBy(5); // 0 -> 5
729
+
730
const renderer = ReactTestRenderer.create(
731
<React.unstable_Profiler id="test" onRender={callback} foo="1">
732
<FirstComponent />
@@ -669,8 +736,8 @@ describe('Profiler', () => {
736
);
737
738
// Render everything initially.
672
- // This simulates a total of 14ms of "actual" render time.
673
- // The "base" render time is also 14ms for the initial render.
739
+ // This simulates a total of 14ms of actual render time.
740
+ // The base render time is also 14ms for the initial render.
741
expect(renderer.unstable_flushAll()).toEqual([
742
'FirstComponent:1',
743
'Yield:4',
@@ -679,13 +746,17 @@ describe('Profiler', () => {
746
]);
747
expect(callback).toHaveBeenCalledTimes(1);
748
let call = callback.mock.calls[0];
682
- expect(call[2]).toBe(14); // "actual" time
683
- expect(call[3]).toBe(14); // "base" time
749
+ expect(call[2]).toBe(14); // actual time
750
+ expect(call[3]).toBe(14); // base time
751
+ expect(call[4]).toBe(5); // start time
752
+ expect(call[5]).toBe(19); // commit time
753
754
callback.mockClear();
755
756
+ advanceTimeBy(100); // 19 -> 119
757
+
758
// Render a partially update, but don't finish.
688
- // This partial render will take 10ms of "actual" render time.
759
+ // This partial render will take 10ms of actual render time.
760
first.setState({renderTime: 10});
761
expect(renderer.unstable_flushThrough(['FirstComponent:10'])).toEqual([
762
'FirstComponent:10',
@@ -693,38 +764,45 @@ describe('Profiler', () => {
764
expect(callback).toHaveBeenCalledTimes(0);
765
766
// Simulate time moving forward while frame is paused.
696
- advanceTimeBy(100);
767
+ advanceTimeBy(100); // 129 -> 229
768
769
// Interrupt with higher priority work.
699
- // This simulates a total of 37ms of "actual" render time.
770
+ // This simulates a total of 37ms of actual render time.
771
expect(
772
renderer.unstable_flushSync(() => second.setState({renderTime: 30})),
773
).toEqual(['SecondComponent:30', 'Yield:7']);
774
704
- // Verify that the "actual" time includes time spent in the both renders so far (10ms and 37ms).
705
- // The "base" time should include the more recent times for the SecondComponent subtree,
775
+ // Verify that the actual time includes time spent in the both renders so far (10ms and 37ms).
776
+ // The base time should include the more recent times for the SecondComponent subtree,
777
// As well as the original times for the FirstComponent subtree.
778
expect(callback).toHaveBeenCalledTimes(1);
779
call = callback.mock.calls[0];
709
- expect(call[2]).toBe(47); // "actual" time
710
- expect(call[3]).toBe(42); // "base" time
780
+ expect(call[2]).toBe(47); // actual time
781
+ expect(call[3]).toBe(42); // base time
782
+ expect(call[4]).toBe(229); // start time
783
+ expect(call[5]).toBe(266); // commit time
784
785
callback.mockClear();
786
787
+ // Simulate time moving forward while frame is paused.
788
+ advanceTimeBy(100); // 266 -> 366
789
+
790
// Resume the original low priority update, with rebased state.
715
- // This simulates a total of 14ms of "actual" render time,
791
+ // This simulates a total of 14ms of actual render time,
792
// And does not include the original (interrupted) 10ms.
717
- // The tree contains 42ms of "base" render time at this point,
793
+ // The tree contains 42ms of base render time at this point,
794
// Reflecting the most recent (longer) render durations.
719
- // TODO: This "actual" time should decrease by 10ms once the scheduler supports resuming.
795
+ // TODO: This actual time should decrease by 10ms once the scheduler supports resuming.
796
expect(renderer.unstable_flushAll()).toEqual([
797
'FirstComponent:10',
798
'Yield:4',
799
]);
800
expect(callback).toHaveBeenCalledTimes(1);
801
call = callback.mock.calls[0];
726
- expect(call[2]).toBe(14); // "actual" time
727
- expect(call[3]).toBe(51); // "base" time
802
+ expect(call[2]).toBe(14); // actual time
803
+ expect(call[3]).toBe(51); // base time
804
+ expect(call[4]).toBe(366); // start time
805
+ expect(call[5]).toBe(380); // commit time
806
});
807
808
[true, false].forEach(flagEnabled => {
@@ -740,7 +818,7 @@ describe('Profiler', () => {
818
mockNowForTests();
819
});
820
743
- it('should accumulate "actual" time after an error handled by componentDidCatch()', () => {
821
+ it('should accumulate actual time after an error handled by componentDidCatch()', () => {
822
const callback = jest.fn();
823
824
const ThrowsError = () => {
@@ -763,6 +841,8 @@ describe('Profiler', () => {
841
}
842
}
843
844
+ advanceTimeBy(5); // 0 -> 5
845
+
846
ReactTestRenderer.create(
847
<React.unstable_Profiler id="test" onRender={callback}>
848
<ErrorBoundary>
@@ -780,21 +860,29 @@ describe('Profiler', () => {
860
// The initial mount only includes the ErrorBoundary (which takes 2ms)
861
// But it spends time rendering all of the failed subtree also.
862
expect(mountCall[1]).toBe('mount');
783
- // "actual" time includes: 2 (ErrorBoundary) + 5 (AdvanceTime) + 10 (ThrowsError)
863
+ // actual time includes: 2 (ErrorBoundary) + 5 (AdvanceTime) + 10 (ThrowsError)
864
// If replayFailedUnitOfWorkWithInvokeGuardedCallback is enbaled, ThrowsError is replayed.
865
expect(mountCall[2]).toBe(flagEnabled && __DEV__ ? 27 : 17);
786
- // "base" time includes: 2 (ErrorBoundary)
866
+ // base time includes: 2 (ErrorBoundary)
867
expect(mountCall[3]).toBe(2);
868
+ // start time
869
+ expect(mountCall[4]).toBe(5);
870
+ // commit time
871
+ expect(mountCall[5]).toBe(flagEnabled && __DEV__ ? 32 : 22);
872
873
// The update includes the ErrorBoundary and its fallback child
874
expect(updateCall[1]).toBe('update');
791
- // "actual" time includes: 2 (ErrorBoundary) + 20 (AdvanceTime)
875
+ // actual time includes: 2 (ErrorBoundary) + 20 (AdvanceTime)
876
expect(updateCall[2]).toBe(22);
793
- // "base" time includes: 2 (ErrorBoundary) + 20 (AdvanceTime)
877
+ // base time includes: 2 (ErrorBoundary) + 20 (AdvanceTime)
878
expect(updateCall[3]).toBe(22);
879
+ // start time
880
+ expect(updateCall[4]).toBe(flagEnabled && __DEV__ ? 32 : 22);
881
+ // commit time
882
+ expect(updateCall[5]).toBe(flagEnabled && __DEV__ ? 54 : 44);
883
});
884
797
- it('should accumulate "actual" time after an error handled by getDerivedStateFromCatch()', () => {
885
+ it('should accumulate actual time after an error handled by getDerivedStateFromCatch()', () => {
886
const callback = jest.fn();
887
888
const ThrowsError = () => {
@@ -817,6 +905,8 @@ describe('Profiler', () => {
905
}
906
}
907
908
+ advanceTimeBy(5); // 0 -> 5
909
+
910
ReactTestRenderer.create(
911
<React.unstable_Profiler id="test" onRender={callback}>
912
<ErrorBoundary>
@@ -832,14 +922,18 @@ describe('Profiler', () => {
922
let [mountCall] = callback.mock.calls;
923
924
// The initial mount includes the ErrorBoundary's error state,
835
- // But i also spends "actual" time rendering UI that fails and isn't included.
925
+ // But i also spends actual time rendering UI that fails and isn't included.
926
expect(mountCall[1]).toBe('mount');
837
- // "actual" time includes: 2 (ErrorBoundary) + 5 (AdvanceTime) + 10 (ThrowsError)
927
+ // actual time includes: 2 (ErrorBoundary) + 5 (AdvanceTime) + 10 (ThrowsError)
928
// Then the re-render: 2 (ErrorBoundary) + 20 (AdvanceTime)
929
// If replayFailedUnitOfWorkWithInvokeGuardedCallback is enbaled, ThrowsError is replayed.
930
expect(mountCall[2]).toBe(flagEnabled && __DEV__ ? 49 : 39);
841
- // "base" time includes: 2 (ErrorBoundary) + 20 (AdvanceTime)
931
+ // base time includes: 2 (ErrorBoundary) + 20 (AdvanceTime)
932
expect(mountCall[3]).toBe(22);
933
+ // start time
934
+ expect(mountCall[4]).toBe(5);
935
+ // commit time
936
+ expect(mountCall[5]).toBe(flagEnabled && __DEV__ ? 54 : 44);
937
});
938
});
939
});
@@ -848,6 +942,8 @@ describe('Profiler', () => {
942
it('reflects the most recently rendered id value', () => {
943
const callback = jest.fn();
944
945
+ advanceTimeBy(5); // 0 -> 5
946
+
947
const renderer = ReactTestRenderer.create(
948
<React.unstable_Profiler id="one" onRender={callback}>
949
<AdvanceTime byAmount={2} />
@@ -856,6 +952,8 @@ describe('Profiler', () => {
952
953
expect(callback).toHaveBeenCalledTimes(1);
954
955
+ advanceTimeBy(20); // 7 -> 27
956
+
957
renderer.update(
958
<React.unstable_Profiler id="two" onRender={callback}>
959
<AdvanceTime byAmount={1} />
@@ -868,13 +966,15 @@ describe('Profiler', () => {
966
967
expect(mountCall[0]).toBe('one');
968
expect(mountCall[1]).toBe('mount');
871
- expect(mountCall[2]).toBe(2); // "actual" time
872
- expect(mountCall[3]).toBe(2); // "base" time
969
+ expect(mountCall[2]).toBe(2); // actual time
970
+ expect(mountCall[3]).toBe(2); // base time
971
+ expect(mountCall[4]).toBe(5); // start time
972
973
expect(updateCall[0]).toBe('two');
974
expect(updateCall[1]).toBe('update');
876
- expect(updateCall[2]).toBe(1); // "actual" time
877
- expect(updateCall[3]).toBe(1); // "base" time
975
+ expect(updateCall[2]).toBe(1); // actual time
976
+ expect(updateCall[3]).toBe(1); // base time
977
+ expect(updateCall[4]).toBe(27); // start time
978
});
979
});
980
});