Measure time between scheduling an async callback and flushing it (#11506)
* Measure time between scheduling an async callback and flushing it Helps detect starvation issues. * Debug comments should print directly above the next measure * Better warning message Most users won't know what "expires" means
Andrew Clark committed
Nov 10, 2017 at 12:14 UTC
c580082861e6f000a99898cc55ac68c79ce6f480
4 files changed
+129
-22
packages/react-reconciler/src/ReactDebugFiberPerf.js
+24
@@ -58,6 +58,7 @@ let hasScheduledUpdateInCurrentCommit: boolean = false;
58
let hasScheduledUpdateInCurrentPhase: boolean = false;
59
let commitCountInCurrentWorkLoop: number = 0;
60
let effectCountInCurrentCommit: number = 0;
61
+let isWaitingForCallback: boolean = false;
62
// During commits, we only show a measurement once per method name
63
// to avoid stretch the commit phase with measurement overhead.
64
const labelsInCurrentCommit: Set<string> = new Set();
@@ -231,6 +232,29 @@ export function recordScheduleUpdate(): void {
232
}
233
}
234
235
+export function startRequestCallbackTimer(): void {
236
+ if (enableUserTimingAPI) {
237
+ if (supportsUserTiming && !isWaitingForCallback) {
238
+ isWaitingForCallback = true;
239
+ beginMark('(Waiting for async callback...)');
240
+ }
241
+ }
242
+}
243
+
244
+export function stopRequestCallbackTimer(didExpire: boolean): void {
245
+ if (enableUserTimingAPI) {
246
+ if (supportsUserTiming) {
247
+ isWaitingForCallback = false;
248
+ const warning = didExpire ? 'React was blocked by main thread' : null;
249
+ endMark(
250
+ '(Waiting for async callback...)',
251
+ '(Waiting for async callback...)',
252
+ warning,
253
+ );
254
+ }
255
+ }
256
+}
257
+
258
export function startWorkTimer(fiber: Fiber): void {
259
if (enableUserTimingAPI) {
260
if (!supportsUserTiming || shouldIgnoreFiber(fiber)) {
packages/react-reconciler/src/ReactFiberScheduler.js
+12
-1
@@ -33,6 +33,7 @@ import {
33
HostPortal,
34
ClassComponent,
35
} from 'shared/ReactTypeOfWork';
36
+import {enableUserTimingAPI} from 'shared/ReactFeatureFlags';
37
import getComponentName from 'shared/getComponentName';
38
import invariant from 'fbjs/lib/invariant';
39
import warning from 'fbjs/lib/warning';
@@ -47,6 +48,8 @@ import ReactDebugCurrentFiber from './ReactDebugCurrentFiber';
48
import {
49
recordEffect,
50
recordScheduleUpdate,
51
+ startRequestCallbackTimer,
52
+ stopRequestCallbackTimer,
53
startWorkTimer,
54
stopWorkTimer,
55
stopFailedWorkTimer,
@@ -1337,6 +1340,7 @@ export default function<T, P, I, TI, PI, C, CC, CX, PL>(
1340
performWork(Sync, null);
1341
} else if (!isCallbackScheduled) {
1342
isCallbackScheduled = true;
1343
+ startRequestCallbackTimer();
1344
scheduleDeferredCallback(performAsyncWork);
1345
}
1346
}
@@ -1425,8 +1429,14 @@ export default function<T, P, I, TI, PI, C, CC, CX, PL>(
1429
deadline = dl;
1430
1431
// Keep working on roots until there's no more work, or until the we reach
1428
- // the deadlne.
1432
+ // the deadline.
1433
findHighestPriorityRoot();
1434
+
1435
+ if (enableUserTimingAPI && deadline !== null) {
1436
+ const didExpire = nextFlushedExpirationTime < recalculateCurrentTime();
1437
+ stopRequestCallbackTimer(didExpire);
1438
+ }
1439
+
1440
while (
1441
nextFlushedRoot !== null &&
1442
nextFlushedExpirationTime !== NoWork &&
@@ -1449,6 +1459,7 @@ export default function<T, P, I, TI, PI, C, CC, CX, PL>(
1459
// If there's work left over, schedule a new callback.
1460
if (nextFlushedRoot !== null && !isCallbackScheduled) {
1461
isCallbackScheduled = true;
1462
+ startRequestCallbackTimer();
1463
scheduleDeferredCallback(performAsyncWork);
1464
}
1465
packages/react-reconciler/src/__tests__/ReactIncrementalPerf-test.js
+17
-3
@@ -20,6 +20,7 @@ describe('ReactDebugFiberPerf', () => {
20
let activeMeasure;
21
let knownMarks;
22
let knownMeasures;
23
+ let comments;
24
25
function resetFlamechart() {
26
root = {
@@ -35,12 +36,11 @@ describe('ReactDebugFiberPerf', () => {
36
activeMeasure = root;
37
knownMarks = new Set();
38
knownMeasures = new Set();
39
+ comments = [];
40
}
41
42
function addComment(comment) {
41
- activeMeasure.children.push(
42
- `${' '.repeat(activeMeasure.indent + 1)}// ${comment}`,
43
- );
43
+ comments.push(comment);
44
}
45
46
function getFlameChart() {
@@ -67,9 +67,11 @@ describe('ReactDebugFiberPerf', () => {
67
// Will be assigned on measure() call:
68
label: null,
69
parent: activeMeasure,
70
+ comments,
71
toString() {
72
return (
73
[
74
+ ...this.comments.map(c => ' '.repeat(this.indent) + '// ' + c),
75
' '.repeat(this.indent) + this.label,
76
...this.children.map(c => c.toString()),
77
].join('\n') +
@@ -78,6 +80,7 @@ describe('ReactDebugFiberPerf', () => {
80
);
81
},
82
};
83
+ comments = [];
84
// Step one level deeper
85
activeMeasure.children.push(measure);
86
activeMeasure = measure;
@@ -546,4 +549,15 @@ describe('ReactDebugFiberPerf', () => {
549
ReactNoop.flush();
550
expect(getFlameChart()).toMatchSnapshot();
551
});
552
+
553
+ it('warns if async work expires (starvation)', () => {
554
+ function Foo() {
555
+ return <span />;
556
+ }
557
+
558
+ ReactNoop.render(<Foo />);
559
+ ReactNoop.expire(5000);
560
+ ReactNoop.flush();
561
+ expect(getFlameChart()).toMatchSnapshot();
562
+ });
563
});
packages/react-reconciler/src/__tests__/__snapshots__/ReactIncrementalPerf-test.js.snap
+76
-18
@@ -1,7 +1,9 @@
1
// Jest Snapshot v1, https://goo.gl/fbAQLP
2
3
exports[`ReactDebugFiberPerf captures all lifecycles 1`] = `
4
-"// Mount
4
+"⚛ (Waiting for async callback...)
5
+
6
+// Mount
7
⚛ (React Tree Reconciliation)
8
⚛ AllLifecycles [mount]
9
⚛ AllLifecycles.componentWillMount
@@ -12,6 +14,8 @@ exports[`ReactDebugFiberPerf captures all lifecycles 1`] = `
14
⚛ (Calling Lifecycle Methods: 1 Total)
15
⚛ AllLifecycles.componentDidMount
16
17
+⚛ (Waiting for async callback...)
18
+
19
// Update
20
⚛ (React Tree Reconciliation)
21
⚛ AllLifecycles [update]
@@ -25,6 +29,8 @@ exports[`ReactDebugFiberPerf captures all lifecycles 1`] = `
29
⚛ (Calling Lifecycle Methods: 2 Total)
30
⚛ AllLifecycles.componentDidUpdate
31
32
+⚛ (Waiting for async callback...)
33
+
34
// Unmount
35
⚛ (React Tree Reconciliation)
36
@@ -36,7 +42,9 @@ exports[`ReactDebugFiberPerf captures all lifecycles 1`] = `
42
`;
43
44
exports[`ReactDebugFiberPerf deduplicates lifecycle names during commit to reduce overhead 1`] = `
39
-"// The commit phase should mention A and B just once
45
+"⚛ (Waiting for async callback...)
46
+
47
+// The commit phase should mention A and B just once
48
⚛ (React Tree Reconciliation)
49
⚛ Parent [update]
50
⚛ A [update]
@@ -50,6 +58,8 @@ exports[`ReactDebugFiberPerf deduplicates lifecycle names during commit to reduc
58
⚛ A.componentDidUpdate
59
⚛ B.componentDidUpdate
60
61
+⚛ (Waiting for async callback...)
62
+
63
// Because of deduplication, we don't know B was cascading,
64
// but we should still see the warning for the commit phase.
65
⚛ (React Tree Reconciliation)
@@ -94,7 +104,9 @@ exports[`ReactDebugFiberPerf does not schedule an extra callback if setState is
104
`;
105
106
exports[`ReactDebugFiberPerf does not treat setState from cWM or cWRP as cascading 1`] = `
97
-"// Should not print a warning
107
+"⚛ (Waiting for async callback...)
108
+
109
+// Should not print a warning
110
⚛ (React Tree Reconciliation)
111
⚛ Parent [mount]
112
⚛ NotCascading [mount]
@@ -104,6 +116,8 @@ exports[`ReactDebugFiberPerf does not treat setState from cWM or cWRP as cascadi
116
⚛ (Committing Host Effects: 1 Total)
117
⚛ (Calling Lifecycle Methods: 0 Total)
118
119
+⚛ (Waiting for async callback...)
120
+
121
// Should not print a warning
122
⚛ (React Tree Reconciliation)
123
⚛ Parent [update]
@@ -117,7 +131,9 @@ exports[`ReactDebugFiberPerf does not treat setState from cWM or cWRP as cascadi
131
`;
132
133
exports[`ReactDebugFiberPerf measures a simple reconciliation 1`] = `
120
-"// Mount
134
+"⚛ (Waiting for async callback...)
135
+
136
+// Mount
137
⚛ (React Tree Reconciliation)
138
⚛ Parent [mount]
139
⚛ Child [mount]
@@ -126,6 +142,8 @@ exports[`ReactDebugFiberPerf measures a simple reconciliation 1`] = `
142
⚛ (Committing Host Effects: 1 Total)
143
⚛ (Calling Lifecycle Methods: 0 Total)
144
145
+⚛ (Waiting for async callback...)
146
+
147
// Update
148
⚛ (React Tree Reconciliation)
149
⚛ Parent [update]
@@ -135,6 +153,8 @@ exports[`ReactDebugFiberPerf measures a simple reconciliation 1`] = `
153
⚛ (Committing Host Effects: 2 Total)
154
⚛ (Calling Lifecycle Methods: 2 Total)
155
156
+⚛ (Waiting for async callback...)
157
+
158
// Unmount
159
⚛ (React Tree Reconciliation)
160
@@ -145,17 +165,23 @@ exports[`ReactDebugFiberPerf measures a simple reconciliation 1`] = `
165
`;
166
167
exports[`ReactDebugFiberPerf measures deferred work in chunks 1`] = `
148
-"// Start mounting Parent and A
168
+"⚛ (Waiting for async callback...)
169
+
170
+// Start mounting Parent and A
171
⚛ (React Tree Reconciliation)
172
⚛ Parent [mount]
173
⚛ A [mount]
174
⚛ Child [mount]
175
176
+⚛ (Waiting for async callback...)
177
+
178
// Mount B just a little (but not enough to memoize)
179
⚛ (React Tree Reconciliation)
180
⚛ Parent [mount]
181
⚛ B [mount]
182
183
+⚛ (Waiting for async callback...)
184
+
185
// Complete B and Parent
186
⚛ (React Tree Reconciliation)
187
⚛ Parent [mount]
@@ -177,6 +203,8 @@ exports[`ReactDebugFiberPerf measures deprioritized work 1`] = `
203
⚛ (Committing Host Effects: 1 Total)
204
⚛ (Calling Lifecycle Methods: 0 Total)
205
206
+⚛ (Waiting for async callback...)
207
+
208
// Flush the child
209
⚛ (React Tree Reconciliation)
210
⚛ Child [mount]
@@ -188,7 +216,9 @@ exports[`ReactDebugFiberPerf measures deprioritized work 1`] = `
216
`;
217
218
exports[`ReactDebugFiberPerf recovers from caught errors 1`] = `
191
-"// Stop on Baddie and restart from Boundary
219
+"⚛ (Waiting for async callback...)
220
+
221
+// Stop on Baddie and restart from Boundary
222
⚛ (React Tree Reconciliation)
223
⚛ Parent [mount]
224
⛔ Boundary [mount] Warning: An error was thrown inside this error boundary
@@ -211,7 +241,9 @@ exports[`ReactDebugFiberPerf recovers from caught errors 1`] = `
241
`;
242
243
exports[`ReactDebugFiberPerf recovers from fatal errors 1`] = `
214
-"// Will fatal
244
+"⚛ (Waiting for async callback...)
245
+
246
+// Will fatal
247
⚛ (React Tree Reconciliation)
248
⚛ Parent [mount]
249
⚛ Baddie [mount]
@@ -220,6 +252,8 @@ exports[`ReactDebugFiberPerf recovers from fatal errors 1`] = `
252
⚛ (Committing Host Effects: 1 Total)
253
⚛ (Calling Lifecycle Methods: 1 Total)
254
255
+⚛ (Waiting for async callback...)
256
+
257
// Will reconcile from a clean state
258
⚛ (React Tree Reconciliation)
259
⚛ Parent [mount]
@@ -232,7 +266,9 @@ exports[`ReactDebugFiberPerf recovers from fatal errors 1`] = `
266
`;
267
268
exports[`ReactDebugFiberPerf skips parents during setState 1`] = `
235
-"// Should include just A and B, no Parents
269
+"⚛ (Waiting for async callback...)
270
+
271
+// Should include just A and B, no Parents
272
⚛ (React Tree Reconciliation)
273
⚛ A [update]
274
⚛ B [update]
@@ -244,7 +280,9 @@ exports[`ReactDebugFiberPerf skips parents during setState 1`] = `
280
`;
281
282
exports[`ReactDebugFiberPerf supports portals 1`] = `
247
-"⚛ (React Tree Reconciliation)
283
+"⚛ (Waiting for async callback...)
284
+
285
+⚛ (React Tree Reconciliation)
286
⚛ Parent [mount]
287
⚛ Child [mount]
288
@@ -255,7 +293,9 @@ exports[`ReactDebugFiberPerf supports portals 1`] = `
293
`;
294
295
exports[`ReactDebugFiberPerf supports returns 1`] = `
258
-"⚛ (React Tree Reconciliation)
296
+"⚛ (Waiting for async callback...)
297
+
298
+⚛ (React Tree Reconciliation)
299
⚛ App [mount]
300
⚛ CoParent [mount]
301
⚛ HandleReturns [mount]
@@ -272,26 +312,42 @@ exports[`ReactDebugFiberPerf supports returns 1`] = `
312
`;
313
314
exports[`ReactDebugFiberPerf warns if an in-progress update is interrupted 1`] = `
275
-"⚛ (React Tree Reconciliation)
276
- ⚛ Foo [mount]
315
+"⚛ (Waiting for async callback...)
316
278
-⛔ (React Tree Reconciliation) Warning: A top-level update interrupted the previous render
317
+⚛ (React Tree Reconciliation)
318
⚛ Foo [mount]
319
320
+⚛ (Waiting for async callback...)
321
+ ⛔ (React Tree Reconciliation) Warning: A top-level update interrupted the previous render
322
+ ⚛ Foo [mount]
323
+ ⚛ (Committing Changes)
324
+ ⚛ (Committing Host Effects: 1 Total)
325
+ ⚛ (Calling Lifecycle Methods: 0 Total)
326
+
327
+⚛ (React Tree Reconciliation)
328
+
329
⚛ (Committing Changes)
330
⚛ (Committing Host Effects: 1 Total)
283
- ⚛ (Calling Lifecycle Methods: 0 Total)
331
+ ⚛ (Calling Lifecycle Methods: 1 Total)
332
+"
333
+`;
334
+
335
+exports[`ReactDebugFiberPerf warns if async work expires (starvation) 1`] = `
336
+"⛔ (Waiting for async callback...) Warning: React was blocked by main thread
337
338
⚛ (React Tree Reconciliation)
339
+ ⚛ Foo [mount]
340
341
⚛ (Committing Changes)
342
⚛ (Committing Host Effects: 1 Total)
289
- ⚛ (Calling Lifecycle Methods: 1 Total)
343
+ ⚛ (Calling Lifecycle Methods: 0 Total)
344
"
345
`;
346
347
exports[`ReactDebugFiberPerf warns on cascading renders from setState 1`] = `
294
-"// Should print a warning
348
+"⚛ (Waiting for async callback...)
349
+
350
+// Should print a warning
351
⚛ (React Tree Reconciliation)
352
⚛ Parent [mount]
353
⚛ Cascading [mount]
@@ -311,7 +367,9 @@ exports[`ReactDebugFiberPerf warns on cascading renders from setState 1`] = `
367
`;
368
369
exports[`ReactDebugFiberPerf warns on cascading renders from top-level render 1`] = `
314
-"// Rendering the first root
370
+"⚛ (Waiting for async callback...)
371
+
372
+// Rendering the first root
373
⚛ (React Tree Reconciliation)
374
⚛ Cascading [mount]
375
@@ -319,8 +377,8 @@ exports[`ReactDebugFiberPerf warns on cascading renders from top-level render 1`
377
⚛ (Committing Host Effects: 1 Total)
378
⚛ (Calling Lifecycle Methods: 1 Total)
379
⛔ Cascading.componentDidMount Warning: Scheduled a cascading update
322
- // Scheduling another root from componentDidMount
380
381
+// Scheduling another root from componentDidMount
382
⚛ (React Tree Reconciliation)
383
⚛ Child [mount]
384