Update user timing to record the timeout deadline with 'waiting' events (#12479)
* Update user timing to record the timeout deadline with 'waiting' events **what is the change?:** When we are processing work during reconciliation, we have a "timeout" deadline to finish the work. It's a safety measure that forces things to finish up synchronously if they are taking too long. The "timeout" is different depending on the type of interaction which triggered the reconciliation. We currently have a shorter "timeout" for "interactive updates", meaning we will try to finish work faster if the reconciliation was triggered by a click or other user interaction. For collecting more data in our logs we want to differentiate the 'waiting for async callback...' events based on the "timeout" so I'm adding that to the logging. One interesting note - in one of the snapshot tests the "timeout" was super high. Going to look into that. **why make this change?:** Right now we are debugging cases where an interaction triggers a reconciliation and the "waiting for async callback...' events are too long, getting blocked because the main thread is too busy. We are keeping logs of these user timing events and want to filter to focus on the reconciliation triggered by interaction. **test plan:** Manually tested and also updated snapshot tests. (Flarnie will insert a screenshot) * Improve wording of message * ran prettier
Flarnie Marchan committed
Mar 29, 2018 at 11:26 UTC
125dd16ba0b3fa74767b1cf417a3116a4a2b251a
3 files changed
+34
-28
packages/react-reconciler/src/ReactDebugFiberPerf.js
+7
-2
@@ -248,13 +248,18 @@ export function startRequestCallbackTimer(): void {
248
}
249
}
250
251
-export function stopRequestCallbackTimer(didExpire: boolean): void {
251
+export function stopRequestCallbackTimer(
252
+ didExpire: boolean,
253
+ expirationTime: number,
254
+): void {
255
if (enableUserTimingAPI) {
256
if (supportsUserTiming) {
257
isWaitingForCallback = false;
258
const warning = didExpire ? 'React was blocked by main thread' : null;
259
endMark(
257
- '(Waiting for async callback...)',
260
+ `(Waiting for async callback... will force flush in ${
261
+ expirationTime
262
+ } ms)`,
263
'(Waiting for async callback...)',
264
warning,
265
);
packages/react-reconciler/src/ReactFiberScheduler.js
+2
-1
@@ -1448,7 +1448,8 @@ export default function<T, P, I, TI, HI, PI, C, CC, CX, PL>(
1448
1449
if (enableUserTimingAPI && deadline !== null) {
1450
const didExpire = nextFlushedExpirationTime < recalculateCurrentTime();
1451
- stopRequestCallbackTimer(didExpire);
1451
+ const timeout = expirationTimeToMs(nextFlushedExpirationTime);
1452
+ stopRequestCallbackTimer(didExpire, timeout);
1453
}
1454
1455
if (isAsync) {
packages/react-reconciler/src/__tests__/__snapshots__/ReactIncrementalPerf-test.internal.js.snap
+25
-25
@@ -1,7 +1,7 @@
1
// Jest Snapshot v1, https://goo.gl/fbAQLP
2
3
exports[`ReactDebugFiberPerf captures all lifecycles 1`] = `
4
-"⚛ (Waiting for async callback...)
4
+"⚛ (Waiting for async callback... will force flush in 5230 ms)
5
6
// Mount
7
⚛ (React Tree Reconciliation)
@@ -15,7 +15,7 @@ exports[`ReactDebugFiberPerf captures all lifecycles 1`] = `
15
⚛ (Calling Lifecycle Methods: 1 Total)
16
⚛ AllLifecycles.componentDidMount
17
18
-⚛ (Waiting for async callback...)
18
+⚛ (Waiting for async callback... will force flush in 5230 ms)
19
20
// Update
21
⚛ (React Tree Reconciliation)
@@ -31,7 +31,7 @@ exports[`ReactDebugFiberPerf captures all lifecycles 1`] = `
31
⚛ (Calling Lifecycle Methods: 2 Total)
32
⚛ AllLifecycles.componentDidUpdate
33
34
-⚛ (Waiting for async callback...)
34
+⚛ (Waiting for async callback... will force flush in 5230 ms)
35
36
// Unmount
37
⚛ (React Tree Reconciliation)
@@ -45,7 +45,7 @@ exports[`ReactDebugFiberPerf captures all lifecycles 1`] = `
45
`;
46
47
exports[`ReactDebugFiberPerf deduplicates lifecycle names during commit to reduce overhead 1`] = `
48
-"⚛ (Waiting for async callback...)
48
+"⚛ (Waiting for async callback... will force flush in 5230 ms)
49
50
// The commit phase should mention A and B just once
51
⚛ (React Tree Reconciliation)
@@ -62,7 +62,7 @@ exports[`ReactDebugFiberPerf deduplicates lifecycle names during commit to reduc
62
⚛ A.componentDidUpdate
63
⚛ B.componentDidUpdate
64
65
-⚛ (Waiting for async callback...)
65
+⚛ (Waiting for async callback... will force flush in 5230 ms)
66
67
// Because of deduplication, we don't know B was cascading,
68
// but we should still see the warning for the commit phase.
@@ -112,7 +112,7 @@ exports[`ReactDebugFiberPerf does not schedule an extra callback if setState is
112
`;
113
114
exports[`ReactDebugFiberPerf does not treat setState from cWM or cWRP as cascading 1`] = `
115
-"⚛ (Waiting for async callback...)
115
+"⚛ (Waiting for async callback... will force flush in 5230 ms)
116
117
// Should not print a warning
118
⚛ (React Tree Reconciliation)
@@ -125,7 +125,7 @@ exports[`ReactDebugFiberPerf does not treat setState from cWM or cWRP as cascadi
125
⚛ (Committing Host Effects: 1 Total)
126
⚛ (Calling Lifecycle Methods: 0 Total)
127
128
-⚛ (Waiting for async callback...)
128
+⚛ (Waiting for async callback... will force flush in 5230 ms)
129
130
// Should not print a warning
131
⚛ (React Tree Reconciliation)
@@ -141,7 +141,7 @@ exports[`ReactDebugFiberPerf does not treat setState from cWM or cWRP as cascadi
141
`;
142
143
exports[`ReactDebugFiberPerf measures a simple reconciliation 1`] = `
144
-"⚛ (Waiting for async callback...)
144
+"⚛ (Waiting for async callback... will force flush in 5230 ms)
145
146
// Mount
147
⚛ (React Tree Reconciliation)
@@ -153,7 +153,7 @@ exports[`ReactDebugFiberPerf measures a simple reconciliation 1`] = `
153
⚛ (Committing Host Effects: 1 Total)
154
⚛ (Calling Lifecycle Methods: 0 Total)
155
156
-⚛ (Waiting for async callback...)
156
+⚛ (Waiting for async callback... will force flush in 5230 ms)
157
158
// Update
159
⚛ (React Tree Reconciliation)
@@ -165,7 +165,7 @@ exports[`ReactDebugFiberPerf measures a simple reconciliation 1`] = `
165
⚛ (Committing Host Effects: 2 Total)
166
⚛ (Calling Lifecycle Methods: 2 Total)
167
168
-⚛ (Waiting for async callback...)
168
+⚛ (Waiting for async callback... will force flush in 5230 ms)
169
170
// Unmount
171
⚛ (React Tree Reconciliation)
@@ -178,7 +178,7 @@ exports[`ReactDebugFiberPerf measures a simple reconciliation 1`] = `
178
`;
179
180
exports[`ReactDebugFiberPerf measures deferred work in chunks 1`] = `
181
-"⚛ (Waiting for async callback...)
181
+"⚛ (Waiting for async callback... will force flush in 5230 ms)
182
183
// Start mounting Parent and A
184
⚛ (React Tree Reconciliation)
@@ -186,14 +186,14 @@ exports[`ReactDebugFiberPerf measures deferred work in chunks 1`] = `
186
⚛ A [mount]
187
⚛ Child [mount]
188
189
-⚛ (Waiting for async callback...)
189
+⚛ (Waiting for async callback... will force flush in 5230 ms)
190
191
// Mount B just a little (but not enough to memoize)
192
⚛ (React Tree Reconciliation)
193
⚛ Parent [mount]
194
⚛ B [mount]
195
196
-⚛ (Waiting for async callback...)
196
+⚛ (Waiting for async callback... will force flush in 5230 ms)
197
198
// Complete B and Parent
199
⚛ (React Tree Reconciliation)
@@ -218,7 +218,7 @@ exports[`ReactDebugFiberPerf measures deprioritized work 1`] = `
218
⚛ (Committing Host Effects: 1 Total)
219
⚛ (Calling Lifecycle Methods: 0 Total)
220
221
-⚛ (Waiting for async callback...)
221
+⚛ (Waiting for async callback... will force flush in 10737418210 ms)
222
223
// Flush the child
224
⚛ (React Tree Reconciliation)
@@ -232,7 +232,7 @@ exports[`ReactDebugFiberPerf measures deprioritized work 1`] = `
232
`;
233
234
exports[`ReactDebugFiberPerf recovers from caught errors 1`] = `
235
-"⚛ (Waiting for async callback...)
235
+"⚛ (Waiting for async callback... will force flush in 5230 ms)
236
237
// Stop on Baddie and restart from Boundary
238
⚛ (React Tree Reconciliation)
@@ -262,7 +262,7 @@ exports[`ReactDebugFiberPerf recovers from caught errors 1`] = `
262
`;
263
264
exports[`ReactDebugFiberPerf recovers from fatal errors 1`] = `
265
-"⚛ (Waiting for async callback...)
265
+"⚛ (Waiting for async callback... will force flush in 5230 ms)
266
267
// Will fatal
268
⚛ (React Tree Reconciliation)
@@ -276,7 +276,7 @@ exports[`ReactDebugFiberPerf recovers from fatal errors 1`] = `
276
⚛ (Committing Host Effects: 1 Total)
277
⚛ (Calling Lifecycle Methods: 0 Total)
278
279
-⚛ (Waiting for async callback...)
279
+⚛ (Waiting for async callback... will force flush in 5230 ms)
280
281
// Will reconcile from a clean state
282
⚛ (React Tree Reconciliation)
@@ -291,7 +291,7 @@ exports[`ReactDebugFiberPerf recovers from fatal errors 1`] = `
291
`;
292
293
exports[`ReactDebugFiberPerf skips parents during setState 1`] = `
294
-"⚛ (Waiting for async callback...)
294
+"⚛ (Waiting for async callback... will force flush in 5230 ms)
295
296
// Should include just A and B, no Parents
297
⚛ (React Tree Reconciliation)
@@ -306,7 +306,7 @@ exports[`ReactDebugFiberPerf skips parents during setState 1`] = `
306
`;
307
308
exports[`ReactDebugFiberPerf supports portals 1`] = `
309
-"⚛ (Waiting for async callback...)
309
+"⚛ (Waiting for async callback... will force flush in 5230 ms)
310
311
⚛ (React Tree Reconciliation)
312
⚛ Parent [mount]
@@ -320,7 +320,7 @@ exports[`ReactDebugFiberPerf supports portals 1`] = `
320
`;
321
322
exports[`ReactDebugFiberPerf supports returns 1`] = `
323
-"⚛ (Waiting for async callback...)
323
+"⚛ (Waiting for async callback... will force flush in 5230 ms)
324
325
⚛ (React Tree Reconciliation)
326
⚛ App [mount]
@@ -339,12 +339,12 @@ exports[`ReactDebugFiberPerf supports returns 1`] = `
339
`;
340
341
exports[`ReactDebugFiberPerf warns if an in-progress update is interrupted 1`] = `
342
-"⚛ (Waiting for async callback...)
342
+"⚛ (Waiting for async callback... will force flush in 5230 ms)
343
344
⚛ (React Tree Reconciliation)
345
⚛ Foo [mount]
346
347
-⚛ (Waiting for async callback...)
347
+⚛ (Waiting for async callback... will force flush in 5230 ms)
348
⛔ (React Tree Reconciliation) Warning: A top-level update interrupted the previous render
349
⚛ Foo [mount]
350
⚛ (Committing Changes)
@@ -362,7 +362,7 @@ exports[`ReactDebugFiberPerf warns if an in-progress update is interrupted 1`] =
362
`;
363
364
exports[`ReactDebugFiberPerf warns if async work expires (starvation) 1`] = `
365
-"⛔ (Waiting for async callback...) Warning: React was blocked by main thread
365
+"⛔ (Waiting for async callback... will force flush in 5230 ms) Warning: React was blocked by main thread
366
367
⚛ (React Tree Reconciliation)
368
⚛ Foo [mount]
@@ -375,7 +375,7 @@ exports[`ReactDebugFiberPerf warns if async work expires (starvation) 1`] = `
375
`;
376
377
exports[`ReactDebugFiberPerf warns on cascading renders from setState 1`] = `
378
-"⚛ (Waiting for async callback...)
378
+"⚛ (Waiting for async callback... will force flush in 5230 ms)
379
380
// Should print a warning
381
⚛ (React Tree Reconciliation)
@@ -399,7 +399,7 @@ exports[`ReactDebugFiberPerf warns on cascading renders from setState 1`] = `
399
`;
400
401
exports[`ReactDebugFiberPerf warns on cascading renders from top-level render 1`] = `
402
-"⚛ (Waiting for async callback...)
402
+"⚛ (Waiting for async callback... will force flush in 5230 ms)
403
404
// Rendering the first root
405
⚛ (React Tree Reconciliation)