From 0f6e3cd61cf4a5a1491bb3c92780936aebc2a146 Mon Sep 17 00:00:00 2001 From: Dan Abramov Date: Thu, 22 Aug 2019 21:58:12 +0100 Subject: [PATCH] [Scheduler] Profiler Features (second try) (#16542) * Revert "Revert "[Scheduler] Profiling features (#16145)" (#16392)" This reverts commit 4ba1412305be3c77b625a70e3c0b9a8638626bd0. * Fix copy paste mistake * Remove init path dependency on ArrayBuffer * Add a regression test for cancelling multiple tasks * Prevent deopt from adding isQueued later * Remove pop() calls that were added for profiling * Verify that Suspend/Unsuspend events match up in tests This currently breaks tests. * Treat Suspend and Resume as exiting and entering work loop Their definitions used to be more fuzzy. For example, Suspend didn't always fire on exit, and sometimes fired when we did _not_ exit (such as at task enqueue). I chatted to Boone, and he's saying treating Suspend and Resume as strictly exiting and entering the loop is fine for their use case. * Revert "Prevent deopt from adding isQueued later" This reverts commit 9c30b0b695d81e9c43b296ab93d895e4416ef713. Unnecessary because GCC * Start counter with 1 * Group exports into unstable_Profiling namespace * No catch in PROD codepath * No label TODO * No null checks --- .eslintrc.js | 2 + .../ReactIncrementalPerf-test.internal.js | 1 + .../npm/umd/scheduler.development.js | 4 + .../npm/umd/scheduler.production.min.js | 4 + .../npm/umd/scheduler.profiling.min.js | 4 + packages/scheduler/src/Scheduler.js | 184 +++++-- .../scheduler/src/SchedulerFeatureFlags.js | 1 + packages/scheduler/src/SchedulerPriorities.js | 18 + packages/scheduler/src/SchedulerProfiling.js | 203 +++++++ .../src/__tests__/SchedulerDOM-test.js | 10 +- .../src/__tests__/SchedulerProfiling-test.js | 508 ++++++++++++++++++ .../src/forks/SchedulerFeatureFlags.www.js | 2 + .../src/forks/SchedulerHostConfig.default.js | 16 +- scripts/rollup/bundles.js | 8 +- scripts/rollup/validate/eslintrc.cjs.js | 5 + scripts/rollup/validate/eslintrc.fb.js | 5 + scripts/rollup/validate/eslintrc.rn.js | 5 + scripts/rollup/validate/eslintrc.umd.js | 5 + 18 files changed, 919 insertions(+), 66 deletions(-) create mode 100644 packages/scheduler/src/SchedulerPriorities.js create mode 100644 packages/scheduler/src/SchedulerProfiling.js create mode 100644 packages/scheduler/src/__tests__/SchedulerProfiling-test.js diff --git a/.eslintrc.js b/.eslintrc.js index 30432c21a5dd1..c91ba7e6e7fc4 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 0bb9c35df61c2..2474c58cfa4e2 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 c3e461e8720dd..91d7a652fe5b9 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 8daa4d998171e..de979ba0e26d3 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 8daa4d998171e..de979ba0e26d3 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 05301a03053b8..4b36cb7dd6a38 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 60b62662cbf8b..98cf4bad14d74 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 0000000000000..1d46ae0e48cd7 --- /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 0000000000000..aaf4cbeef76be --- /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 3a66657d17ee2..dacfb53e9eb73 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 0000000000000..fdbadfb77c488 --- /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 06abe7786b1cd..360be98e603f6 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 c11fca6cd029d..37a38027c7b5d 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 fb36d65dde452..0c9c659f6ee2a 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 202d3bb22b64b..2347fbb6cfe8d 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 346529e389a54..a32b7e38f0a37 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 030aed7fcd25e..f211d9573f42e 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 a949525b6c289..5b96526bba8ed 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,