From 3df46e6745226b2a695d9b5070a13772aa69786d Mon Sep 17 00:00:00 2001 From: Brian Vaughn Date: Fri, 6 Aug 2021 11:59:49 -0400 Subject: [PATCH] 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. --- .../__tests__/preprocessData-test.internal.js | 959 ++++++++++-------- .../src/import-worker/preprocessData.js | 32 +- .../src/utils/getBatchRange.js | 12 +- 3 files changed, 591 insertions(+), 412 deletions(-) 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..5f3a0fc5dbe9b 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,156 @@ 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); + } + }); + }); + }); + // 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..f19f94546938b 100644 --- a/packages/react-devtools-scheduling-profiler/src/import-worker/preprocessData.js +++ b/packages/react-devtools-scheduling-profiler/src/import-worker/preprocessData.js @@ -27,6 +27,7 @@ import type { 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 +43,7 @@ type ProcessorState = {| measureStack: MeasureStackElement[], nativeEventStack: NativeEvent[], nextRenderShouldGenerateNewBatchID: boolean, + potentialLongEvents: Array<[NativeEvent, BatchUID]>, uidCounter: BatchUID, unresolvedSuspenseEvents: Map, |}; @@ -349,7 +351,7 @@ 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) + // TODO (scheduling profiler) 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') { @@ -453,11 +455,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 +671,7 @@ export default function preprocessData( measureStack: [], nativeEventStack: [], nextRenderShouldGenerateNewBatchID: true, + potentialLongEvents: [], uidCounter: 0, unresolvedSuspenseEvents: new Map(), }; @@ -684,5 +690,19 @@ 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; + } + }); + 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..44da98d6b4cf9 100644 --- a/packages/react-devtools-scheduling-profiler/src/utils/getBatchRange.js +++ b/packages/react-devtools-scheduling-profiler/src/utils/getBatchRange.js @@ -14,26 +14,30 @@ import type {BatchUID, Milliseconds, ReactProfilerData} from '../types'; function unmemoizedGetBatchRange( batchUID: BatchUID, data: ReactProfilerData, + minStartTime?: number = 0, ): [Milliseconds, Milliseconds] { const {measures} = data; - let startTime = 0; + let startTime = minStartTime; let stopTime = Infinity; 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; + startTime = Math.max(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; } }