diff --git a/.eslintrc.js b/.eslintrc.js index 30432c21a5dd..c91ba7e6e7fc 100644 --- a/.eslintrc.js +++ b/.eslintrc.js @@ -142,6 +142,8 @@ module.exports = { ], globals: { + SharedArrayBuffer: true, + spyOnDev: true, spyOnDevAndProd: true, spyOnProd: true, diff --git a/packages/react-reconciler/src/__tests__/ReactIncrementalPerf-test.internal.js b/packages/react-reconciler/src/__tests__/ReactIncrementalPerf-test.internal.js index 0bb9c35df61c..2474c58cfa4e 100644 --- a/packages/react-reconciler/src/__tests__/ReactIncrementalPerf-test.internal.js +++ b/packages/react-reconciler/src/__tests__/ReactIncrementalPerf-test.internal.js @@ -136,6 +136,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/npm/umd/scheduler.development.js b/packages/scheduler/npm/umd/scheduler.development.js index c3e461e8720d..91d7a652fe5b 100644 --- a/packages/scheduler/npm/umd/scheduler.development.js +++ b/packages/scheduler/npm/umd/scheduler.development.js @@ -144,5 +144,9 @@ return global.React.__SECRET_INTERNALS_DO_NOT_USE_OR_YOU_WILL_BE_FIRED .Scheduler.unstable_UserBlockingPriority; }, + get unstable_Profiling() { + return global.React.__SECRET_INTERNALS_DO_NOT_USE_OR_YOU_WILL_BE_FIRED + .Scheduler.unstable_Profiling; + }, }); }); diff --git a/packages/scheduler/npm/umd/scheduler.production.min.js b/packages/scheduler/npm/umd/scheduler.production.min.js index 8daa4d998171..de979ba0e26d 100644 --- a/packages/scheduler/npm/umd/scheduler.production.min.js +++ b/packages/scheduler/npm/umd/scheduler.production.min.js @@ -138,5 +138,9 @@ return global.React.__SECRET_INTERNALS_DO_NOT_USE_OR_YOU_WILL_BE_FIRED .Scheduler.unstable_UserBlockingPriority; }, + get unstable_Profiling() { + return global.React.__SECRET_INTERNALS_DO_NOT_USE_OR_YOU_WILL_BE_FIRED + .Scheduler.unstable_Profiling; + }, }); }); diff --git a/packages/scheduler/npm/umd/scheduler.profiling.min.js b/packages/scheduler/npm/umd/scheduler.profiling.min.js index 8daa4d998171..de979ba0e26d 100644 --- a/packages/scheduler/npm/umd/scheduler.profiling.min.js +++ b/packages/scheduler/npm/umd/scheduler.profiling.min.js @@ -138,5 +138,9 @@ return global.React.__SECRET_INTERNALS_DO_NOT_USE_OR_YOU_WILL_BE_FIRED .Scheduler.unstable_UserBlockingPriority; }, + get unstable_Profiling() { + return global.React.__SECRET_INTERNALS_DO_NOT_USE_OR_YOU_WILL_BE_FIRED + .Scheduler.unstable_Profiling; + }, }); }); diff --git a/packages/scheduler/src/Scheduler.js b/packages/scheduler/src/Scheduler.js index 05301a03053b..4b36cb7dd6a3 100644 --- a/packages/scheduler/src/Scheduler.js +++ b/packages/scheduler/src/Scheduler.js @@ -8,7 +8,10 @@ /* eslint-disable no-var */ -import {enableSchedulerDebugging} from './SchedulerFeatureFlags'; +import { + enableSchedulerDebugging, + enableProfiling, +} from './SchedulerFeatureFlags'; import { requestHostCallback, requestHostTimeout, @@ -21,11 +24,26 @@ import { import {push, pop, peek} from './SchedulerMinHeap'; // 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 { + sharedProfilingBuffer, + markTaskRun, + markTaskYield, + markTaskCompleted, + markTaskCanceled, + markTaskErrored, + markSchedulerSuspended, + markSchedulerUnsuspended, + markTaskStart, + stopLoggingProfilingEvents, + startLoggingProfilingEvents, +} from './SchedulerProfiling'; // Max 31 bit integer. The max integer size in V8 for 32-bit systems. // Math.pow(2, 30) - 1 @@ -46,7 +64,7 @@ var taskQueue = []; var timerQueue = []; // Incrementing id counter. Used to maintain insertion order. -var taskIdCounter = 0; +var taskIdCounter = 1; // Pausing the scheduler is useful for debugging. var isSchedulerPaused = false; @@ -60,15 +78,6 @@ var isPerformingWork = false; var isHostCallbackScheduled = false; var isHostTimeoutScheduled = false; -function flushTask(task, callback, currentTime) { - currentPriorityLevel = task.priorityLevel; - var didUserCallbackTimeout = task.expirationTime <= currentTime; - var continuationCallback = callback(didUserCallbackTimeout); - return typeof continuationCallback === 'function' - ? continuationCallback - : null; -} - function advanceTimers(currentTime) { // Check for tasks that are no longer delayed and add them to the queue. let timer = peek(timerQueue); @@ -81,6 +90,10 @@ function advanceTimers(currentTime) { pop(timerQueue); timer.sortIndex = timer.expirationTime; push(taskQueue, timer); + if (enableProfiling) { + markTaskStart(timer); + timer.isQueued = true; + } } else { // Remaining timers are pending. return; @@ -107,6 +120,10 @@ function handleTimeout(currentTime) { } function flushWork(hasTimeRemaining, initialTime) { + if (enableProfiling) { + markSchedulerUnsuspended(initialTime); + } + // We'll need a host callback the next time work is scheduled. isHostCallbackScheduled = false; if (isHostTimeoutScheduled) { @@ -118,52 +135,82 @@ function flushWork(hasTimeRemaining, initialTime) { isPerformingWork = true; const previousPriorityLevel = currentPriorityLevel; try { - let currentTime = initialTime; - advanceTimers(currentTime); - currentTask = peek(taskQueue); - while ( - currentTask !== null && - !(enableSchedulerDebugging && isSchedulerPaused) - ) { - if ( - currentTask.expirationTime > currentTime && - (!hasTimeRemaining || shouldYieldToHost()) - ) { - // This currentTask hasn't expired, and we've reached the deadline. - break; - } - const callback = currentTask.callback; - if (callback !== null) { - currentTask.callback = null; - const continuation = flushTask(currentTask, callback, currentTime); - if (continuation !== null) { - currentTask.callback = continuation; - } else { - if (currentTask === peek(taskQueue)) { - pop(taskQueue); - } + if (enableProfiling) { + try { + return workLoop(hasTimeRemaining, initialTime); + } catch (error) { + if (currentTask !== null) { + const currentTime = getCurrentTime(); + markTaskErrored(currentTask, currentTime); + currentTask.isQueued = false; } - currentTime = getCurrentTime(); - advanceTimers(currentTime); - } else { - pop(taskQueue); + throw error; } - currentTask = peek(taskQueue); - } - // Return whether there's additional work - if (currentTask !== null) { - return true; } else { - let firstTimer = peek(timerQueue); - if (firstTimer !== null) { - requestHostTimeout(handleTimeout, firstTimer.startTime - currentTime); - } - return false; + // No catch in prod codepath. + return workLoop(hasTimeRemaining, initialTime); } } finally { currentTask = null; currentPriorityLevel = previousPriorityLevel; isPerformingWork = false; + if (enableProfiling) { + const currentTime = getCurrentTime(); + markSchedulerSuspended(currentTime); + } + } +} + +function workLoop(hasTimeRemaining, initialTime) { + let currentTime = initialTime; + advanceTimers(currentTime); + currentTask = peek(taskQueue); + while ( + currentTask !== null && + !(enableSchedulerDebugging && isSchedulerPaused) + ) { + if ( + currentTask.expirationTime > currentTime && + (!hasTimeRemaining || shouldYieldToHost()) + ) { + // This currentTask hasn't expired, and we've reached the deadline. + break; + } + const callback = currentTask.callback; + if (callback !== null) { + currentTask.callback = null; + currentPriorityLevel = currentTask.priorityLevel; + const didUserCallbackTimeout = currentTask.expirationTime <= currentTime; + markTaskRun(currentTask, currentTime); + const continuationCallback = callback(didUserCallbackTimeout); + currentTime = getCurrentTime(); + if (typeof continuationCallback === 'function') { + currentTask.callback = continuationCallback; + markTaskYield(currentTask, currentTime); + } else { + if (enableProfiling) { + markTaskCompleted(currentTask, currentTime); + currentTask.isQueued = false; + } + if (currentTask === peek(taskQueue)) { + pop(taskQueue); + } + } + advanceTimers(currentTime); + } else { + pop(taskQueue); + } + currentTask = peek(taskQueue); + } + // Return whether there's additional work + if (currentTask !== null) { + return true; + } else { + let firstTimer = peek(timerQueue); + if (firstTimer !== null) { + requestHostTimeout(handleTimeout, firstTimer.startTime - currentTime); + } + return false; } } @@ -276,6 +323,9 @@ function unstable_scheduleCallback(priorityLevel, callback, options) { expirationTime, sortIndex: -1, }; + if (enableProfiling) { + newTask.isQueued = false; + } if (startTime > currentTime) { // This is a delayed task. @@ -295,6 +345,10 @@ function unstable_scheduleCallback(priorityLevel, callback, options) { } else { newTask.sortIndex = expirationTime; push(taskQueue, newTask); + if (enableProfiling) { + markTaskStart(newTask, currentTime); + newTask.isQueued = true; + } // Schedule a host callback, if needed. If we're already performing work, // wait until the next time we yield. if (!isHostCallbackScheduled && !isPerformingWork) { @@ -323,9 +377,17 @@ function unstable_getFirstCallbackNode() { } function unstable_cancelCallback(task) { - // Null out the callback to indicate the task has been canceled. (Can't remove - // from the queue because you can't remove arbitrary nodes from an array based - // heap, only the first one.) + if (enableProfiling) { + if (task.isQueued) { + const currentTime = getCurrentTime(); + markTaskCanceled(task, currentTime); + task.isQueued = false; + } + } + + // Null out the callback to indicate the task has been canceled. (Can't + // remove from the queue because you can't remove arbitrary nodes from an + // array based heap, only the first one.) task.callback = null; } @@ -370,3 +432,11 @@ export { getCurrentTime as unstable_now, forceFrameRate as unstable_forceFrameRate, }; + +export const unstable_Profiling = enableProfiling + ? { + startLoggingProfilingEvents, + stopLoggingProfilingEvents, + sharedProfilingBuffer, + } + : null; diff --git a/packages/scheduler/src/SchedulerFeatureFlags.js b/packages/scheduler/src/SchedulerFeatureFlags.js index 60b62662cbf8..98cf4bad14d7 100644 --- a/packages/scheduler/src/SchedulerFeatureFlags.js +++ b/packages/scheduler/src/SchedulerFeatureFlags.js @@ -11,3 +11,4 @@ export const enableIsInputPending = false; export const requestIdleCallbackBeforeFirstFrame = false; export const requestTimerEventBeforeFirstFrame = false; export const enableMessageLoopImplementation = false; +export const enableProfiling = __PROFILE__; diff --git a/packages/scheduler/src/SchedulerPriorities.js b/packages/scheduler/src/SchedulerPriorities.js new file mode 100644 index 000000000000..1d46ae0e48cd --- /dev/null +++ b/packages/scheduler/src/SchedulerPriorities.js @@ -0,0 +1,18 @@ +/** + * 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 = 0 | 1 | 2 | 3 | 4 | 5; + +// TODO: Use symbols? +export const NoPriority = 0; +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 000000000000..aaf4cbeef76b --- /dev/null +++ b/packages/scheduler/src/SchedulerProfiling.js @@ -0,0 +1,203 @@ +/** + * 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} from './SchedulerFeatureFlags'; + +import {NoPriority} from './SchedulerPriorities'; + +let runIdCounter: number = 0; +let mainThreadIdCounter: number = 0; + +const profilingStateSize = 4; +export const sharedProfilingBuffer = enableProfiling + ? // $FlowFixMe Flow doesn't know about SharedArrayBuffer + typeof SharedArrayBuffer === 'function' + ? new SharedArrayBuffer(profilingStateSize * Int32Array.BYTES_PER_ELEMENT) + : // $FlowFixMe Flow doesn't know about ArrayBuffer + typeof ArrayBuffer === 'function' + ? new ArrayBuffer(profilingStateSize * Int32Array.BYTES_PER_ELEMENT) + : null // Don't crash the init path on IE9 + : null; + +const profilingState = + enableProfiling && sharedProfilingBuffer !== null + ? new Int32Array(sharedProfilingBuffer) + : []; // We can't read this but it helps save bytes for null checks + +const PRIORITY = 0; +const CURRENT_TASK_ID = 1; +const CURRENT_RUN_ID = 2; +const QUEUE_SIZE = 3; + +if (enableProfiling) { + profilingState[PRIORITY] = NoPriority; + // This is maintained with a counter, because the size of the priority queue + // array might include canceled tasks. + profilingState[QUEUE_SIZE] = 0; + profilingState[CURRENT_TASK_ID] = 0; +} + +const INITIAL_EVENT_LOG_SIZE = 1000; + +let eventLogSize = 0; +let eventLogBuffer = null; +let eventLog = null; +let eventLogIndex = 0; + +const TaskStartEvent = 1; +const TaskCompleteEvent = 2; +const TaskErrorEvent = 3; +const TaskCancelEvent = 4; +const TaskRunEvent = 5; +const TaskYieldEvent = 6; +const SchedulerSuspendEvent = 7; +const SchedulerResumeEvent = 8; + +function logEvent(entries) { + if (eventLog !== null) { + const offset = eventLogIndex; + eventLogIndex += entries.length; + if (eventLogIndex + 1 > eventLogSize) { + eventLogSize = eventLogIndex + 1; + const newEventLog = new Int32Array( + eventLogSize * Int32Array.BYTES_PER_ELEMENT, + ); + newEventLog.set(eventLog); + eventLogBuffer = newEventLog.buffer; + eventLog = newEventLog; + } + eventLog.set(entries, offset); + } +} + +export function startLoggingProfilingEvents(): void { + eventLogSize = INITIAL_EVENT_LOG_SIZE; + eventLogBuffer = new ArrayBuffer(eventLogSize * Int32Array.BYTES_PER_ELEMENT); + eventLog = new Int32Array(eventLogBuffer); + eventLogIndex = 0; +} + +export function stopLoggingProfilingEvents(): ArrayBuffer | null { + const buffer = eventLogBuffer; + eventLogBuffer = eventLog = null; + return buffer; +} + +export function markTaskStart( + task: {id: number, priorityLevel: PriorityLevel}, + time: number, +) { + if (enableProfiling) { + profilingState[QUEUE_SIZE]++; + + if (eventLog !== null) { + logEvent([TaskStartEvent, time, task.id, task.priorityLevel]); + } + } +} + +export function markTaskCompleted( + task: { + id: number, + priorityLevel: PriorityLevel, + }, + time: number, +) { + if (enableProfiling) { + profilingState[PRIORITY] = NoPriority; + profilingState[CURRENT_TASK_ID] = 0; + profilingState[QUEUE_SIZE]--; + + if (eventLog !== null) { + logEvent([TaskCompleteEvent, time, task.id]); + } + } +} + +export function markTaskCanceled( + task: { + id: number, + priorityLevel: PriorityLevel, + }, + time: number, +) { + if (enableProfiling) { + profilingState[QUEUE_SIZE]--; + + if (eventLog !== null) { + logEvent([TaskCancelEvent, time, task.id]); + } + } +} + +export function markTaskErrored( + task: { + id: number, + priorityLevel: PriorityLevel, + }, + time: number, +) { + if (enableProfiling) { + profilingState[PRIORITY] = NoPriority; + profilingState[CURRENT_TASK_ID] = 0; + profilingState[QUEUE_SIZE]--; + + if (eventLog !== null) { + logEvent([TaskErrorEvent, time, task.id]); + } + } +} + +export function markTaskRun( + task: {id: number, priorityLevel: PriorityLevel}, + time: number, +) { + if (enableProfiling) { + runIdCounter++; + + profilingState[PRIORITY] = task.priorityLevel; + profilingState[CURRENT_TASK_ID] = task.id; + profilingState[CURRENT_RUN_ID] = runIdCounter; + + if (eventLog !== null) { + logEvent([TaskRunEvent, time, task.id, runIdCounter]); + } + } +} + +export function markTaskYield(task: {id: number}, time: number) { + if (enableProfiling) { + profilingState[PRIORITY] = NoPriority; + profilingState[CURRENT_TASK_ID] = 0; + profilingState[CURRENT_RUN_ID] = 0; + + if (eventLog !== null) { + logEvent([TaskYieldEvent, time, task.id, runIdCounter]); + } + } +} + +export function markSchedulerSuspended(time: number) { + if (enableProfiling) { + mainThreadIdCounter++; + + if (eventLog !== null) { + logEvent([SchedulerSuspendEvent, time, mainThreadIdCounter]); + } + } +} + +export function markSchedulerUnsuspended(time: number) { + if (enableProfiling) { + if (eventLog !== null) { + logEvent([SchedulerResumeEvent, time, mainThreadIdCounter]); + } + } +} diff --git a/packages/scheduler/src/__tests__/SchedulerDOM-test.js b/packages/scheduler/src/__tests__/SchedulerDOM-test.js index 3a66657d17ee..dacfb53e9eb7 100644 --- a/packages/scheduler/src/__tests__/SchedulerDOM-test.js +++ b/packages/scheduler/src/__tests__/SchedulerDOM-test.js @@ -59,11 +59,15 @@ describe('SchedulerDOM', () => { runPostMessageCallbacks(config); } - let frameSize = 33; - let startOfLatestFrame = 0; - let currentTime = 0; + let frameSize; + let startOfLatestFrame; + let currentTime; beforeEach(() => { + frameSize = 33; + startOfLatestFrame = 0; + currentTime = 0; + delete global.performance; global.requestAnimationFrame = function(cb) { return rAFCallbacks.push(() => { diff --git a/packages/scheduler/src/__tests__/SchedulerProfiling-test.js b/packages/scheduler/src/__tests__/SchedulerProfiling-test.js new file mode 100644 index 000000000000..fdbadfb77c48 --- /dev/null +++ b/packages/scheduler/src/__tests__/SchedulerProfiling-test.js @@ -0,0 +1,508 @@ +/** + * 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 sharedProfilingArray; +// let runWithPriority; +let ImmediatePriority; +let UserBlockingPriority; +let NormalPriority; +let LowPriority; +let IdlePriority; +let scheduleCallback; +let cancelCallback; +// let wrapCallback; +// let getCurrentPriorityLevel; +// let shouldYield; + +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', () => { + if (!__PROFILE__) { + // The tests in this suite only apply when profiling is on + it('profiling APIs are not available', () => { + Scheduler = require('scheduler'); + expect(Scheduler.unstable_Profiling).toBe(null); + }); + return; + } + + beforeEach(() => { + jest.resetModules(); + jest.mock('scheduler', () => require('scheduler/unstable_mock')); + Scheduler = require('scheduler'); + + sharedProfilingArray = new Int32Array( + Scheduler.unstable_Profiling.sharedProfilingBuffer, + ); + + // 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; + }); + + const PRIORITY = 0; + const CURRENT_TASK_ID = 1; + const CURRENT_RUN_ID = 2; + const QUEUE_SIZE = 3; + + afterEach(() => { + if (sharedProfilingArray[QUEUE_SIZE] !== 0) { + throw Error( + 'Test exited, but the shared profiling buffer indicates that a task ' + + 'is still running', + ); + } + }); + + const TaskStartEvent = 1; + const TaskCompleteEvent = 2; + const TaskErrorEvent = 3; + const TaskCancelEvent = 4; + const TaskRunEvent = 5; + const TaskYieldEvent = 6; + const SchedulerSuspendEvent = 7; + const SchedulerResumeEvent = 8; + + function stopProfilingAndPrintFlamegraph() { + const eventLog = new Int32Array( + Scheduler.unstable_Profiling.stopLoggingProfilingEvents(), + ); + + const tasks = new Map(); + const mainThreadRuns = []; + + let isSuspended = true; + let i = 0; + processLog: while (i < eventLog.length) { + const instruction = eventLog[i]; + const time = eventLog[i + 1]; + switch (instruction) { + case 0: { + break processLog; + } + case TaskStartEvent: { + const taskId = eventLog[i + 2]; + const priorityLevel = eventLog[i + 3]; + const task = { + id: taskId, + priorityLevel, + label: null, + start: time, + end: -1, + exitStatus: null, + runs: [], + }; + tasks.set(taskId, task); + i += 4; + break; + } + case TaskCompleteEvent: { + if (isSuspended) { + throw Error('Task cannot Complete outside the work loop.'); + } + const taskId = eventLog[i + 2]; + const task = tasks.get(taskId); + if (task === undefined) { + throw Error('Task does not exist.'); + } + task.end = time; + task.exitStatus = 'completed'; + i += 3; + break; + } + case TaskErrorEvent: { + if (isSuspended) { + throw Error('Task cannot Error outside the work loop.'); + } + const taskId = eventLog[i + 2]; + const task = tasks.get(taskId); + if (task === undefined) { + throw Error('Task does not exist.'); + } + task.end = time; + task.exitStatus = 'errored'; + i += 3; + break; + } + case TaskCancelEvent: { + const taskId = eventLog[i + 2]; + const task = tasks.get(taskId); + if (task === undefined) { + throw Error('Task does not exist.'); + } + task.end = time; + task.exitStatus = 'canceled'; + i += 3; + break; + } + case TaskRunEvent: + case TaskYieldEvent: { + if (isSuspended) { + throw Error('Task cannot Run or Yield outside the work loop.'); + } + const taskId = eventLog[i + 2]; + const task = tasks.get(taskId); + if (task === undefined) { + throw Error('Task does not exist.'); + } + task.runs.push(time); + i += 4; + break; + } + case SchedulerSuspendEvent: { + if (isSuspended) { + throw Error('Scheduler cannot Suspend outside the work loop.'); + } + isSuspended = true; + mainThreadRuns.push(time); + i += 3; + break; + } + case SchedulerResumeEvent: { + if (!isSuspended) { + throw Error('Scheduler cannot Resume inside the work loop.'); + } + isSuspended = false; + mainThreadRuns.push(time); + i += 3; + break; + } + default: { + throw Error('Unknown instruction type: ' + instruction); + } + } + } + + // 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 = true; + 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 ${task.id} [${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; + } + + function getProfilingInfo() { + const queueSize = sharedProfilingArray[QUEUE_SIZE]; + if (queueSize === 0) { + return 'Empty Queue'; + } + const priorityLevel = sharedProfilingArray[PRIORITY]; + if (priorityLevel === 0) { + return 'Suspended, Queue Size: ' + queueSize; + } + return ( + `Task: ${sharedProfilingArray[CURRENT_TASK_ID]}, ` + + `Run: ${sharedProfilingArray[CURRENT_RUN_ID]}, ` + + `Priority: ${priorityLevelToString(priorityLevel)}, ` + + `Queue Size: ${sharedProfilingArray[QUEUE_SIZE]}` + ); + } + + it('creates a basic flamegraph', () => { + Scheduler.unstable_Profiling.startLoggingProfilingEvents(); + + Scheduler.unstable_advanceTime(100); + scheduleCallback( + NormalPriority, + () => { + Scheduler.unstable_advanceTime(300); + Scheduler.unstable_yieldValue(getProfilingInfo()); + scheduleCallback( + UserBlockingPriority, + () => { + Scheduler.unstable_yieldValue(getProfilingInfo()); + Scheduler.unstable_advanceTime(300); + }, + {label: 'Bar'}, + ); + Scheduler.unstable_advanceTime(100); + Scheduler.unstable_yieldValue('Yield'); + return () => { + Scheduler.unstable_yieldValue(getProfilingInfo()); + Scheduler.unstable_advanceTime(300); + }; + }, + {label: 'Foo'}, + ); + expect(Scheduler).toFlushAndYieldThrough([ + 'Task: 1, Run: 1, Priority: Normal, Queue Size: 1', + 'Yield', + ]); + Scheduler.unstable_advanceTime(100); + expect(Scheduler).toFlushAndYield([ + 'Task: 2, Run: 2, Priority: User-blocking, Queue Size: 2', + 'Task: 1, Run: 3, Priority: Normal, Queue Size: 1', + ]); + + expect(getProfilingInfo()).toEqual('Empty Queue'); + + expect(stopProfilingAndPrintFlamegraph()).toEqual( + ` +!!! Main thread │██░░░░░░░░██░░░░░░░░░░░░ +Task 2 [User-blocking] │ ░░░░██████ +Task 1 [Normal] │ ████████░░░░░░░░██████ +`, + ); + }); + + it('marks when a task is canceled', () => { + Scheduler.unstable_Profiling.startLoggingProfilingEvents(); + + const task = scheduleCallback(NormalPriority, () => { + Scheduler.unstable_yieldValue(getProfilingInfo()); + Scheduler.unstable_advanceTime(300); + Scheduler.unstable_yieldValue('Yield'); + return () => { + Scheduler.unstable_yieldValue('Continuation'); + Scheduler.unstable_advanceTime(200); + }; + }); + + expect(Scheduler).toFlushAndYieldThrough([ + 'Task: 1, Run: 1, Priority: Normal, Queue Size: 1', + 'Yield', + ]); + Scheduler.unstable_advanceTime(100); + + cancelCallback(task); + + Scheduler.unstable_advanceTime(1000); + expect(Scheduler).toFlushWithoutYielding(); + expect(stopProfilingAndPrintFlamegraph()).toEqual( + ` +!!! Main thread │░░░░░░██████████████████████ +Task 1 [Normal] │██████░░🡐 canceled +`, + ); + }); + + it('marks when a task errors', () => { + Scheduler.unstable_Profiling.startLoggingProfilingEvents(); + + scheduleCallback(NormalPriority, () => { + Scheduler.unstable_advanceTime(300); + throw Error('Oops'); + }); + + expect(Scheduler).toFlushAndThrow('Oops'); + Scheduler.unstable_advanceTime(100); + + Scheduler.unstable_advanceTime(1000); + expect(Scheduler).toFlushWithoutYielding(); + expect(stopProfilingAndPrintFlamegraph()).toEqual( + ` +!!! Main thread │░░░░░░██████████████████████ +Task 1 [Normal] │██████🡐 errored +`, + ); + }); + + it('marks when multiple tasks are canceled', () => { + Scheduler.unstable_Profiling.startLoggingProfilingEvents(); + + const task1 = scheduleCallback(NormalPriority, () => { + Scheduler.unstable_yieldValue(getProfilingInfo()); + Scheduler.unstable_advanceTime(300); + Scheduler.unstable_yieldValue('Yield'); + return () => { + Scheduler.unstable_yieldValue('Continuation'); + Scheduler.unstable_advanceTime(200); + }; + }); + const task2 = scheduleCallback(NormalPriority, () => { + Scheduler.unstable_yieldValue(getProfilingInfo()); + Scheduler.unstable_advanceTime(300); + Scheduler.unstable_yieldValue('Yield'); + return () => { + Scheduler.unstable_yieldValue('Continuation'); + Scheduler.unstable_advanceTime(200); + }; + }); + + expect(Scheduler).toFlushAndYieldThrough([ + 'Task: 1, Run: 1, Priority: Normal, Queue Size: 2', + 'Yield', + ]); + Scheduler.unstable_advanceTime(100); + + cancelCallback(task1); + cancelCallback(task2); + + // 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(stopProfilingAndPrintFlamegraph()).toEqual( + ` +!!! Main thread │░░░░░░██████████████████████ +Task 1 [Normal] │██████░░🡐 canceled +Task 2 [Normal] │░░░░░░░░🡐 canceled +`, + ); + }); + + it('handles cancelling a task that already finished', () => { + Scheduler.unstable_Profiling.startLoggingProfilingEvents(); + + const task = scheduleCallback(NormalPriority, () => { + Scheduler.unstable_yieldValue('A'); + Scheduler.unstable_advanceTime(1000); + }); + expect(Scheduler).toFlushAndYield(['A']); + cancelCallback(task); + expect(stopProfilingAndPrintFlamegraph()).toEqual( + ` +!!! Main thread │░░░░░░░░░░░░░░░░░░░░ +Task 1 [Normal] │████████████████████ +`, + ); + }); + + it('handles cancelling a task multiple times', () => { + Scheduler.unstable_Profiling.startLoggingProfilingEvents(); + + 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(stopProfilingAndPrintFlamegraph()).toEqual( + ` +!!! Main thread │████████████░░░░░░░░░░░░░░░░░░░░ +Task 1 [Normal] │░░░░░░░░░░░░████████████████████ +Task 2 [Normal] │ ░░░░░░░░🡐 canceled +`, + ); + }); + + it('handles cancelling a delayed task', () => { + Scheduler.unstable_Profiling.startLoggingProfilingEvents(); + const task = scheduleCallback( + NormalPriority, + () => Scheduler.unstable_yieldValue('A'), + {delay: 1000}, + ); + cancelCallback(task); + expect(Scheduler).toFlushWithoutYielding(); + expect(stopProfilingAndPrintFlamegraph()).toEqual( + ` +!!! Main thread │ +`, + ); + }); + + it('resizes event log buffer if there are many events', () => { + const tasks = []; + for (let i = 0; i < 5000; i++) { + tasks.push(scheduleCallback(NormalPriority, () => {})); + } + expect(getProfilingInfo()).toEqual('Suspended, Queue Size: 5000'); + tasks.forEach(task => cancelCallback(task)); + expect(getProfilingInfo()).toEqual('Empty Queue'); + }); +}); diff --git a/packages/scheduler/src/forks/SchedulerFeatureFlags.www.js b/packages/scheduler/src/forks/SchedulerFeatureFlags.www.js index 06abe7786b1c..360be98e603f 100644 --- a/packages/scheduler/src/forks/SchedulerFeatureFlags.www.js +++ b/packages/scheduler/src/forks/SchedulerFeatureFlags.www.js @@ -13,3 +13,5 @@ export const { requestTimerEventBeforeFirstFrame, enableMessageLoopImplementation, } = require('SchedulerFeatureFlags'); + +export const enableProfiling = __PROFILE__; diff --git a/packages/scheduler/src/forks/SchedulerHostConfig.default.js b/packages/scheduler/src/forks/SchedulerHostConfig.default.js index c11fca6cd029..37a38027c7b5 100644 --- a/packages/scheduler/src/forks/SchedulerHostConfig.default.js +++ b/packages/scheduler/src/forks/SchedulerHostConfig.default.js @@ -53,8 +53,9 @@ if ( } } }; + const initialTime = Date.now(); getCurrentTime = function() { - return Date.now(); + return Date.now() - initialTime; }; requestHostCallback = function(cb) { if (_callback !== null) { @@ -111,10 +112,15 @@ if ( typeof requestIdleCallback === 'function' && typeof cancelIdleCallback === 'function'; - getCurrentTime = - typeof performance === 'object' && typeof performance.now === 'function' - ? () => performance.now() - : () => Date.now(); + if ( + typeof performance === 'object' && + typeof performance.now === 'function' + ) { + getCurrentTime = () => performance.now(); + } else { + const initialTime = Date.now(); + getCurrentTime = () => Date.now() - initialTime; + } let isRAFLoopRunning = false; let isMessageLoopRunning = false; diff --git a/scripts/rollup/bundles.js b/scripts/rollup/bundles.js index fb36d65dde45..0c9c659f6ee2 100644 --- a/scripts/rollup/bundles.js +++ b/scripts/rollup/bundles.js @@ -411,7 +411,13 @@ const bundles = [ /******* React Scheduler (experimental) *******/ { - bundleTypes: [NODE_DEV, NODE_PROD, FB_WWW_DEV, FB_WWW_PROD], + bundleTypes: [ + NODE_DEV, + NODE_PROD, + FB_WWW_DEV, + FB_WWW_PROD, + FB_WWW_PROFILING, + ], moduleType: ISOMORPHIC, entry: 'scheduler', global: 'Scheduler', diff --git a/scripts/rollup/validate/eslintrc.cjs.js b/scripts/rollup/validate/eslintrc.cjs.js index 202d3bb22b64..2347fbb6cfe8 100644 --- a/scripts/rollup/validate/eslintrc.cjs.js +++ b/scripts/rollup/validate/eslintrc.cjs.js @@ -21,6 +21,11 @@ module.exports = { process: true, setImmediate: true, Buffer: true, + + // Scheduler profiling + SharedArrayBuffer: true, + Int32Array: true, + ArrayBuffer: true, }, parserOptions: { ecmaVersion: 5, diff --git a/scripts/rollup/validate/eslintrc.fb.js b/scripts/rollup/validate/eslintrc.fb.js index 346529e389a5..a32b7e38f0a3 100644 --- a/scripts/rollup/validate/eslintrc.fb.js +++ b/scripts/rollup/validate/eslintrc.fb.js @@ -22,6 +22,11 @@ module.exports = { // Node.js Server Rendering setImmediate: true, Buffer: true, + + // Scheduler profiling + SharedArrayBuffer: true, + Int32Array: true, + ArrayBuffer: true, }, parserOptions: { ecmaVersion: 5, diff --git a/scripts/rollup/validate/eslintrc.rn.js b/scripts/rollup/validate/eslintrc.rn.js index 030aed7fcd25..f211d9573f42 100644 --- a/scripts/rollup/validate/eslintrc.rn.js +++ b/scripts/rollup/validate/eslintrc.rn.js @@ -21,6 +21,11 @@ module.exports = { // Fabric. See https://github.com/facebook/react/pull/15490 // for more information nativeFabricUIManager: true, + + // Scheduler profiling + SharedArrayBuffer: true, + Int32Array: true, + ArrayBuffer: true, }, parserOptions: { ecmaVersion: 5, diff --git a/scripts/rollup/validate/eslintrc.umd.js b/scripts/rollup/validate/eslintrc.umd.js index a949525b6c28..5b96526bba8e 100644 --- a/scripts/rollup/validate/eslintrc.umd.js +++ b/scripts/rollup/validate/eslintrc.umd.js @@ -24,6 +24,11 @@ module.exports = { define: true, require: true, global: true, + + // Scheduler profiling + SharedArrayBuffer: true, + Int32Array: true, + ArrayBuffer: true, }, parserOptions: { ecmaVersion: 5,