diff --git a/packages/react-reconciler/src/__tests__/ReactIncrementalPerf-test.internal.js b/packages/react-reconciler/src/__tests__/ReactIncrementalPerf-test.internal.js index b6b957647e044..48401d2d630c6 100644 --- a/packages/react-reconciler/src/__tests__/ReactIncrementalPerf-test.internal.js +++ b/packages/react-reconciler/src/__tests__/ReactIncrementalPerf-test.internal.js @@ -127,6 +127,7 @@ describe('ReactDebugFiberPerf', () => { require('shared/ReactFeatureFlags').enableProfilerTimer = false; require('shared/ReactFeatureFlags').replayFailedUnitOfWorkWithInvokeGuardedCallback = false; require('shared/ReactFeatureFlags').debugRenderPhaseSideEffectsForStrictMode = false; + require('scheduler/src/SchedulerFeatureFlags').enableProfiling = false; // Import after the polyfill is set up: React = require('react'); diff --git a/packages/scheduler/src/Scheduler.js b/packages/scheduler/src/Scheduler.js index cdb9930d4c973..21e60491a008e 100644 --- a/packages/scheduler/src/Scheduler.js +++ b/packages/scheduler/src/Scheduler.js @@ -8,9 +8,13 @@ /* eslint-disable no-var */ -import {enableSchedulerDebugging} from './SchedulerFeatureFlags'; import { - requestHostCallback, + enableSchedulerDebugging, + enableProfiling, +} from './SchedulerFeatureFlags'; +import { + requestHostCallback as requestHostCallbackWithoutProfiling, + cancelHostCallback, requestHostTimeout, cancelHostTimeout, shouldYieldToHost, @@ -18,13 +22,23 @@ import { forceFrameRate, requestPaint, } from './SchedulerHostConfig'; - -// TODO: Use symbols? -var ImmediatePriority = 1; -var UserBlockingPriority = 2; -var NormalPriority = 3; -var LowPriority = 4; -var IdlePriority = 5; +import { + ImmediatePriority, + UserBlockingPriority, + NormalPriority, + LowPriority, + IdlePriority, +} from './SchedulerPriorities'; +import { + markTaskRun, + markTaskYield, + markTaskCompleted, + markTaskCanceled, + markTaskErrored, + markSchedulerSuspended, + markSchedulerUnsuspended, + markTaskStart, +} from './SchedulerProfiling'; // Max 31 bit integer. The max integer size in V8 for 32-bit systems. // Math.pow(2, 30) - 1 @@ -44,6 +58,9 @@ var IDLE_PRIORITY = maxSigned31BitInt; var firstTask = null; var firstDelayedTask = null; +// Only used for profiling +var taskIdCounter = 0; + // Pausing the scheduler is useful for debugging. var isSchedulerPaused = false; @@ -72,6 +89,17 @@ function scheduler_flushTaskAtPriority_Idle(callback, didTimeout) { return callback(didTimeout); } +function requestHostCallbackWithProfiling(cb) { + if (enableProfiling) { + markSchedulerSuspended(); + requestHostCallbackWithoutProfiling(cb); + } +} + +const requestHostCallback = enableProfiling + ? requestHostCallbackWithProfiling + : requestHostCallbackWithoutProfiling; + function flushTask(task, currentTime) { // Remove the task from the list before calling the callback. That way the // list is in a consistent state even if the callback throws. @@ -98,6 +126,7 @@ function flushTask(task, currentTime) { currentTask = task; var continuationCallback; try { + markTaskRun(task); var didUserCallbackTimeout = task.expirationTime <= currentTime; // Add an extra function to the callstack. Profiling tools can use this // to infer the priority of work that appears higher in the stack. @@ -134,6 +163,7 @@ function flushTask(task, currentTime) { break; } } catch (error) { + markTaskErrored(task); throw error; } finally { currentPriorityLevel = previousPriorityLevel; @@ -143,6 +173,7 @@ function flushTask(task, currentTime) { // A callback may return a continuation. The continuation should be scheduled // with the same priority and expiration as the just-finished callback. if (typeof continuationCallback === 'function') { + markTaskYield(task); var expirationTime = task.expirationTime; var continuationTask = task; continuationTask.callback = continuationCallback; @@ -180,6 +211,8 @@ function flushTask(task, currentTime) { continuationTask.next = nextAfterContinuation; continuationTask.previous = previous; } + } else { + markTaskCompleted(task); } } @@ -229,6 +262,10 @@ function flushWork(hasTimeRemaining, initialTime) { return; } + if (isHostCallbackScheduled) { + markSchedulerUnsuspended(); + } + // We'll need a host callback the next time work is scheduled. isHostCallbackScheduled = false; if (isHostTimeoutScheduled) { @@ -271,6 +308,8 @@ function flushWork(hasTimeRemaining, initialTime) { } // Return whether there's additional work if (firstTask !== null) { + isHostCallbackScheduled = true; + markSchedulerSuspended(); return true; } else { if (firstDelayedTask !== null) { @@ -369,6 +408,7 @@ function unstable_scheduleCallback(priorityLevel, callback, options) { var startTime; var timeout; + var label; if (typeof options === 'object' && options !== null) { var delay = options.delay; if (typeof delay === 'number' && delay > 0) { @@ -380,6 +420,12 @@ function unstable_scheduleCallback(priorityLevel, callback, options) { typeof options.timeout === 'number' ? options.timeout : timeoutForPriorityLevel(priorityLevel); + if (enableProfiling) { + var _label = options.label; + if (typeof _label === 'string') { + label = _label; + } + } } else { timeout = timeoutForPriorityLevel(priorityLevel); startTime = currentTime; @@ -396,6 +442,14 @@ function unstable_scheduleCallback(priorityLevel, callback, options) { previous: null, }; + if (enableProfiling) { + taskIdCounter++; + newTask.id = taskIdCounter; + if (typeof options === 'object' && options !== null) { + newTask.label = label; + } + } + if (startTime > currentTime) { // This is a delayed task. insertDelayedTask(newTask, startTime); @@ -424,6 +478,7 @@ function unstable_scheduleCallback(priorityLevel, callback, options) { } function insertScheduledTask(newTask, expirationTime) { + markTaskStart(newTask); // Insert the new task into the list, ordered first by its timeout, then by // insertion. So the new task is inserted after any other task the // same timeout @@ -514,11 +569,22 @@ function unstable_cancelCallback(task) { return; } + markTaskCanceled(task); + if (task === next) { if (task === firstTask) { firstTask = null; + if (!isPerformingWork) { + isHostCallbackScheduled = false; + cancelHostCallback(); + markSchedulerUnsuspended(); + } } else if (task === firstDelayedTask) { firstDelayedTask = null; + if (!isPerformingWork) { + isHostTimeoutScheduled = false; + cancelHostTimeout(); + } } } else { if (task === firstTask) { diff --git a/packages/scheduler/src/SchedulerFeatureFlags.js b/packages/scheduler/src/SchedulerFeatureFlags.js index 10749c1eeb259..848c299dd6df4 100644 --- a/packages/scheduler/src/SchedulerFeatureFlags.js +++ b/packages/scheduler/src/SchedulerFeatureFlags.js @@ -8,3 +8,4 @@ export const enableSchedulerDebugging = false; export const enableIsInputPending = false; +export const enableProfiling = __PROFILE__; diff --git a/packages/scheduler/src/SchedulerPriorities.js b/packages/scheduler/src/SchedulerPriorities.js new file mode 100644 index 0000000000000..b7ce82a60cdd3 --- /dev/null +++ b/packages/scheduler/src/SchedulerPriorities.js @@ -0,0 +1,17 @@ +/** + * Copyright (c) Facebook, Inc. and its affiliates. + * + * This source code is licensed under the MIT license found in the + * LICENSE file in the root directory of this source tree. + * + * @flow + */ + +export type PriorityLevel = 1 | 2 | 3 | 4 | 5; + +// TODO: Use symbols? +export const ImmediatePriority = 1; +export const UserBlockingPriority = 2; +export const NormalPriority = 3; +export const LowPriority = 4; +export const IdlePriority = 5; diff --git a/packages/scheduler/src/SchedulerProfiling.js b/packages/scheduler/src/SchedulerProfiling.js new file mode 100644 index 0000000000000..5580c675d03b6 --- /dev/null +++ b/packages/scheduler/src/SchedulerProfiling.js @@ -0,0 +1,114 @@ +/** + * Copyright (c) Facebook, Inc. and its affiliates. + * + * This source code is licensed under the MIT license found in the + * LICENSE file in the root directory of this source tree. + * + * @flow + */ + +import type {PriorityLevel} from './SchedulerPriorities'; +import {enableProfiling as enableProfilingFeatureFlag} from './SchedulerFeatureFlags'; + +const enableProfiling = + enableProfilingFeatureFlag && + typeof performance !== 'undefined' && + typeof performance.mark === 'function' && + typeof performance.clearMarks === 'function'; + +let runIdCounter: number = 0; +let mainThreadIdCounter: number = 0; + +export function markTaskStart(task: {id: number}) { + if (enableProfiling) { + // Use extra field to track if delayed task starts. + const taskStartMark = `SchedulerTask-${task.id}-Start`; + performance.mark(taskStartMark); + performance.clearMarks(taskStartMark); + } +} + +export function markTaskCompleted(task: { + id: number, + priorityLevel: PriorityLevel, + label?: string, +}) { + if (enableProfiling) { + const info = JSON.stringify({ + priorityLevel: task.priorityLevel, + label: task.label, + exitStatus: 'completed', + }); + const taskEndMark = `SchedulerTask-${task.id}-End-${info}`; + performance.mark(taskEndMark); + performance.clearMarks(taskEndMark); + } +} + +export function markTaskCanceled(task: { + id: number, + priorityLevel: PriorityLevel, + label?: string, +}) { + if (enableProfiling) { + const info = JSON.stringify({ + priorityLevel: task.priorityLevel, + label: task.label, + exitStatus: 'canceled', + }); + const taskEndMark = `SchedulerTask-${task.id}-End-${info}`; + performance.mark(taskEndMark); + performance.clearMarks(taskEndMark); + } +} + +export function markTaskErrored(task: { + id: number, + priorityLevel: PriorityLevel, + label?: string, +}) { + if (enableProfiling) { + const info = JSON.stringify({ + priorityLevel: task.priorityLevel, + label: task.label, + exitStatus: 'errored', + }); + const taskEndMark = `SchedulerTask-${task.id}-End-${info}`; + performance.mark(taskEndMark); + performance.clearMarks(taskEndMark); + } +} + +export function markTaskRun(task: {id: number}) { + if (enableProfiling) { + runIdCounter++; + const runMark = `SchedulerTask-${task.id}-Run-${runIdCounter}`; + performance.mark(runMark); + performance.clearMarks(runMark); + } +} + +export function markTaskYield(task: {id: number}) { + if (enableProfiling) { + const yieldMark = `SchedulerTask-${task.id}-Yield-${runIdCounter}`; + performance.mark(yieldMark); + performance.clearMarks(yieldMark); + } +} + +export function markSchedulerSuspended() { + if (enableProfiling) { + mainThreadIdCounter++; + const suspendStartMark = 'SchedulerSuspended-Start-' + mainThreadIdCounter; + performance.mark(suspendStartMark); + performance.clearMarks(suspendStartMark); + } +} + +export function markSchedulerUnsuspended() { + if (enableProfiling) { + const suspendedEndMark = 'SchedulerSuspended-End-' + mainThreadIdCounter; + performance.mark(suspendedEndMark); + performance.clearMarks(suspendedEndMark); + } +} diff --git a/packages/scheduler/src/__tests__/SchedulerProfiling-test.js b/packages/scheduler/src/__tests__/SchedulerProfiling-test.js new file mode 100644 index 0000000000000..11e14511d7f5e --- /dev/null +++ b/packages/scheduler/src/__tests__/SchedulerProfiling-test.js @@ -0,0 +1,397 @@ +/** + * Copyright (c) Facebook, Inc. and its affiliates. + * + * This source code is licensed under the MIT license found in the + * LICENSE file in the root directory of this source tree. + * + * @emails react-core + * @jest-environment node + */ + +/* eslint-disable no-for-of-loops/no-for-of-loops */ + +'use strict'; + +let Scheduler; +// let runWithPriority; +let ImmediatePriority; +let UserBlockingPriority; +let NormalPriority; +let LowPriority; +let IdlePriority; +let scheduleCallback; +let cancelCallback; +// let wrapCallback; +// let getCurrentPriorityLevel; +// let shouldYield; +let performance; + +function priorityLevelToString(priorityLevel) { + switch (priorityLevel) { + case ImmediatePriority: + return 'Immediate'; + case UserBlockingPriority: + return 'User-blocking'; + case NormalPriority: + return 'Normal'; + case LowPriority: + return 'Low'; + case IdlePriority: + return 'Idle'; + default: + return null; + } +} + +describe('Scheduler', () => { + beforeEach(() => { + jest.resetModules(); + jest.mock('scheduler', () => require('scheduler/unstable_mock')); + + performance = global.performance = createUserTimingPolyfill(); + + Scheduler = require('scheduler'); + + // runWithPriority = Scheduler.unstable_runWithPriority; + ImmediatePriority = Scheduler.unstable_ImmediatePriority; + UserBlockingPriority = Scheduler.unstable_UserBlockingPriority; + NormalPriority = Scheduler.unstable_NormalPriority; + LowPriority = Scheduler.unstable_LowPriority; + IdlePriority = Scheduler.unstable_IdlePriority; + scheduleCallback = Scheduler.unstable_scheduleCallback; + cancelCallback = Scheduler.unstable_cancelCallback; + // wrapCallback = Scheduler.unstable_wrapCallback; + // getCurrentPriorityLevel = Scheduler.unstable_getCurrentPriorityLevel; + // shouldYield = Scheduler.unstable_shouldYield; + }); + + afterEach(() => { + performance.assertAllUserTimingsAreCleared(); + }); + + function createUserTimingPolyfill() { + let marks = new Map(); + let unclearedMarkCount = 0; + + return { + mark(name) { + if (marks.has(name)) { + throw Error(`Mark ${name} already exists`); + } + marks.set(name, {name, cleared: false, time: Scheduler.unstable_now()}); + unclearedMarkCount += 1; + }, + clearMarks(name) { + if (typeof name !== 'string') { + throw Error('Must pass a name to clearMarks'); + } + const mark = marks.get(name); + if (mark === undefined) { + throw Error(`Mark "${name}" does not exist`); + } + if (mark.cleared) { + throw Error(`Mark "${name}" already cleared.`); + } + mark.cleared = true; + unclearedMarkCount -= 1; + }, + printUserTimings() { + const tasks = new Map(); + const mainThreadRuns = []; + + // `marks` are stored in a map so that we can detect when they are + // cleared; however, we're going to treat them like an event log, since + // that's the format we'll have in a real performance profile. + // + // This first step reduces the event log to a map of tasks. + for (const mark of marks.values()) { + const parts = mark.name.split('-'); + const type = parts[0]; + switch (type) { + case 'SchedulerTask': { + const taskId = parts[1]; + const eventType = parts[2]; + let task = tasks.get(taskId); + if (task === undefined) { + task = { + id: taskId, + priorityLevel: -1, + label: null, + start: -1, + end: -1, + exitStatus: null, + runs: [], + }; + tasks.set(taskId, task); + } + switch (eventType) { + case 'Start': { + task.start = mark.time; + break; + } + case 'End': { + const info = JSON.parse(parts[3]); + task.end = mark.time; + task.priorityLevel = info.priorityLevel; + task.label = info.label; + task.exitStatus = info.exitStatus; + break; + } + case 'Run': + case 'Yield': { + // NOTE: Mark times are assumed to be monotonic in these tests + // but they might not be given an arbitrary profiling format. + task.runs.push(mark.time); + break; + } + default: { + throw Error(`Unrecognized mark: "${mark.name}"`); + } + } + break; + } + case 'SchedulerSuspended': { + const eventType = parts[1]; + switch (eventType) { + case 'Start': + case 'End': { + // NOTE: Mark times are assumed to be monotonic in these tests + // but they might not be given an arbitrary profiling format. + mainThreadRuns.push(mark.time); + break; + } + default: { + throw Error(`Unrecognized mark: "${mark.name}"`); + } + } + break; + } + default: { + throw Error(`Unrecognized mark: "${mark.name}"`); + } + } + } + + // Now we can render the tasks as a flamegraph. + const labelColumnWidth = 30; + const msPerChar = 50; + + let result = ''; + + const mainThreadLabelColumn = '!!! Main thread '; + let mainThreadTimelineColumn = ''; + let isMainThreadBusy = false; + for (const time of mainThreadRuns) { + const index = time / msPerChar; + mainThreadTimelineColumn += (isMainThreadBusy ? '█' : ' ').repeat( + index - mainThreadTimelineColumn.length, + ); + isMainThreadBusy = !isMainThreadBusy; + } + result += `${mainThreadLabelColumn}│${mainThreadTimelineColumn}\n`; + + const tasksByPriority = Array.from(tasks.values()).sort( + (t1, t2) => t1.priorityLevel - t2.priorityLevel, + ); + + for (const task of tasksByPriority) { + let label = task.label; + if (label === undefined) { + label = 'Task'; + } + let labelColumn = `[${task.id}] ${label} [${priorityLevelToString( + task.priorityLevel, + )}]`; + labelColumn += ' '.repeat(labelColumnWidth - labelColumn.length - 1); + + // Add empty space up until the start mark + let timelineColumn = ' '.repeat(task.start / msPerChar); + + let isRunning = false; + for (const time of task.runs) { + const index = time / msPerChar; + timelineColumn += (isRunning ? '█' : '░').repeat( + index - timelineColumn.length, + ); + isRunning = !isRunning; + } + + const endIndex = task.end / msPerChar; + timelineColumn += (isRunning ? '█' : '░').repeat( + endIndex - timelineColumn.length, + ); + + if (task.exitStatus !== 'completed') { + timelineColumn += `🡐 ${task.exitStatus}`; + } + + result += `${labelColumn}│${timelineColumn}\n`; + } + return '\n' + result; + }, + resetUserTimings() { + marks = new Map(); + unclearedMarkCount = 0; + }, + assertAllUserTimingsAreCleared() { + if (unclearedMarkCount !== 0) { + const unclearedMarkNames = []; + marks.forEach((mark, markName) => { + if (!mark.cleared) { + unclearedMarkNames.push(markName); + } + }); + throw Error('Marks not cleared: ' + unclearedMarkNames.join(', ')); + } + }, + }; + } + + if (!__DEV__) { + // The tests in this suite are dev only + it("empty test so Jest doesn't complain that there are no tests in this file", () => {}); + return; + } + + it('creates a basic flamegraph', () => { + Scheduler.unstable_advanceTime(100); + scheduleCallback( + NormalPriority, + () => { + Scheduler.unstable_advanceTime(300); + scheduleCallback( + UserBlockingPriority, + () => { + Scheduler.unstable_advanceTime(300); + }, + {label: 'Bar'}, + ); + Scheduler.unstable_advanceTime(100); + Scheduler.unstable_yieldValue('Yield'); + return () => { + Scheduler.unstable_advanceTime(300); + }; + }, + {label: 'Foo'}, + ); + expect(Scheduler).toFlushAndYieldThrough(['Yield']); + Scheduler.unstable_advanceTime(100); + expect(Scheduler).toFlushWithoutYielding(); + expect(performance.printUserTimings()).toEqual( + ` +!!! Main thread │ ██ +[2] Bar [User-blocking] │ ░░░░██████ +[1] Foo [Normal] │ ████████░░░░░░░░██████ +`, + ); + }); + + it('marks when a task is canceled', () => { + const task = scheduleCallback(NormalPriority, () => { + Scheduler.unstable_advanceTime(300); + Scheduler.unstable_yieldValue('Yield'); + return () => { + Scheduler.unstable_yieldValue('Continuation'); + Scheduler.unstable_advanceTime(200); + }; + }); + + expect(Scheduler).toFlushAndYieldThrough(['Yield']); + Scheduler.unstable_advanceTime(100); + + cancelCallback(task); + + // Advance more time. This should not affect the size of the main + // thread row, since the Scheduler queue is empty. + Scheduler.unstable_advanceTime(1000); + expect(Scheduler).toFlushWithoutYielding(); + + // The main thread row should end when the callback is cancelled. + expect(performance.printUserTimings()).toEqual( + ` +!!! Main thread │ ██ +[1] Task [Normal] │██████░░🡐 canceled +`, + ); + }); + + it('marks when a task errors', () => { + scheduleCallback(NormalPriority, () => { + Scheduler.unstable_advanceTime(300); + throw Error('Oops'); + }); + + expect(Scheduler).toFlushAndThrow('Oops'); + Scheduler.unstable_advanceTime(100); + + // Advance more time. This should not affect the size of the main + // thread row, since the Scheduler queue is empty. + Scheduler.unstable_advanceTime(1000); + expect(Scheduler).toFlushWithoutYielding(); + + // The main thread row should end when the callback is cancelled. + expect(performance.printUserTimings()).toEqual( + ` +!!! Main thread │ +[1] Task [Normal] │██████🡐 errored +`, + ); + }); + + it('handles cancelling a task that already finished', () => { + const task = scheduleCallback(NormalPriority, () => { + Scheduler.unstable_yieldValue('A'); + Scheduler.unstable_advanceTime(1000); + }); + expect(Scheduler).toFlushAndYield(['A']); + cancelCallback(task); + expect(performance.printUserTimings()).toEqual( + ` +!!! Main thread │ +[1] Task [Normal] │████████████████████ +`, + ); + }); + + it('handles cancelling a task multiple times', () => { + scheduleCallback( + NormalPriority, + () => { + Scheduler.unstable_yieldValue('A'); + Scheduler.unstable_advanceTime(1000); + }, + {label: 'A'}, + ); + Scheduler.unstable_advanceTime(200); + const task = scheduleCallback( + NormalPriority, + () => { + Scheduler.unstable_yieldValue('B'); + Scheduler.unstable_advanceTime(1000); + }, + {label: 'B'}, + ); + Scheduler.unstable_advanceTime(400); + cancelCallback(task); + cancelCallback(task); + cancelCallback(task); + expect(Scheduler).toFlushAndYield(['A']); + expect(performance.printUserTimings()).toEqual( + ` +!!! Main thread │████████████ +[1] A [Normal] │░░░░░░░░░░░░████████████████████ +[2] B [Normal] │ ░░░░░░░░🡐 canceled +`, + ); + }); + + it('handles cancelling a delayed task', () => { + const task = scheduleCallback( + NormalPriority, + () => Scheduler.unstable_yieldValue('A'), + {delay: 1000}, + ); + cancelCallback(task); + expect(Scheduler).toFlushWithoutYielding(); + }); +}); diff --git a/packages/scheduler/src/forks/SchedulerFeatureFlags.www.js b/packages/scheduler/src/forks/SchedulerFeatureFlags.www.js index f13f32802418c..8987fd5f186d4 100644 --- a/packages/scheduler/src/forks/SchedulerFeatureFlags.www.js +++ b/packages/scheduler/src/forks/SchedulerFeatureFlags.www.js @@ -9,4 +9,5 @@ export const { enableIsInputPending, enableSchedulerDebugging, + enableProfiling, } = require('SchedulerFeatureFlags');