From 009dd0e9f9d010b202ba730139743283d91b9269 Mon Sep 17 00:00:00 2001 From: Brian Vaughn Date: Fri, 6 Aug 2021 14:57:52 -0400 Subject: [PATCH] Scheduling Profiler: Improve warnings and add unit tests (#22038) * Scheduling Profiler: Updated instructions to mentioned v18+ requirement * Moved long-event warning to post processing This lets us rule out non-React work or React work that started before the event and finished quickly during the event. Also added unit tests for this warning and the various cases. * Moved long-event warning to post processing This lets us rule out non-React work or React work that started before the event and finished quickly during the event. Also added unit tests for this warning and the various cases. * Updated nested update warning text * Udpate warning about suspending outside of a transition Handle edge case where component suspends before the first commit (and label metadata) has been logged. Add unit tests. * Fixed logic error in getBatchRange() with minStartTime * PR feedback: Combined a conditional statement --- .../src/SchedulingProfiler.css | 1 + .../src/SchedulingProfiler.js | 2 +- .../__tests__/preprocessData-test.internal.js | 1271 +++++++++++------ .../src/import-worker/preprocessData.js | 132 +- .../src/utils/getBatchRange.js | 14 +- 5 files changed, 977 insertions(+), 443 deletions(-) diff --git a/packages/react-devtools-scheduling-profiler/src/SchedulingProfiler.css b/packages/react-devtools-scheduling-profiler/src/SchedulingProfiler.css index 5be33714a8f9f..9a0d35c818331 100644 --- a/packages/react-devtools-scheduling-profiler/src/SchedulingProfiler.css +++ b/packages/react-devtools-scheduling-profiler/src/SchedulingProfiler.css @@ -54,6 +54,7 @@ .WelcomeInstructionsListItemLink { color: var(--color-link); margin-left: 0.25rem; + margin-right: 0.25rem; } .ImportButtonLabel { diff --git a/packages/react-devtools-scheduling-profiler/src/SchedulingProfiler.js b/packages/react-devtools-scheduling-profiler/src/SchedulingProfiler.js index 760bbeead7d4f..9b3220c5ae1b7 100644 --- a/packages/react-devtools-scheduling-profiler/src/SchedulingProfiler.js +++ b/packages/react-devtools-scheduling-profiler/src/SchedulingProfiler.js @@ -86,7 +86,7 @@ const Welcome = ({onFileSelect}: {|onFileSelect: (file: File) => void|}) => ( target="_blank"> profiling build of ReactDOM - . + (version 18 or newer).
  • Open the "Performance" tab in Chrome and record some performance data. diff --git a/packages/react-devtools-scheduling-profiler/src/import-worker/__tests__/preprocessData-test.internal.js b/packages/react-devtools-scheduling-profiler/src/import-worker/__tests__/preprocessData-test.internal.js index f08dcd2512b1e..4c59a68efe3be 100644 --- a/packages/react-devtools-scheduling-profiler/src/import-worker/__tests__/preprocessData-test.internal.js +++ b/packages/react-devtools-scheduling-profiler/src/import-worker/__tests__/preprocessData-test.internal.js @@ -60,6 +60,7 @@ describe(getLanesFromTransportDecimalBitmask, () => { describe(preprocessData, () => { let React; let ReactDOM; + let Scheduler; let act; let clearedMarks; @@ -135,6 +136,26 @@ describe(preprocessData, () => { }); } + function createNativeEventEntry(type, duration) { + return createUserTimingEntry({ + cat: 'devtools.timeline', + name: 'EventDispatch', + args: {data: {type}}, + dur: duration, + tdur: duration, + }); + } + + function creactCpuProfilerSample() { + return createUserTimingEntry({ + args: {data: {startTime: ++startTime}}, + cat: 'disabled-by-default-v8.cpu_profiler', + id: '0x1', + name: 'Profile', + ph: 'P', + }); + } + function createBoilerplateEntries() { return [ createProfilerVersionEntry(), @@ -144,13 +165,7 @@ describe(preprocessData, () => { } function createUserTimingData(sampleMarks) { - const cpuProfilerSample = createUserTimingEntry({ - args: {data: {startTime: ++startTime}}, - cat: 'disabled-by-default-v8.cpu_profiler', - id: '0x1', - name: 'Profile', - ph: 'P', - }); + const cpuProfilerSample = creactCpuProfilerSample(); const randomSample = createUserTimingEntry({ dur: 100, @@ -168,7 +183,7 @@ describe(preprocessData, () => { pid: ++pid, tid: ++tid, ts: ++startTime, - args: {data: {navigationId: 'fake-navigation-id'}}, + args: {data: {}}, cat: 'blink.user_timing', name: markName, ph: 'R', @@ -185,6 +200,7 @@ describe(preprocessData, () => { React = require('react'); ReactDOM = require('react-dom'); + Scheduler = require('scheduler'); const TestUtils = require('react-dom/test-utils'); act = TestUtils.act; @@ -219,13 +235,7 @@ describe(preprocessData, () => { }); it('should return empty data given a timeline with no React scheduling profiling marks', () => { - const cpuProfilerSample = createUserTimingEntry({ - args: {data: {startTime: ++startTime}}, - cat: 'disabled-by-default-v8.cpu_profiler', - id: '0x1', - name: 'Profile', - ph: 'P', - }); + const cpuProfilerSample = creactCpuProfilerSample(); const randomSample = createUserTimingEntry({ dur: 100, tdur: 200, @@ -292,13 +302,7 @@ describe(preprocessData, () => { }); it('should process legacy data format (before lane labels were added)', () => { - const cpuProfilerSample = createUserTimingEntry({ - args: {data: {startTime: ++startTime}}, - cat: 'disabled-by-default-v8.cpu_profiler', - id: '0x1', - name: 'Profile', - ph: 'P', - }); + const cpuProfilerSample = creactCpuProfilerSample(); if (gate(flags => flags.enableSchedulingProfiler)) { // Data below is hard-coded based on an older profile sample. @@ -336,102 +340,102 @@ describe(preprocessData, () => { }), ]); expect(data).toMatchInlineSnapshot(` - Object { - "componentMeasures": Array [], - "duration": 0.011, - "flamechart": Array [], - "laneToLabelMap": Map { - 0 => "Sync", - 1 => "InputContinuousHydration", - 2 => "InputContinuous", - 3 => "DefaultHydration", - 4 => "Default", - 5 => "TransitionHydration", - 6 => "Transition", - 7 => "Transition", - 8 => "Transition", - 9 => "Transition", - 10 => "Transition", - 11 => "Transition", - 12 => "Transition", - 13 => "Transition", - 14 => "Transition", - 15 => "Transition", - 16 => "Transition", - 17 => "Transition", - 18 => "Transition", - 19 => "Transition", - 20 => "Transition", - 21 => "Transition", - 22 => "Retry", - 23 => "Retry", - 24 => "Retry", - 25 => "Retry", - 26 => "Retry", - 27 => "SelectiveHydration", - 28 => "IdleHydration", - 29 => "Idle", - 30 => "Offscreen", - }, - "measures": Array [ - Object { - "batchUID": 0, - "depth": 0, - "duration": 0.004999999999999999, - "lanes": Array [ - 9, - ], - "timestamp": 0.006, - "type": "render-idle", - }, - Object { - "batchUID": 0, - "depth": 0, - "duration": 0.001, - "lanes": Array [ - 9, - ], - "timestamp": 0.006, - "type": "render", - }, - Object { - "batchUID": 0, - "depth": 0, - "duration": 0.002999999999999999, - "lanes": Array [ - 9, - ], - "timestamp": 0.008, - "type": "commit", - }, - Object { - "batchUID": 0, - "depth": 1, - "duration": 0.0010000000000000009, - "lanes": Array [ - 9, - ], - "timestamp": 0.009, - "type": "layout-effects", - }, - ], - "nativeEvents": Array [], - "otherUserTimingMarks": Array [], - "reactVersion": "17.0.3", - "schedulingEvents": Array [ - Object { - "lanes": Array [ - 9, - ], - "timestamp": 0.005, - "type": "schedule-render", - "warning": null, - }, - ], - "startTime": 1, - "suspenseEvents": Array [], - } - `); + Object { + "componentMeasures": Array [], + "duration": 0.011, + "flamechart": Array [], + "laneToLabelMap": Map { + 0 => "Sync", + 1 => "InputContinuousHydration", + 2 => "InputContinuous", + 3 => "DefaultHydration", + 4 => "Default", + 5 => "TransitionHydration", + 6 => "Transition", + 7 => "Transition", + 8 => "Transition", + 9 => "Transition", + 10 => "Transition", + 11 => "Transition", + 12 => "Transition", + 13 => "Transition", + 14 => "Transition", + 15 => "Transition", + 16 => "Transition", + 17 => "Transition", + 18 => "Transition", + 19 => "Transition", + 20 => "Transition", + 21 => "Transition", + 22 => "Retry", + 23 => "Retry", + 24 => "Retry", + 25 => "Retry", + 26 => "Retry", + 27 => "SelectiveHydration", + 28 => "IdleHydration", + 29 => "Idle", + 30 => "Offscreen", + }, + "measures": Array [ + Object { + "batchUID": 0, + "depth": 0, + "duration": 0.004999999999999999, + "lanes": Array [ + 9, + ], + "timestamp": 0.006, + "type": "render-idle", + }, + Object { + "batchUID": 0, + "depth": 0, + "duration": 0.001, + "lanes": Array [ + 9, + ], + "timestamp": 0.006, + "type": "render", + }, + Object { + "batchUID": 0, + "depth": 0, + "duration": 0.002999999999999999, + "lanes": Array [ + 9, + ], + "timestamp": 0.008, + "type": "commit", + }, + Object { + "batchUID": 0, + "depth": 1, + "duration": 0.0010000000000000009, + "lanes": Array [ + 9, + ], + "timestamp": 0.009, + "type": "layout-effects", + }, + ], + "nativeEvents": Array [], + "otherUserTimingMarks": Array [], + "reactVersion": "17.0.3", + "schedulingEvents": Array [ + Object { + "lanes": Array [ + 9, + ], + "timestamp": 0.005, + "type": "schedule-render", + "warning": null, + }, + ], + "startTime": 1, + "suspenseEvents": Array [], + } + `); } }); @@ -444,107 +448,107 @@ describe(preprocessData, () => { ...createUserTimingData(clearedMarks), ]); expect(data).toMatchInlineSnapshot(` - Object { - "componentMeasures": Array [], - "duration": 0.013, - "flamechart": Array [], - "laneToLabelMap": Map { - 0 => "Sync", - 1 => "InputContinuousHydration", - 2 => "InputContinuous", - 3 => "DefaultHydration", - 4 => "Default", - 5 => "TransitionHydration", - 6 => "Transition", - 7 => "Transition", - 8 => "Transition", - 9 => "Transition", - 10 => "Transition", - 11 => "Transition", - 12 => "Transition", - 13 => "Transition", - 14 => "Transition", - 15 => "Transition", - 16 => "Transition", - 17 => "Transition", - 18 => "Transition", - 19 => "Transition", - 20 => "Transition", - 21 => "Transition", - 22 => "Retry", - 23 => "Retry", - 24 => "Retry", - 25 => "Retry", - 26 => "Retry", - 27 => "SelectiveHydration", - 28 => "IdleHydration", - 29 => "Idle", - 30 => "Offscreen", - }, - "measures": Array [ - Object { - "batchUID": 0, - "depth": 0, - "duration": 0.008, - "lanes": Array [ - 0, - ], - "timestamp": 0.005, - "type": "render-idle", - }, - Object { - "batchUID": 0, - "depth": 0, - "duration": 0.001, - "lanes": Array [ - 0, - ], - "timestamp": 0.005, - "type": "render", - }, - Object { - "batchUID": 0, - "depth": 0, - "duration": 0.005999999999999999, - "lanes": Array [ - 0, - ], - "timestamp": 0.007, - "type": "commit", - }, - Object { - "batchUID": 0, - "depth": 1, - "duration": 0.0010000000000000009, - "lanes": Array [ - 0, - ], - "timestamp": 0.011, - "type": "layout-effects", - }, - ], - "nativeEvents": Array [], - "otherUserTimingMarks": Array [ - Object { - "name": "__v3", - "timestamp": 0.003, - }, - ], - "reactVersion": "17.0.3", - "schedulingEvents": Array [ - Object { - "lanes": Array [ - 0, - ], - "timestamp": 0.004, - "type": "schedule-render", - "warning": null, - }, - ], - "startTime": 4, - "suspenseEvents": Array [], - } - `); + Object { + "componentMeasures": Array [], + "duration": 0.013, + "flamechart": Array [], + "laneToLabelMap": Map { + 0 => "Sync", + 1 => "InputContinuousHydration", + 2 => "InputContinuous", + 3 => "DefaultHydration", + 4 => "Default", + 5 => "TransitionHydration", + 6 => "Transition", + 7 => "Transition", + 8 => "Transition", + 9 => "Transition", + 10 => "Transition", + 11 => "Transition", + 12 => "Transition", + 13 => "Transition", + 14 => "Transition", + 15 => "Transition", + 16 => "Transition", + 17 => "Transition", + 18 => "Transition", + 19 => "Transition", + 20 => "Transition", + 21 => "Transition", + 22 => "Retry", + 23 => "Retry", + 24 => "Retry", + 25 => "Retry", + 26 => "Retry", + 27 => "SelectiveHydration", + 28 => "IdleHydration", + 29 => "Idle", + 30 => "Offscreen", + }, + "measures": Array [ + Object { + "batchUID": 0, + "depth": 0, + "duration": 0.008, + "lanes": Array [ + 0, + ], + "timestamp": 0.005, + "type": "render-idle", + }, + Object { + "batchUID": 0, + "depth": 0, + "duration": 0.001, + "lanes": Array [ + 0, + ], + "timestamp": 0.005, + "type": "render", + }, + Object { + "batchUID": 0, + "depth": 0, + "duration": 0.005999999999999999, + "lanes": Array [ + 0, + ], + "timestamp": 0.007, + "type": "commit", + }, + Object { + "batchUID": 0, + "depth": 1, + "duration": 0.0010000000000000009, + "lanes": Array [ + 0, + ], + "timestamp": 0.011, + "type": "layout-effects", + }, + ], + "nativeEvents": Array [], + "otherUserTimingMarks": Array [ + Object { + "name": "__v3", + "timestamp": 0.003, + }, + ], + "reactVersion": "17.0.3", + "schedulingEvents": Array [ + Object { + "lanes": Array [ + 0, + ], + "timestamp": 0.004, + "type": "schedule-render", + "warning": null, + }, + ], + "startTime": 4, + "suspenseEvents": Array [], + } + `); } }); @@ -568,189 +572,189 @@ describe(preprocessData, () => { ...createUserTimingData(clearedMarks), ]); expect(data).toMatchInlineSnapshot(` - Object { - "componentMeasures": Array [ - Object { - "componentName": "App", - "duration": 0.001, - "timestamp": 0.006, - "warning": null, - }, - Object { - "componentName": "App", - "duration": 0.0010000000000000009, - "timestamp": 0.02, - "warning": null, - }, - ], - "duration": 0.031, - "flamechart": Array [], - "laneToLabelMap": Map { - 0 => "Sync", - 1 => "InputContinuousHydration", - 2 => "InputContinuous", - 3 => "DefaultHydration", - 4 => "Default", - 5 => "TransitionHydration", - 6 => "Transition", - 7 => "Transition", - 8 => "Transition", - 9 => "Transition", - 10 => "Transition", - 11 => "Transition", - 12 => "Transition", - 13 => "Transition", - 14 => "Transition", - 15 => "Transition", - 16 => "Transition", - 17 => "Transition", - 18 => "Transition", - 19 => "Transition", - 20 => "Transition", - 21 => "Transition", - 22 => "Retry", - 23 => "Retry", - 24 => "Retry", - 25 => "Retry", - 26 => "Retry", - 27 => "SelectiveHydration", - 28 => "IdleHydration", - 29 => "Idle", - 30 => "Offscreen", - }, - "measures": Array [ - Object { - "batchUID": 0, - "depth": 0, - "duration": 0.009999999999999998, - "lanes": Array [ - 4, - ], - "timestamp": 0.005, - "type": "render-idle", - }, - Object { - "batchUID": 0, - "depth": 0, - "duration": 0.003, - "lanes": Array [ - 4, - ], - "timestamp": 0.005, - "type": "render", - }, - Object { - "batchUID": 0, - "depth": 0, - "duration": 0.006, - "lanes": Array [ - 4, - ], - "timestamp": 0.009, - "type": "commit", - }, - Object { - "batchUID": 0, - "depth": 1, - "duration": 0.0010000000000000009, - "lanes": Array [ - 4, - ], - "timestamp": 0.013, - "type": "layout-effects", - }, - Object { - "batchUID": 0, - "depth": 0, - "duration": 0.0019999999999999983, - "lanes": Array [ - 4, - ], - "timestamp": 0.016, - "type": "passive-effects", - }, - Object { - "batchUID": 1, - "depth": 0, - "duration": 0.010000000000000002, - "lanes": Array [ - 4, - ], - "timestamp": 0.019, - "type": "render-idle", - }, - Object { - "batchUID": 1, - "depth": 0, - "duration": 0.002999999999999999, - "lanes": Array [ - 4, - ], - "timestamp": 0.019, - "type": "render", - }, - Object { - "batchUID": 1, - "depth": 0, - "duration": 0.006000000000000002, - "lanes": Array [ - 4, - ], - "timestamp": 0.023, - "type": "commit", - }, - Object { - "batchUID": 1, - "depth": 1, - "duration": 0.0010000000000000009, - "lanes": Array [ - 4, - ], - "timestamp": 0.027, - "type": "layout-effects", - }, - Object { - "batchUID": 1, - "depth": 0, - "duration": 0.0010000000000000009, - "lanes": Array [ - 4, - ], - "timestamp": 0.03, - "type": "passive-effects", - }, - ], - "nativeEvents": Array [], - "otherUserTimingMarks": Array [ - Object { - "name": "__v3", - "timestamp": 0.003, - }, - ], - "reactVersion": "17.0.3", - "schedulingEvents": Array [ - Object { - "lanes": Array [ - 4, - ], - "timestamp": 0.004, - "type": "schedule-render", - "warning": null, - }, - Object { - "componentName": "App", - "lanes": Array [ - 4, - ], - "timestamp": 0.017, - "type": "schedule-state-update", - "warning": null, - }, - ], - "startTime": 4, - "suspenseEvents": Array [], - } - `); + Object { + "componentMeasures": Array [ + Object { + "componentName": "App", + "duration": 0.001, + "timestamp": 0.006, + "warning": null, + }, + Object { + "componentName": "App", + "duration": 0.0010000000000000009, + "timestamp": 0.02, + "warning": null, + }, + ], + "duration": 0.031, + "flamechart": Array [], + "laneToLabelMap": Map { + 0 => "Sync", + 1 => "InputContinuousHydration", + 2 => "InputContinuous", + 3 => "DefaultHydration", + 4 => "Default", + 5 => "TransitionHydration", + 6 => "Transition", + 7 => "Transition", + 8 => "Transition", + 9 => "Transition", + 10 => "Transition", + 11 => "Transition", + 12 => "Transition", + 13 => "Transition", + 14 => "Transition", + 15 => "Transition", + 16 => "Transition", + 17 => "Transition", + 18 => "Transition", + 19 => "Transition", + 20 => "Transition", + 21 => "Transition", + 22 => "Retry", + 23 => "Retry", + 24 => "Retry", + 25 => "Retry", + 26 => "Retry", + 27 => "SelectiveHydration", + 28 => "IdleHydration", + 29 => "Idle", + 30 => "Offscreen", + }, + "measures": Array [ + Object { + "batchUID": 0, + "depth": 0, + "duration": 0.009999999999999998, + "lanes": Array [ + 4, + ], + "timestamp": 0.005, + "type": "render-idle", + }, + Object { + "batchUID": 0, + "depth": 0, + "duration": 0.003, + "lanes": Array [ + 4, + ], + "timestamp": 0.005, + "type": "render", + }, + Object { + "batchUID": 0, + "depth": 0, + "duration": 0.006, + "lanes": Array [ + 4, + ], + "timestamp": 0.009, + "type": "commit", + }, + Object { + "batchUID": 0, + "depth": 1, + "duration": 0.0010000000000000009, + "lanes": Array [ + 4, + ], + "timestamp": 0.013, + "type": "layout-effects", + }, + Object { + "batchUID": 0, + "depth": 0, + "duration": 0.0019999999999999983, + "lanes": Array [ + 4, + ], + "timestamp": 0.016, + "type": "passive-effects", + }, + Object { + "batchUID": 1, + "depth": 0, + "duration": 0.010000000000000002, + "lanes": Array [ + 4, + ], + "timestamp": 0.019, + "type": "render-idle", + }, + Object { + "batchUID": 1, + "depth": 0, + "duration": 0.002999999999999999, + "lanes": Array [ + 4, + ], + "timestamp": 0.019, + "type": "render", + }, + Object { + "batchUID": 1, + "depth": 0, + "duration": 0.006000000000000002, + "lanes": Array [ + 4, + ], + "timestamp": 0.023, + "type": "commit", + }, + Object { + "batchUID": 1, + "depth": 1, + "duration": 0.0010000000000000009, + "lanes": Array [ + 4, + ], + "timestamp": 0.027, + "type": "layout-effects", + }, + Object { + "batchUID": 1, + "depth": 0, + "duration": 0.0010000000000000009, + "lanes": Array [ + 4, + ], + "timestamp": 0.03, + "type": "passive-effects", + }, + ], + "nativeEvents": Array [], + "otherUserTimingMarks": Array [ + Object { + "name": "__v3", + "timestamp": 0.003, + }, + ], + "reactVersion": "17.0.3", + "schedulingEvents": Array [ + Object { + "lanes": Array [ + 4, + ], + "timestamp": 0.004, + "type": "schedule-render", + "warning": null, + }, + Object { + "componentName": "App", + "lanes": Array [ + 4, + ], + "timestamp": 0.017, + "type": "schedule-state-update", + "warning": null, + }, + ], + "startTime": 4, + "suspenseEvents": Array [], + } + `); } }); @@ -833,5 +837,468 @@ describe(preprocessData, () => { `); }); + describe('warnings', () => { + describe('long event handlers', () => { + it('should not warn when React scedules a (sync) update inside of a short event handler', () => { + function App() { + return null; + } + + if (gate(flags => flags.enableSchedulingProfiler)) { + const testMarks = [ + creactCpuProfilerSample(), + ...createBoilerplateEntries(), + createNativeEventEntry('click', 5), + ]; + + clearedMarks.splice(0); + + ReactDOM.render(, document.createElement('div')); + + testMarks.push(...createUserTimingData(clearedMarks)); + + const data = preprocessData(testMarks); + const event = data.nativeEvents.find(({type}) => type === 'click'); + expect(event.warning).toBe(null); + } + }); + + it('should not warn about long events if the cause was non-React JavaScript', () => { + function App() { + return null; + } + + if (gate(flags => flags.enableSchedulingProfiler)) { + const testMarks = [ + creactCpuProfilerSample(), + ...createBoilerplateEntries(), + createNativeEventEntry('click', 25000), + ]; + + startTime += 2000; + + clearedMarks.splice(0); + + ReactDOM.render(, document.createElement('div')); + + testMarks.push(...createUserTimingData(clearedMarks)); + + const data = preprocessData(testMarks); + const event = data.nativeEvents.find(({type}) => type === 'click'); + expect(event.warning).toBe(null); + } + }); + + it('should warn when React scedules a long (sync) update inside of an event', () => { + function App() { + return null; + } + + if (gate(flags => flags.enableSchedulingProfiler)) { + const testMarks = [ + creactCpuProfilerSample(), + ...createBoilerplateEntries(), + createNativeEventEntry('click', 25000), + ]; + + clearedMarks.splice(0); + + ReactDOM.render(, document.createElement('div')); + + clearedMarks.forEach(markName => { + if (markName === '--render-stop') { + // Fake a long running render + startTime += 20000; + } + + testMarks.push({ + pid: ++pid, + tid: ++tid, + ts: ++startTime, + args: {data: {}}, + cat: 'blink.user_timing', + name: markName, + ph: 'R', + }); + }); + + const data = preprocessData(testMarks); + const event = data.nativeEvents.find(({type}) => type === 'click'); + expect(event.warning).toMatchInlineSnapshot( + `"An event handler scheduled a big update with React. Consider using the Transition API to defer some of this work."`, + ); + } + }); + + it('should not warn when React finishes a previously long (async) update with a short (sync) update inside of an event', () => { + function Yield({id, value}) { + Scheduler.unstable_yieldValue(`${id}:${value}`); + return null; + } + + if (gate(flags => flags.enableSchedulingProfiler)) { + const testMarks = [ + creactCpuProfilerSample(), + ...createBoilerplateEntries(), + ]; + + // Advance the clock by some arbitrary amount. + startTime += 50000; + + const root = ReactDOM.createRoot(document.createElement('div')); + + React.startTransition(() => { + // Start rendering an async update (but don't finish). + root.render( + <> + + + , + ); + expect(Scheduler).toFlushAndYieldThrough(['A:1']); + + testMarks.push(...createUserTimingData(clearedMarks)); + clearedMarks.splice(0); + + // Advance the clock some more to make the pending React update seem long. + startTime += 20000; + + // Fake a long "click" event in the middle + // and schedule a sync update that will also flush the previous work. + testMarks.push(createNativeEventEntry('click', 25000)); + ReactDOM.flushSync(() => { + root.render( + <> + + + , + ); + }); + }); + + expect(Scheduler).toHaveYielded(['A:2', 'B:2']); + + testMarks.push(...createUserTimingData(clearedMarks)); + + const data = preprocessData(testMarks); + const event = data.nativeEvents.find(({type}) => type === 'click'); + expect(event.warning).toBe(null); + } + }); + }); + + describe('nested updates', () => { + it('should not warn about short nested (state) updates during layout effects', () => { + function Component() { + const [didMount, setDidMount] = React.useState(false); + Scheduler.unstable_yieldValue( + `Component ${didMount ? 'update' : 'mount'}`, + ); + React.useLayoutEffect(() => { + setDidMount(true); + }, []); + return didMount; + } + + if (gate(flags => flags.enableSchedulingProfiler)) { + const root = ReactDOM.createRoot(document.createElement('div')); + act(() => { + root.render(); + }); + + expect(Scheduler).toHaveYielded([ + 'Component mount', + 'Component update', + ]); + + const data = preprocessData([ + ...createBoilerplateEntries(), + ...createUserTimingData(clearedMarks), + ]); + + const event = data.schedulingEvents.find( + ({type}) => type === 'schedule-state-update', + ); + expect(event.warning).toBe(null); + } + }); + + it('should not warn about short (forced) updates during layout effects', () => { + class Component extends React.Component { + _didMount: boolean = false; + componentDidMount() { + this._didMount = true; + this.forceUpdate(); + } + render() { + Scheduler.unstable_yieldValue( + `Component ${this._didMount ? 'update' : 'mount'}`, + ); + return null; + } + } + + if (gate(flags => flags.enableSchedulingProfiler)) { + const root = ReactDOM.createRoot(document.createElement('div')); + act(() => { + root.render(); + }); + + expect(Scheduler).toHaveYielded([ + 'Component mount', + 'Component update', + ]); + + const data = preprocessData([ + ...createBoilerplateEntries(), + ...createUserTimingData(clearedMarks), + ]); + + const event = data.schedulingEvents.find( + ({type}) => type === 'schedule-force-update', + ); + expect(event.warning).toBe(null); + } + }); + + it('should warn about long nested (state) updates during layout effects', () => { + function Component() { + const [didMount, setDidMount] = React.useState(false); + Scheduler.unstable_yieldValue( + `Component ${didMount ? 'update' : 'mount'}`, + ); + // Fake a long render + startTime += 20000; + React.useLayoutEffect(() => { + setDidMount(true); + }, []); + return didMount; + } + + if (gate(flags => flags.enableSchedulingProfiler)) { + const cpuProfilerSample = creactCpuProfilerSample(); + + const root = ReactDOM.createRoot(document.createElement('div')); + act(() => { + root.render(); + }); + + expect(Scheduler).toHaveYielded([ + 'Component mount', + 'Component update', + ]); + + const testMarks = []; + clearedMarks.forEach(markName => { + if (markName === '--component-render-start-Component') { + // Fake a long running render + startTime += 20000; + } + + testMarks.push({ + pid: ++pid, + tid: ++tid, + ts: ++startTime, + args: {data: {}}, + cat: 'blink.user_timing', + name: markName, + ph: 'R', + }); + }); + + const data = preprocessData([ + cpuProfilerSample, + ...createBoilerplateEntries(), + ...testMarks, + ]); + + const event = data.schedulingEvents.find( + ({type}) => type === 'schedule-state-update', + ); + expect(event.warning).toMatchInlineSnapshot( + `"A big nested update was scheduled during layout. Nested updates require React to re-render synchronously before the browser can paint. Consider delaying this update by moving it to a passive effect (useEffect)."`, + ); + } + }); + + it('should warn about long nested (forced) updates during layout effects', () => { + class Component extends React.Component { + _didMount: boolean = false; + componentDidMount() { + this._didMount = true; + this.forceUpdate(); + } + render() { + Scheduler.unstable_yieldValue( + `Component ${this._didMount ? 'update' : 'mount'}`, + ); + return null; + } + } + + if (gate(flags => flags.enableSchedulingProfiler)) { + const cpuProfilerSample = creactCpuProfilerSample(); + + const root = ReactDOM.createRoot(document.createElement('div')); + act(() => { + root.render(); + }); + + expect(Scheduler).toHaveYielded([ + 'Component mount', + 'Component update', + ]); + + const testMarks = []; + clearedMarks.forEach(markName => { + if (markName === '--component-render-start-Component') { + // Fake a long running render + startTime += 20000; + } + + testMarks.push({ + pid: ++pid, + tid: ++tid, + ts: ++startTime, + args: {data: {}}, + cat: 'blink.user_timing', + name: markName, + ph: 'R', + }); + }); + + const data = preprocessData([ + cpuProfilerSample, + ...createBoilerplateEntries(), + ...testMarks, + ]); + + const event = data.schedulingEvents.find( + ({type}) => type === 'schedule-force-update', + ); + expect(event.warning).toMatchInlineSnapshot( + `"A big nested update was scheduled during layout. Nested updates require React to re-render synchronously before the browser can paint. Consider delaying this update by moving it to a passive effect (useEffect)."`, + ); + } + }); + }); + + describe('suspend during an update', () => { + // This also tests an edge case where the a component suspends while profiling + // before the first commit is logged (so the lane-to-labels map will not yet exist). + it('should warn about suspending during an udpate', () => { + let promise = null; + let resolvedValue = null; + function readValue(value) { + if (resolvedValue !== null) { + return resolvedValue; + } else if (promise === null) { + promise = Promise.resolve(true).then(() => { + resolvedValue = value; + }); + } + throw promise; + } + + function Component({shouldSuspend}) { + Scheduler.unstable_yieldValue(`Component ${shouldSuspend}`); + if (shouldSuspend) { + readValue(123); + } + return null; + } + + if (gate(flags => flags.enableSchedulingProfiler)) { + // Mount and commit the app + const root = ReactDOM.createRoot(document.createElement('div')); + act(() => + root.render( + + + , + ), + ); + + clearedMarks.splice(0); + + const testMarks = [creactCpuProfilerSample()]; + + // Start profiling and suspend during a render. + act(() => + root.render( + + + , + ), + ); + + testMarks.push(...createUserTimingData(clearedMarks)); + + const data = preprocessData(testMarks); + expect(data.suspenseEvents).toHaveLength(1); + expect(data.suspenseEvents[0].warning).toMatchInlineSnapshot( + `"A component suspended during an update which caused a fallback to be shown. Consider using the Transition API to avoid hiding components after they've been mounted."`, + ); + } + }); + + it('should not warn about suspending during an transition', async () => { + let promise = null; + let resolvedValue = null; + function readValue(value) { + if (resolvedValue !== null) { + return resolvedValue; + } else if (promise === null) { + promise = Promise.resolve(true).then(() => { + resolvedValue = value; + }); + } + throw promise; + } + + function Component({shouldSuspend}) { + Scheduler.unstable_yieldValue(`Component ${shouldSuspend}`); + if (shouldSuspend) { + readValue(123); + } + return null; + } + + if (gate(flags => flags.enableSchedulingProfiler)) { + // Mount and commit the app + const root = ReactDOM.createRoot(document.createElement('div')); + act(() => + root.render( + + + , + ), + ); + + clearedMarks.splice(0); + + const testMarks = [creactCpuProfilerSample()]; + + // Start profiling and suspend during a render. + await act(async () => + React.startTransition(() => + root.render( + + + , + ), + ), + ); + + testMarks.push(...createUserTimingData(clearedMarks)); + + const data = preprocessData(testMarks); + expect(data.suspenseEvents).toHaveLength(1); + expect(data.suspenseEvents[0].warning).toBe(null); + } + }); + }); + }); + // TODO: Add test for flamechart parsing }); diff --git a/packages/react-devtools-scheduling-profiler/src/import-worker/preprocessData.js b/packages/react-devtools-scheduling-profiler/src/import-worker/preprocessData.js index 36beebac0b137..92695a5da010a 100644 --- a/packages/react-devtools-scheduling-profiler/src/import-worker/preprocessData.js +++ b/packages/react-devtools-scheduling-profiler/src/import-worker/preprocessData.js @@ -22,11 +22,13 @@ import type { ReactComponentMeasure, ReactMeasureType, ReactProfilerData, + SchedulingEvent, SuspenseEvent, } from '../types'; import {REACT_TOTAL_NUM_LANES, SCHEDULING_PROFILER_VERSION} from '../constants'; import InvalidProfileError from './InvalidProfileError'; +import {getBatchRange} from '../utils/getBatchRange'; type MeasureStackElement = {| type: ReactMeasureType, @@ -42,6 +44,12 @@ type ProcessorState = {| measureStack: MeasureStackElement[], nativeEventStack: NativeEvent[], nextRenderShouldGenerateNewBatchID: boolean, + potentialLongEvents: Array<[NativeEvent, BatchUID]>, + potentialLongNestedUpdate: SchedulingEvent | null, + potentialLongNestedUpdates: Array<[SchedulingEvent, BatchUID]>, + potentialSuspenseEventsOutsideOfTransition: Array< + [SuspenseEvent, ReactLane[]], + >, uidCounter: BatchUID, unresolvedSuspenseEvents: Map, |}; @@ -52,7 +60,9 @@ const WARNING_STRINGS = { LONG_EVENT_HANDLER: 'An event handler scheduled a big update with React. Consider using the Transition API to defer some of this work.', NESTED_UPDATE: - 'A nested update was scheduled during layout. These updates require React to re-render synchronously before the browser can paint.', + 'A big nested update was scheduled during layout. ' + + 'Nested updates require React to re-render synchronously before the browser can paint. ' + + 'Consider delaying this update by moving it to a passive effect (useEffect).', SUSPEND_DURING_UPATE: 'A component suspended during an update which caused a fallback to be shown. ' + "Consider using the Transition API to avoid hiding components after they've been mounted.", @@ -309,37 +319,39 @@ function processTimelineEvent( } else if (name.startsWith('--schedule-forced-update-')) { const [laneBitmaskString, componentName] = name.substr(25).split('-'); - let warning = null; - if (state.measureStack.find(({type}) => type === 'commit')) { - // TODO (scheduling profiler) Only warn if the subsequent update is longer than some threshold. - // This might be easier to do if we separated warnings into a second pass. - warning = WARNING_STRINGS.NESTED_UPDATE; - } - - currentProfilerData.schedulingEvents.push({ + const forceUpdateEvent = { type: 'schedule-force-update', lanes: getLanesFromTransportDecimalBitmask(laneBitmaskString), componentName, timestamp: startTime, - warning, - }); - } else if (name.startsWith('--schedule-state-update-')) { - const [laneBitmaskString, componentName] = name.substr(24).split('-'); + warning: null, + }; - let warning = null; + // If this is a nested update, make a note of it. + // Once we're done processing events, we'll check to see if it was a long update and warn about it. if (state.measureStack.find(({type}) => type === 'commit')) { - // TODO (scheduling profiler) Only warn if the subsequent update is longer than some threshold. - // This might be easier to do if we separated warnings into a second pass. - warning = WARNING_STRINGS.NESTED_UPDATE; + state.potentialLongNestedUpdate = forceUpdateEvent; } - currentProfilerData.schedulingEvents.push({ + currentProfilerData.schedulingEvents.push(forceUpdateEvent); + } else if (name.startsWith('--schedule-state-update-')) { + const [laneBitmaskString, componentName] = name.substr(24).split('-'); + + const stateUpdateEvent = { type: 'schedule-state-update', lanes: getLanesFromTransportDecimalBitmask(laneBitmaskString), componentName, timestamp: startTime, - warning, - }); + warning: null, + }; + + // If this is a nested update, make a note of it. + // Once we're done processing events, we'll check to see if it was a long update and warn about it. + if (state.measureStack.find(({type}) => type === 'commit')) { + state.potentialLongNestedUpdate = stateUpdateEvent; + } + + currentProfilerData.schedulingEvents.push(stateUpdateEvent); } // eslint-disable-line brace-style // React Events - suspense @@ -349,16 +361,6 @@ function processTimelineEvent( .split('-'); const lanes = getLanesFromTransportDecimalBitmask(laneBitmaskString); - // TODO It's possible we don't have lane-to-label mapping yet (since it's logged during commit phase) - // We may need to do this sort of error checking in a separate pass. - let warning = null; - if (phase === 'update') { - // HACK This is a bit gross but the numeric lane value might change between render versions. - if (lanes.some(lane => laneToLabelMap.get(lane) === 'Transition')) { - warning = WARNING_STRINGS.SUSPEND_DURING_UPATE; - } - } - const availableDepths = new Array( state.unresolvedSuspenseEvents.size + 1, ).fill(true); @@ -389,9 +391,20 @@ function processTimelineEvent( resuspendTimestamps: null, timestamp: startTime, type: 'suspense', - warning, + warning: null, }; + if (phase === 'update') { + // If a component suspended during an update, we should verify that it was during a transition. + // We need the lane metadata to verify this though. + // Since that data is only logged during commit, we may not have it yet. + // Store these events for post-processing then. + state.potentialSuspenseEventsOutsideOfTransition.push([ + suspenseEvent, + lanes, + ]); + } + currentProfilerData.suspenseEvents.push(suspenseEvent); state.unresolvedSuspenseEvents.set(id, suspenseEvent); } else if (name.startsWith('--suspense-resuspend-')) { @@ -430,6 +443,17 @@ function processTimelineEvent( state.nextRenderShouldGenerateNewBatchID = false; state.batchUID = ((state.uidCounter++: any): BatchUID); } + + // If this render is the result of a nested update, make a note of it. + // Once we're done processing events, we'll check to see if it was a long update and warn about it. + if (state.potentialLongNestedUpdate !== null) { + state.potentialLongNestedUpdates.push([ + state.potentialLongNestedUpdate, + state.batchUID, + ]); + state.potentialLongNestedUpdate = null; + } + const [laneBitmaskString] = name.substr(15).split('-'); throwIfIncomplete('render', state.measureStack); @@ -453,11 +477,14 @@ function processTimelineEvent( for (let i = 0; i < state.nativeEventStack.length; i++) { const nativeEvent = state.nativeEventStack[i]; const stopTime = nativeEvent.timestamp + nativeEvent.duration; - if ( - stopTime > startTime && - nativeEvent.duration > NATIVE_EVENT_DURATION_THRESHOLD - ) { - nativeEvent.warning = WARNING_STRINGS.LONG_EVENT_HANDLER; + + // If React work was scheduled during an event handler, and the event had a long duration, + // it might be because the React render was long and stretched the event. + // It might also be that the React work was short and that something else stretched the event. + // Make a note of this event for now and we'll examine the batch of React render work later. + // (We can't know until we're done processing the React update anyway.) + if (stopTime > startTime) { + state.potentialLongEvents.push([nativeEvent, state.batchUID]); } } } else if ( @@ -666,6 +693,10 @@ export default function preprocessData( measureStack: [], nativeEventStack: [], nextRenderShouldGenerateNewBatchID: true, + potentialLongEvents: [], + potentialLongNestedUpdate: null, + potentialLongNestedUpdates: [], + potentialSuspenseEventsOutsideOfTransition: [], uidCounter: 0, unresolvedSuspenseEvents: new Map(), }; @@ -684,5 +715,34 @@ export default function preprocessData( console.error('Incomplete events or measures', measureStack); } + // Check for warnings. + state.potentialLongEvents.forEach(([nativeEvent, batchUID]) => { + // See how long the subsequent batch of React work was. + // Ignore any work that was already started. + const [startTime, stopTime] = getBatchRange( + batchUID, + profilerData, + nativeEvent.timestamp, + ); + if (stopTime - startTime > NATIVE_EVENT_DURATION_THRESHOLD) { + nativeEvent.warning = WARNING_STRINGS.LONG_EVENT_HANDLER; + } + }); + state.potentialLongNestedUpdates.forEach(([schedulingEvent, batchUID]) => { + // See how long the subsequent batch of React work was. + const [startTime, stopTime] = getBatchRange(batchUID, profilerData); + if (stopTime - startTime > NATIVE_EVENT_DURATION_THRESHOLD) { + schedulingEvent.warning = WARNING_STRINGS.NESTED_UPDATE; + } + }); + state.potentialSuspenseEventsOutsideOfTransition.forEach( + ([suspenseEvent, lanes]) => { + // HACK This is a bit gross but the numeric lane value might change between render versions. + if (!lanes.some(lane => laneToLabelMap.get(lane) === 'Transition')) { + suspenseEvent.warning = WARNING_STRINGS.SUSPEND_DURING_UPATE; + } + }, + ); + return profilerData; } diff --git a/packages/react-devtools-scheduling-profiler/src/utils/getBatchRange.js b/packages/react-devtools-scheduling-profiler/src/utils/getBatchRange.js index cba61a47161aa..0d977e0390e79 100644 --- a/packages/react-devtools-scheduling-profiler/src/utils/getBatchRange.js +++ b/packages/react-devtools-scheduling-profiler/src/utils/getBatchRange.js @@ -14,6 +14,7 @@ import type {BatchUID, Milliseconds, ReactProfilerData} from '../types'; function unmemoizedGetBatchRange( batchUID: BatchUID, data: ReactProfilerData, + minStartTime?: ?number, ): [Milliseconds, Milliseconds] { const {measures} = data; @@ -22,18 +23,23 @@ function unmemoizedGetBatchRange( let i = 0; + // Find the first measure in the current batch. for (i; i < measures.length; i++) { const measure = measures[i]; if (measure.batchUID === batchUID) { - startTime = measure.timestamp; - break; + if (minStartTime == null || measure.timestamp >= minStartTime) { + startTime = measure.timestamp; + break; + } } } + // Find the last measure in the current batch. for (i; i < measures.length; i++) { const measure = measures[i]; - stopTime = measure.timestamp; - if (measure.batchUID !== batchUID) { + if (measure.batchUID === batchUID) { + stopTime = measure.timestamp; + } else { break; } }