From 161aba9ffe215485645bf89d97b0227650209231 Mon Sep 17 00:00:00 2001 From: Andrew Clark Date: Tue, 16 Jul 2019 19:12:07 -0700 Subject: [PATCH 1/4] [Scheduler] Mark user-timing events Marks when Scheduler starts and stops running a task. Also marks when a task is initially scheduled, and when Scheduler is waiting for a callback, which can't be inferred from a sample-based JavaScript CPU profile alone. The plan is to use the user-timing events to build a Scheduler profiler that shows how the lifetime of tasks interact with each other and with unscheduled main thread work. The test suite works by printing an text representation of a Scheduler flamegraph. --- .../ReactIncrementalPerf-test.internal.js | 1 + packages/scheduler/src/Scheduler.js | 104 ++++- .../scheduler/src/SchedulerFeatureFlags.js | 2 + packages/scheduler/src/SchedulerPriorities.js | 17 + packages/scheduler/src/SchedulerProfiling.js | 134 ++++++ .../SchedulerProfiling-test.internal.js | 398 ++++++++++++++++++ .../src/forks/SchedulerFeatureFlags.www.js | 3 + scripts/rollup/bundles.js | 8 +- 8 files changed, 651 insertions(+), 16 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.internal.js 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 05301a03053b8..1450ba372b477 100644 --- a/packages/scheduler/src/Scheduler.js +++ b/packages/scheduler/src/Scheduler.js @@ -8,10 +8,14 @@ /* eslint-disable no-var */ -import {enableSchedulerDebugging} from './SchedulerFeatureFlags'; import { - requestHostCallback, + enableSchedulerDebugging, + enableProfiling, +} from './SchedulerFeatureFlags'; +import { + requestHostCallback as requestHostCallbackWithoutProfiling, requestHostTimeout, + cancelHostCallback, cancelHostTimeout, shouldYieldToHost, getCurrentTime, @@ -21,11 +25,23 @@ 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 { + 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 @@ -60,13 +76,29 @@ var isPerformingWork = false; var isHostCallbackScheduled = false; var isHostTimeoutScheduled = false; +function requestHostCallbackWithProfiling(cb) { + if (enableProfiling) { + markSchedulerSuspended(); + requestHostCallbackWithoutProfiling(cb); + } +} + +const requestHostCallback = enableProfiling + ? requestHostCallbackWithProfiling + : requestHostCallbackWithoutProfiling; + function flushTask(task, callback, currentTime) { currentPriorityLevel = task.priorityLevel; var didUserCallbackTimeout = task.expirationTime <= currentTime; + markTaskRun(task); var continuationCallback = callback(didUserCallbackTimeout); - return typeof continuationCallback === 'function' - ? continuationCallback - : null; + if (typeof continuationCallback === 'function') { + markTaskYield(task); + return continuationCallback; + } else { + markTaskCompleted(task); + return null; + } } function advanceTimers(currentTime) { @@ -81,6 +113,7 @@ function advanceTimers(currentTime) { pop(timerQueue); timer.sortIndex = timer.expirationTime; push(taskQueue, timer); + markTaskStart(timer); } else { // Remaining timers are pending. return; @@ -107,6 +140,10 @@ function handleTimeout(currentTime) { } function flushWork(hasTimeRemaining, initialTime) { + if (isHostCallbackScheduled) { + markSchedulerUnsuspended(); + } + // We'll need a host callback the next time work is scheduled. isHostCallbackScheduled = false; if (isHostTimeoutScheduled) { @@ -152,6 +189,8 @@ function flushWork(hasTimeRemaining, initialTime) { } // Return whether there's additional work if (currentTask !== null) { + markSchedulerSuspended(); + isHostCallbackScheduled = true; return true; } else { let firstTimer = peek(timerQueue); @@ -160,6 +199,14 @@ function flushWork(hasTimeRemaining, initialTime) { } return false; } + } catch (error) { + if (currentTask !== null) { + markTaskErrored(currentTask); + if (currentTask === peek(taskQueue)) { + pop(taskQueue); + } + } + throw error; } finally { currentTask = null; currentPriorityLevel = previousPriorityLevel; @@ -250,6 +297,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) { @@ -261,6 +309,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; @@ -269,7 +323,7 @@ function unstable_scheduleCallback(priorityLevel, callback, options) { var expirationTime = startTime + timeout; var newTask = { - id: taskIdCounter++, + id: ++taskIdCounter, callback, priorityLevel, startTime, @@ -277,6 +331,12 @@ function unstable_scheduleCallback(priorityLevel, callback, options) { sortIndex: -1, }; + if (enableProfiling) { + if (typeof options === 'object' && options !== null) { + newTask.label = label; + } + } + if (startTime > currentTime) { // This is a delayed task. newTask.sortIndex = startTime; @@ -295,6 +355,7 @@ function unstable_scheduleCallback(priorityLevel, callback, options) { } else { newTask.sortIndex = expirationTime; push(taskQueue, newTask); + markTaskStart(newTask); // Schedule a host callback, if needed. If we're already performing work, // wait until the next time we yield. if (!isHostCallbackScheduled && !isPerformingWork) { @@ -323,10 +384,23 @@ 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.) - task.callback = null; + if (enableProfiling && task.callback !== null) { + markTaskCanceled(task); + } + if (task !== null && task === peek(taskQueue)) { + pop(taskQueue); + if (enableProfiling && !isPerformingWork && taskQueue.length === 0) { + // The queue is now empty. + markSchedulerUnsuspended(); + isHostCallbackScheduled = false; + cancelHostCallback(); + } + } else { + // 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; + } } function unstable_getCurrentPriorityLevel() { diff --git a/packages/scheduler/src/SchedulerFeatureFlags.js b/packages/scheduler/src/SchedulerFeatureFlags.js index 60b62662cbf8b..9611038ce39bd 100644 --- a/packages/scheduler/src/SchedulerFeatureFlags.js +++ b/packages/scheduler/src/SchedulerFeatureFlags.js @@ -11,3 +11,5 @@ export const enableIsInputPending = false; export const requestIdleCallbackBeforeFirstFrame = false; export const requestTimerEventBeforeFirstFrame = false; export const enableMessageLoopImplementation = false; +export const enableProfiling = __PROFILE__; +export const enableUserTimingAPI = false; 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..168a989720ada --- /dev/null +++ b/packages/scheduler/src/SchedulerProfiling.js @@ -0,0 +1,134 @@ +/** + * 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, + enableUserTimingAPI as enableUserTimingAPIFeatureFlag, +} from './SchedulerFeatureFlags'; + +const enableUserTimingAPI = + enableUserTimingAPIFeatureFlag && + 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) { + if (enableUserTimingAPI) { + // 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) { + if (enableUserTimingAPI) { + 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) { + if (enableUserTimingAPI) { + 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) { + if (enableUserTimingAPI) { + 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) { + if (enableUserTimingAPI) { + runIdCounter++; + const runMark = `SchedulerTask-${task.id}-Run-${runIdCounter}`; + performance.mark(runMark); + performance.clearMarks(runMark); + } + } +} + +export function markTaskYield(task: {id: number}) { + if (enableProfiling) { + if (enableUserTimingAPI) { + const yieldMark = `SchedulerTask-${task.id}-Yield-${runIdCounter}`; + performance.mark(yieldMark); + performance.clearMarks(yieldMark); + } + } +} + +export function markSchedulerSuspended() { + if (enableProfiling) { + if (enableUserTimingAPI) { + mainThreadIdCounter++; + const suspendStartMark = + 'SchedulerSuspended-Start-' + mainThreadIdCounter; + performance.mark(suspendStartMark); + performance.clearMarks(suspendStartMark); + } + } +} + +export function markSchedulerUnsuspended() { + if (enableProfiling) { + if (enableUserTimingAPI) { + const suspendedEndMark = 'SchedulerSuspended-End-' + mainThreadIdCounter; + performance.mark(suspendedEndMark); + performance.clearMarks(suspendedEndMark); + } + } +} diff --git a/packages/scheduler/src/__tests__/SchedulerProfiling-test.internal.js b/packages/scheduler/src/__tests__/SchedulerProfiling-test.internal.js new file mode 100644 index 0000000000000..102f4333b9914 --- /dev/null +++ b/packages/scheduler/src/__tests__/SchedulerProfiling-test.internal.js @@ -0,0 +1,398 @@ +/** + * 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(); + + require('scheduler/src/SchedulerFeatureFlags').enableUserTimingAPI = true; + 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 06abe7786b1cd..9ecd6dd749606 100644 --- a/packages/scheduler/src/forks/SchedulerFeatureFlags.www.js +++ b/packages/scheduler/src/forks/SchedulerFeatureFlags.www.js @@ -12,4 +12,7 @@ export const { requestIdleCallbackBeforeFirstFrame, requestTimerEventBeforeFirstFrame, enableMessageLoopImplementation, + enableUserTimingAPI, } = require('SchedulerFeatureFlags'); + +export const enableProfiling = __PROFILE__; diff --git a/scripts/rollup/bundles.js b/scripts/rollup/bundles.js index d1e60de6507c5..9e157b58a5feb 100644 --- a/scripts/rollup/bundles.js +++ b/scripts/rollup/bundles.js @@ -420,7 +420,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', From 72f6bcaf68f3f9b8952c9c1e5ccdba364676fdc4 Mon Sep 17 00:00:00 2001 From: Andrew Clark Date: Tue, 13 Aug 2019 11:02:52 -0700 Subject: [PATCH 2/4] Expose shared array buffer with profiling info Array contains - the priority Scheduler is currently running - the size of the queue - the id of the currently running task --- .eslintrc.js | 2 + .../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 | 30 +++++++-- .../scheduler/src/SchedulerFeatureFlags.js | 1 + packages/scheduler/src/SchedulerPriorities.js | 3 +- packages/scheduler/src/SchedulerProfiling.js | 53 +++++++++++++++- .../SchedulerProfiling-test.internal.js | 61 ++++++++++++++++--- .../src/forks/SchedulerFeatureFlags.www.js | 1 + 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 ++ 14 files changed, 169 insertions(+), 14 deletions(-) diff --git a/.eslintrc.js b/.eslintrc.js index de78bd074902c..87e243938d0b3 100644 --- a/.eslintrc.js +++ b/.eslintrc.js @@ -140,6 +140,8 @@ module.exports = { ], globals: { + SharedArrayBuffer: true, + spyOnDev: true, spyOnDevAndProd: true, spyOnProd: true, diff --git a/packages/scheduler/npm/umd/scheduler.development.js b/packages/scheduler/npm/umd/scheduler.development.js index c3e461e8720dd..41a2412a35de2 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_sharedProfilingBuffer() { + return global.React.__SECRET_INTERNALS_DO_NOT_USE_OR_YOU_WILL_BE_FIRED + .Scheduler.unstable_getFirstCallbackNode; + }, }); }); diff --git a/packages/scheduler/npm/umd/scheduler.production.min.js b/packages/scheduler/npm/umd/scheduler.production.min.js index 8daa4d998171e..6ea8e9df7fe43 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_sharedProfilingBuffer() { + return global.React.__SECRET_INTERNALS_DO_NOT_USE_OR_YOU_WILL_BE_FIRED + .Scheduler.unstable_getFirstCallbackNode; + }, }); }); diff --git a/packages/scheduler/npm/umd/scheduler.profiling.min.js b/packages/scheduler/npm/umd/scheduler.profiling.min.js index 8daa4d998171e..6ea8e9df7fe43 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_sharedProfilingBuffer() { + return global.React.__SECRET_INTERNALS_DO_NOT_USE_OR_YOU_WILL_BE_FIRED + .Scheduler.unstable_getFirstCallbackNode; + }, }); }); diff --git a/packages/scheduler/src/Scheduler.js b/packages/scheduler/src/Scheduler.js index 1450ba372b477..ea4efdf6d0aa1 100644 --- a/packages/scheduler/src/Scheduler.js +++ b/packages/scheduler/src/Scheduler.js @@ -10,6 +10,7 @@ import { enableSchedulerDebugging, + enableSharedProfilingBuffer, enableProfiling, } from './SchedulerFeatureFlags'; import { @@ -33,6 +34,7 @@ import { IdlePriority, } from './SchedulerPriorities'; import { + sharedProfilingBuffer, markTaskRun, markTaskYield, markTaskCompleted, @@ -83,6 +85,10 @@ function requestHostCallbackWithProfiling(cb) { } } +// Expose a shared array buffer that contains profiling information. +export const unstable_sharedProfilingBuffer = + enableProfiling && enableSharedProfilingBuffer ? sharedProfilingBuffer : null; + const requestHostCallback = enableProfiling ? requestHostCallbackWithProfiling : requestHostCallbackWithoutProfiling; @@ -96,7 +102,10 @@ function flushTask(task, callback, currentTime) { markTaskYield(task); return continuationCallback; } else { - markTaskCompleted(task); + if (enableProfiling) { + markTaskCompleted(task); + task.isQueued = false; + } return null; } } @@ -113,7 +122,10 @@ function advanceTimers(currentTime) { pop(timerQueue); timer.sortIndex = timer.expirationTime; push(taskQueue, timer); - markTaskStart(timer); + if (enableProfiling) { + markTaskStart(timer); + timer.isQueued = true; + } } else { // Remaining timers are pending. return; @@ -201,7 +213,10 @@ function flushWork(hasTimeRemaining, initialTime) { } } catch (error) { if (currentTask !== null) { - markTaskErrored(currentTask); + if (enableProfiling) { + markTaskErrored(currentTask); + currentTask.isQueued = false; + } if (currentTask === peek(taskQueue)) { pop(taskQueue); } @@ -332,6 +347,7 @@ function unstable_scheduleCallback(priorityLevel, callback, options) { }; if (enableProfiling) { + newTask.isQueued = false; if (typeof options === 'object' && options !== null) { newTask.label = label; } @@ -355,7 +371,10 @@ function unstable_scheduleCallback(priorityLevel, callback, options) { } else { newTask.sortIndex = expirationTime; push(taskQueue, newTask); - markTaskStart(newTask); + if (enableProfiling) { + markTaskStart(newTask); + 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) { @@ -384,8 +403,9 @@ function unstable_getFirstCallbackNode() { } function unstable_cancelCallback(task) { - if (enableProfiling && task.callback !== null) { + if (enableProfiling && task.isQueued) { markTaskCanceled(task); + task.isQueued = false; } if (task !== null && task === peek(taskQueue)) { pop(taskQueue); diff --git a/packages/scheduler/src/SchedulerFeatureFlags.js b/packages/scheduler/src/SchedulerFeatureFlags.js index 9611038ce39bd..c93c6f012e921 100644 --- a/packages/scheduler/src/SchedulerFeatureFlags.js +++ b/packages/scheduler/src/SchedulerFeatureFlags.js @@ -13,3 +13,4 @@ export const requestTimerEventBeforeFirstFrame = false; export const enableMessageLoopImplementation = false; export const enableProfiling = __PROFILE__; export const enableUserTimingAPI = false; +export const enableSharedProfilingBuffer = false; diff --git a/packages/scheduler/src/SchedulerPriorities.js b/packages/scheduler/src/SchedulerPriorities.js index b7ce82a60cdd3..1d46ae0e48cd7 100644 --- a/packages/scheduler/src/SchedulerPriorities.js +++ b/packages/scheduler/src/SchedulerPriorities.js @@ -7,9 +7,10 @@ * @flow */ -export type PriorityLevel = 1 | 2 | 3 | 4 | 5; +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; diff --git a/packages/scheduler/src/SchedulerProfiling.js b/packages/scheduler/src/SchedulerProfiling.js index 168a989720ada..909e4db0b23f0 100644 --- a/packages/scheduler/src/SchedulerProfiling.js +++ b/packages/scheduler/src/SchedulerProfiling.js @@ -11,8 +11,11 @@ import type {PriorityLevel} from './SchedulerPriorities'; import { enableProfiling, enableUserTimingAPI as enableUserTimingAPIFeatureFlag, + enableSharedProfilingBuffer, } from './SchedulerFeatureFlags'; +import {NoPriority} from './SchedulerPriorities'; + const enableUserTimingAPI = enableUserTimingAPIFeatureFlag && typeof performance !== 'undefined' && @@ -22,8 +25,35 @@ const enableUserTimingAPI = let runIdCounter: number = 0; let mainThreadIdCounter: number = 0; +const length = 3; +const size = Int32Array.BYTES_PER_ELEMENT * length; +export const sharedProfilingBuffer = + // $FlowFixMe Flow doesn't know about SharedArrayBuffer + typeof SharedArrayBuffer === 'function' + ? new SharedArrayBuffer(size) + : // $FlowFixMe Flow doesn't know about ArrayBuffer + new ArrayBuffer(size); +const profilingInfo = enableSharedProfilingBuffer + ? new Int32Array(sharedProfilingBuffer) + : null; + +const PRIORITY = 0; +const CURRENT_TASK_ID = 1; +const QUEUE_SIZE = 2; + +if (enableSharedProfilingBuffer && profilingInfo !== null) { + profilingInfo[PRIORITY] = NoPriority; + // This is maintained with a counter, because the size of the priority queue + // array might include canceled tasks. + profilingInfo[QUEUE_SIZE] = 0; + profilingInfo[CURRENT_TASK_ID] = 0; +} + export function markTaskStart(task: {id: number}) { if (enableProfiling) { + if (enableSharedProfilingBuffer && profilingInfo !== null) { + profilingInfo[QUEUE_SIZE]++; + } if (enableUserTimingAPI) { // Use extra field to track if delayed task starts. const taskStartMark = `SchedulerTask-${task.id}-Start`; @@ -39,6 +69,11 @@ export function markTaskCompleted(task: { label?: string, }) { if (enableProfiling) { + if (enableSharedProfilingBuffer && profilingInfo !== null) { + profilingInfo[PRIORITY] = NoPriority; + profilingInfo[CURRENT_TASK_ID] = 0; + profilingInfo[QUEUE_SIZE]--; + } if (enableUserTimingAPI) { const info = JSON.stringify({ priorityLevel: task.priorityLevel, @@ -58,6 +93,9 @@ export function markTaskCanceled(task: { label?: string, }) { if (enableProfiling) { + if (enableSharedProfilingBuffer && profilingInfo !== null) { + profilingInfo[QUEUE_SIZE]--; + } if (enableUserTimingAPI) { const info = JSON.stringify({ priorityLevel: task.priorityLevel, @@ -77,6 +115,11 @@ export function markTaskErrored(task: { label?: string, }) { if (enableProfiling) { + if (enableSharedProfilingBuffer && profilingInfo !== null) { + profilingInfo[PRIORITY] = NoPriority; + profilingInfo[CURRENT_TASK_ID] = 0; + profilingInfo[QUEUE_SIZE]--; + } if (enableUserTimingAPI) { const info = JSON.stringify({ priorityLevel: task.priorityLevel, @@ -90,8 +133,12 @@ export function markTaskErrored(task: { } } -export function markTaskRun(task: {id: number}) { +export function markTaskRun(task: {id: number, priorityLevel: PriorityLevel}) { if (enableProfiling) { + if (enableSharedProfilingBuffer && profilingInfo !== null) { + profilingInfo[PRIORITY] = task.priorityLevel; + profilingInfo[CURRENT_TASK_ID] = task.id; + } if (enableUserTimingAPI) { runIdCounter++; const runMark = `SchedulerTask-${task.id}-Run-${runIdCounter}`; @@ -103,6 +150,10 @@ export function markTaskRun(task: {id: number}) { export function markTaskYield(task: {id: number}) { if (enableProfiling) { + if (enableSharedProfilingBuffer && profilingInfo !== null) { + profilingInfo[PRIORITY] = NoPriority; + profilingInfo[CURRENT_TASK_ID] = 0; + } if (enableUserTimingAPI) { const yieldMark = `SchedulerTask-${task.id}-Yield-${runIdCounter}`; performance.mark(yieldMark); diff --git a/packages/scheduler/src/__tests__/SchedulerProfiling-test.internal.js b/packages/scheduler/src/__tests__/SchedulerProfiling-test.internal.js index 102f4333b9914..a38200a30b0fe 100644 --- a/packages/scheduler/src/__tests__/SchedulerProfiling-test.internal.js +++ b/packages/scheduler/src/__tests__/SchedulerProfiling-test.internal.js @@ -13,6 +13,7 @@ 'use strict'; let Scheduler; +let sharedProfilingArray; // let runWithPriority; let ImmediatePriority; let UserBlockingPriority; @@ -44,6 +45,12 @@ function priorityLevelToString(priorityLevel) { } describe('Scheduler', () => { + 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; + } + beforeEach(() => { jest.resetModules(); jest.mock('scheduler', () => require('scheduler/unstable_mock')); @@ -51,8 +58,13 @@ describe('Scheduler', () => { performance = global.performance = createUserTimingPolyfill(); require('scheduler/src/SchedulerFeatureFlags').enableUserTimingAPI = true; + require('scheduler/src/SchedulerFeatureFlags').enableSharedProfilingBuffer = true; Scheduler = require('scheduler'); + sharedProfilingArray = new Int32Array( + Scheduler.unstable_sharedProfilingBuffer, + ); + // runWithPriority = Scheduler.unstable_runWithPriority; ImmediatePriority = Scheduler.unstable_ImmediatePriority; UserBlockingPriority = Scheduler.unstable_UserBlockingPriority; @@ -68,6 +80,12 @@ describe('Scheduler', () => { afterEach(() => { performance.assertAllUserTimingsAreCleared(); + if (sharedProfilingArray[2] !== 0) { + throw Error( + 'Test exited, but the shared profiling buffer indicates that a task ' + + 'is still running', + ); + } }); function createUserTimingPolyfill() { @@ -248,10 +266,23 @@ describe('Scheduler', () => { }; } - 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; + const PRIORITY = 0; + const CURRENT_TASK_ID = 1; + const QUEUE_SIZE = 2; + 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 `Current Task: ${ + sharedProfilingArray[QUEUE_SIZE] + }, Priority: ${priorityLevelToString(priorityLevel)}, Queue Size: ${ + sharedProfilingArray[CURRENT_TASK_ID] + }`; } it('creates a basic flamegraph', () => { @@ -260,9 +291,11 @@ describe('Scheduler', () => { NormalPriority, () => { Scheduler.unstable_advanceTime(300); + Scheduler.unstable_yieldValue(getProfilingInfo()); scheduleCallback( UserBlockingPriority, () => { + Scheduler.unstable_yieldValue(getProfilingInfo()); Scheduler.unstable_advanceTime(300); }, {label: 'Bar'}, @@ -270,14 +303,24 @@ describe('Scheduler', () => { Scheduler.unstable_advanceTime(100); Scheduler.unstable_yieldValue('Yield'); return () => { + Scheduler.unstable_yieldValue(getProfilingInfo()); Scheduler.unstable_advanceTime(300); }; }, {label: 'Foo'}, ); - expect(Scheduler).toFlushAndYieldThrough(['Yield']); + expect(Scheduler).toFlushAndYieldThrough([ + 'Current Task: 1, Priority: Normal, Queue Size: 1', + 'Yield', + ]); Scheduler.unstable_advanceTime(100); - expect(Scheduler).toFlushWithoutYielding(); + expect(Scheduler).toFlushAndYield([ + 'Current Task: 2, Priority: User-blocking, Queue Size: 2', + 'Current Task: 1, Priority: Normal, Queue Size: 1', + ]); + + expect(getProfilingInfo()).toEqual('Empty Queue'); + expect(performance.printUserTimings()).toEqual( ` !!! Main thread │ ██ @@ -289,6 +332,7 @@ describe('Scheduler', () => { it('marks when a task is canceled', () => { const task = scheduleCallback(NormalPriority, () => { + Scheduler.unstable_yieldValue(getProfilingInfo()); Scheduler.unstable_advanceTime(300); Scheduler.unstable_yieldValue('Yield'); return () => { @@ -297,7 +341,10 @@ describe('Scheduler', () => { }; }); - expect(Scheduler).toFlushAndYieldThrough(['Yield']); + expect(Scheduler).toFlushAndYieldThrough([ + 'Current Task: 1, Priority: Normal, Queue Size: 1', + 'Yield', + ]); Scheduler.unstable_advanceTime(100); cancelCallback(task); diff --git a/packages/scheduler/src/forks/SchedulerFeatureFlags.www.js b/packages/scheduler/src/forks/SchedulerFeatureFlags.www.js index 9ecd6dd749606..2460a7213681d 100644 --- a/packages/scheduler/src/forks/SchedulerFeatureFlags.www.js +++ b/packages/scheduler/src/forks/SchedulerFeatureFlags.www.js @@ -13,6 +13,7 @@ export const { requestTimerEventBeforeFirstFrame, enableMessageLoopImplementation, enableUserTimingAPI, + enableSharedProfilingBuffer, } = require('SchedulerFeatureFlags'); export const enableProfiling = __PROFILE__; 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, From f5e0622014cbaa7ffe4ee2df496bbcb29a0d84b0 Mon Sep 17 00:00:00 2001 From: Andrew Clark Date: Tue, 13 Aug 2019 17:11:49 -0700 Subject: [PATCH 3/4] Replace user-timing calls with event log Events are written to an array buffer using a custom instruction format. For now, this is only meant to be used during page start up, before the profiler worker has a chance to start up. Once the worker is ready, call `stopLoggingProfilerEvents` to return the log up to that point, then send the array buffer to the worker. Then switch to the sampling based approach. --- .../npm/umd/scheduler.development.js | 16 + .../npm/umd/scheduler.production.min.js | 16 + .../npm/umd/scheduler.profiling.min.js | 16 + packages/scheduler/src/Scheduler.js | 105 ++--- .../scheduler/src/SchedulerFeatureFlags.js | 2 - packages/scheduler/src/SchedulerProfiling.js | 240 ++++++------ .../src/__tests__/SchedulerDOM-test.js | 10 +- ...internal.js => SchedulerProfiling-test.js} | 369 +++++++++--------- .../src/forks/SchedulerFeatureFlags.www.js | 2 - .../src/forks/SchedulerHostConfig.default.js | 16 +- 10 files changed, 440 insertions(+), 352 deletions(-) rename packages/scheduler/src/__tests__/{SchedulerProfiling-test.internal.js => SchedulerProfiling-test.js} (50%) diff --git a/packages/scheduler/npm/umd/scheduler.development.js b/packages/scheduler/npm/umd/scheduler.development.js index 41a2412a35de2..693aff797d2b6 100644 --- a/packages/scheduler/npm/umd/scheduler.development.js +++ b/packages/scheduler/npm/umd/scheduler.development.js @@ -110,6 +110,20 @@ ); } + function unstable_startLoggingProfilingEvents() { + return global.React.__SECRET_INTERNALS_DO_NOT_USE_OR_YOU_WILL_BE_FIRED.Scheduler.unstable_startLoggingProfilingEvents.apply( + this, + arguments + ); + } + + function unstable_stopLoggingProfilingEvents() { + return global.React.__SECRET_INTERNALS_DO_NOT_USE_OR_YOU_WILL_BE_FIRED.Scheduler.unstable_stopLoggingProfilingEvents.apply( + this, + arguments + ); + } + return Object.freeze({ unstable_now: unstable_now, unstable_scheduleCallback: unstable_scheduleCallback, @@ -124,6 +138,8 @@ unstable_pauseExecution: unstable_pauseExecution, unstable_getFirstCallbackNode: unstable_getFirstCallbackNode, unstable_forceFrameRate: unstable_forceFrameRate, + unstable_startLoggingProfilingEvents: unstable_startLoggingProfilingEvents, + unstable_stopLoggingProfilingEvents: unstable_stopLoggingProfilingEvents, get unstable_IdlePriority() { return global.React.__SECRET_INTERNALS_DO_NOT_USE_OR_YOU_WILL_BE_FIRED .Scheduler.unstable_IdlePriority; diff --git a/packages/scheduler/npm/umd/scheduler.production.min.js b/packages/scheduler/npm/umd/scheduler.production.min.js index 6ea8e9df7fe43..93177662aeb11 100644 --- a/packages/scheduler/npm/umd/scheduler.production.min.js +++ b/packages/scheduler/npm/umd/scheduler.production.min.js @@ -104,6 +104,20 @@ ); } + function unstable_startLoggingProfilingEvents() { + return global.React.__SECRET_INTERNALS_DO_NOT_USE_OR_YOU_WILL_BE_FIRED.Scheduler.unstable_startLoggingProfilingEvents.apply( + this, + arguments + ); + } + + function unstable_stopLoggingProfilingEvents() { + return global.React.__SECRET_INTERNALS_DO_NOT_USE_OR_YOU_WILL_BE_FIRED.Scheduler.unstable_stopLoggingProfilingEvents.apply( + this, + arguments + ); + } + return Object.freeze({ unstable_now: unstable_now, unstable_scheduleCallback: unstable_scheduleCallback, @@ -118,6 +132,8 @@ unstable_pauseExecution: unstable_pauseExecution, unstable_getFirstCallbackNode: unstable_getFirstCallbackNode, unstable_forceFrameRate: unstable_forceFrameRate, + unstable_startLoggingProfilingEvents: unstable_startLoggingProfilingEvents, + unstable_stopLoggingProfilingEvents: unstable_stopLoggingProfilingEvents, get unstable_IdlePriority() { return global.React.__SECRET_INTERNALS_DO_NOT_USE_OR_YOU_WILL_BE_FIRED .Scheduler.unstable_IdlePriority; diff --git a/packages/scheduler/npm/umd/scheduler.profiling.min.js b/packages/scheduler/npm/umd/scheduler.profiling.min.js index 6ea8e9df7fe43..93177662aeb11 100644 --- a/packages/scheduler/npm/umd/scheduler.profiling.min.js +++ b/packages/scheduler/npm/umd/scheduler.profiling.min.js @@ -104,6 +104,20 @@ ); } + function unstable_startLoggingProfilingEvents() { + return global.React.__SECRET_INTERNALS_DO_NOT_USE_OR_YOU_WILL_BE_FIRED.Scheduler.unstable_startLoggingProfilingEvents.apply( + this, + arguments + ); + } + + function unstable_stopLoggingProfilingEvents() { + return global.React.__SECRET_INTERNALS_DO_NOT_USE_OR_YOU_WILL_BE_FIRED.Scheduler.unstable_stopLoggingProfilingEvents.apply( + this, + arguments + ); + } + return Object.freeze({ unstable_now: unstable_now, unstable_scheduleCallback: unstable_scheduleCallback, @@ -118,6 +132,8 @@ unstable_pauseExecution: unstable_pauseExecution, unstable_getFirstCallbackNode: unstable_getFirstCallbackNode, unstable_forceFrameRate: unstable_forceFrameRate, + unstable_startLoggingProfilingEvents: unstable_startLoggingProfilingEvents, + unstable_stopLoggingProfilingEvents: unstable_stopLoggingProfilingEvents, get unstable_IdlePriority() { return global.React.__SECRET_INTERNALS_DO_NOT_USE_OR_YOU_WILL_BE_FIRED .Scheduler.unstable_IdlePriority; diff --git a/packages/scheduler/src/Scheduler.js b/packages/scheduler/src/Scheduler.js index ea4efdf6d0aa1..59cf2023f6027 100644 --- a/packages/scheduler/src/Scheduler.js +++ b/packages/scheduler/src/Scheduler.js @@ -10,7 +10,6 @@ import { enableSchedulerDebugging, - enableSharedProfilingBuffer, enableProfiling, } from './SchedulerFeatureFlags'; import { @@ -43,6 +42,8 @@ import { markSchedulerSuspended, markSchedulerUnsuspended, markTaskStart, + stopLoggingProfilingEvents, + startLoggingProfilingEvents, } from './SchedulerProfiling'; // Max 31 bit integer. The max integer size in V8 for 32-bit systems. @@ -78,38 +79,17 @@ var isPerformingWork = false; var isHostCallbackScheduled = false; var isHostTimeoutScheduled = false; -function requestHostCallbackWithProfiling(cb) { +function requestHostCallbackWithProfiling(cb, time) { if (enableProfiling) { - markSchedulerSuspended(); + markSchedulerSuspended(time); requestHostCallbackWithoutProfiling(cb); } } -// Expose a shared array buffer that contains profiling information. -export const unstable_sharedProfilingBuffer = - enableProfiling && enableSharedProfilingBuffer ? sharedProfilingBuffer : null; - const requestHostCallback = enableProfiling ? requestHostCallbackWithProfiling : requestHostCallbackWithoutProfiling; -function flushTask(task, callback, currentTime) { - currentPriorityLevel = task.priorityLevel; - var didUserCallbackTimeout = task.expirationTime <= currentTime; - markTaskRun(task); - var continuationCallback = callback(didUserCallbackTimeout); - if (typeof continuationCallback === 'function') { - markTaskYield(task); - return continuationCallback; - } else { - if (enableProfiling) { - markTaskCompleted(task); - task.isQueued = false; - } - return null; - } -} - function advanceTimers(currentTime) { // Check for tasks that are no longer delayed and add them to the queue. let timer = peek(timerQueue); @@ -141,7 +121,7 @@ function handleTimeout(currentTime) { if (!isHostCallbackScheduled) { if (peek(taskQueue) !== null) { isHostCallbackScheduled = true; - requestHostCallback(flushWork); + requestHostCallback(flushWork, currentTime); } else { const firstTimer = peek(timerQueue); if (firstTimer !== null) { @@ -153,7 +133,7 @@ function handleTimeout(currentTime) { function flushWork(hasTimeRemaining, initialTime) { if (isHostCallbackScheduled) { - markSchedulerUnsuspended(); + markSchedulerUnsuspended(initialTime); } // We'll need a host callback the next time work is scheduled. @@ -184,15 +164,24 @@ function flushWork(hasTimeRemaining, initialTime) { const callback = currentTask.callback; if (callback !== null) { currentTask.callback = null; - const continuation = flushTask(currentTask, callback, currentTime); - if (continuation !== null) { - currentTask.callback = continuation; + 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); } } - currentTime = getCurrentTime(); advanceTimers(currentTime); } else { pop(taskQueue); @@ -201,7 +190,7 @@ function flushWork(hasTimeRemaining, initialTime) { } // Return whether there's additional work if (currentTask !== null) { - markSchedulerSuspended(); + markSchedulerSuspended(currentTime); isHostCallbackScheduled = true; return true; } else { @@ -214,7 +203,8 @@ function flushWork(hasTimeRemaining, initialTime) { } catch (error) { if (currentTask !== null) { if (enableProfiling) { - markTaskErrored(currentTask); + const currentTime = getCurrentTime(); + markTaskErrored(currentTask, currentTime); currentTask.isQueued = false; } if (currentTask === peek(taskQueue)) { @@ -312,7 +302,8 @@ function unstable_scheduleCallback(priorityLevel, callback, options) { var startTime; var timeout; - var label; + // TODO: Expose the current label when profiling, somehow + // var label; if (typeof options === 'object' && options !== null) { var delay = options.delay; if (typeof delay === 'number' && delay > 0) { @@ -324,12 +315,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; - } - } + // if (enableProfiling) { + // var _label = options.label; + // if (typeof _label === 'string') { + // label = _label; + // } + // } } else { timeout = timeoutForPriorityLevel(priorityLevel); startTime = currentTime; @@ -348,9 +339,9 @@ function unstable_scheduleCallback(priorityLevel, callback, options) { if (enableProfiling) { newTask.isQueued = false; - if (typeof options === 'object' && options !== null) { - newTask.label = label; - } + // if (typeof options === 'object' && options !== null) { + // newTask.label = label; + // } } if (startTime > currentTime) { @@ -372,14 +363,14 @@ function unstable_scheduleCallback(priorityLevel, callback, options) { newTask.sortIndex = expirationTime; push(taskQueue, newTask); if (enableProfiling) { - markTaskStart(newTask); + 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) { isHostCallbackScheduled = true; - requestHostCallback(flushWork); + requestHostCallback(flushWork, currentTime); } } @@ -394,7 +385,12 @@ function unstable_continueExecution() { isSchedulerPaused = false; if (!isHostCallbackScheduled && !isPerformingWork) { isHostCallbackScheduled = true; - requestHostCallback(flushWork); + if (enableProfiling) { + const currentTime = getCurrentTime(); + requestHostCallbackWithProfiling(flushWork, currentTime); + } else { + requestHostCallback(flushWork); + } } } @@ -404,14 +400,16 @@ function unstable_getFirstCallbackNode() { function unstable_cancelCallback(task) { if (enableProfiling && task.isQueued) { - markTaskCanceled(task); + const currentTime = getCurrentTime(); + markTaskCanceled(task, currentTime); task.isQueued = false; } if (task !== null && task === peek(taskQueue)) { pop(taskQueue); if (enableProfiling && !isPerformingWork && taskQueue.length === 0) { // The queue is now empty. - markSchedulerUnsuspended(); + const currentTime = getCurrentTime(); + markSchedulerUnsuspended(currentTime); isHostCallbackScheduled = false; cancelHostCallback(); } @@ -464,3 +462,16 @@ export { getCurrentTime as unstable_now, forceFrameRate as unstable_forceFrameRate, }; + +export const unstable_startLoggingProfilingEvents = enableProfiling + ? startLoggingProfilingEvents + : null; + +export const unstable_stopLoggingProfilingEvents = enableProfiling + ? stopLoggingProfilingEvents + : null; + +// Expose a shared array buffer that contains profiling information. +export const unstable_sharedProfilingBuffer = enableProfiling + ? sharedProfilingBuffer + : null; diff --git a/packages/scheduler/src/SchedulerFeatureFlags.js b/packages/scheduler/src/SchedulerFeatureFlags.js index c93c6f012e921..98cf4bad14d74 100644 --- a/packages/scheduler/src/SchedulerFeatureFlags.js +++ b/packages/scheduler/src/SchedulerFeatureFlags.js @@ -12,5 +12,3 @@ export const requestIdleCallbackBeforeFirstFrame = false; export const requestTimerEventBeforeFirstFrame = false; export const enableMessageLoopImplementation = false; export const enableProfiling = __PROFILE__; -export const enableUserTimingAPI = false; -export const enableSharedProfilingBuffer = false; diff --git a/packages/scheduler/src/SchedulerProfiling.js b/packages/scheduler/src/SchedulerProfiling.js index 909e4db0b23f0..6b820497b8df5 100644 --- a/packages/scheduler/src/SchedulerProfiling.js +++ b/packages/scheduler/src/SchedulerProfiling.js @@ -8,32 +8,22 @@ */ import type {PriorityLevel} from './SchedulerPriorities'; -import { - enableProfiling, - enableUserTimingAPI as enableUserTimingAPIFeatureFlag, - enableSharedProfilingBuffer, -} from './SchedulerFeatureFlags'; +import {enableProfiling} from './SchedulerFeatureFlags'; import {NoPriority} from './SchedulerPriorities'; -const enableUserTimingAPI = - enableUserTimingAPIFeatureFlag && - typeof performance !== 'undefined' && - typeof performance.mark === 'function' && - typeof performance.clearMarks === 'function'; - let runIdCounter: number = 0; let mainThreadIdCounter: number = 0; -const length = 3; -const size = Int32Array.BYTES_PER_ELEMENT * length; +const profilingStateSize = 3; export const sharedProfilingBuffer = // $FlowFixMe Flow doesn't know about SharedArrayBuffer typeof SharedArrayBuffer === 'function' - ? new SharedArrayBuffer(size) + ? new SharedArrayBuffer(profilingStateSize * Int32Array.BYTES_PER_ELEMENT) : // $FlowFixMe Flow doesn't know about ArrayBuffer - new ArrayBuffer(size); -const profilingInfo = enableSharedProfilingBuffer + new ArrayBuffer(profilingStateSize * Int32Array.BYTES_PER_ELEMENT); + +const profilingState = enableProfiling ? new Int32Array(sharedProfilingBuffer) : null; @@ -41,145 +31,177 @@ const PRIORITY = 0; const CURRENT_TASK_ID = 1; const QUEUE_SIZE = 2; -if (enableSharedProfilingBuffer && profilingInfo !== null) { - profilingInfo[PRIORITY] = NoPriority; +if (enableProfiling && profilingState !== null) { + profilingState[PRIORITY] = NoPriority; // This is maintained with a counter, because the size of the priority queue // array might include canceled tasks. - profilingInfo[QUEUE_SIZE] = 0; - profilingInfo[CURRENT_TASK_ID] = 0; + 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}) { +export function markTaskStart( + task: {id: number, priorityLevel: PriorityLevel}, + time: number, +) { if (enableProfiling) { - if (enableSharedProfilingBuffer && profilingInfo !== null) { - profilingInfo[QUEUE_SIZE]++; + if (profilingState !== null) { + profilingState[QUEUE_SIZE]++; } - if (enableUserTimingAPI) { - // Use extra field to track if delayed task starts. - const taskStartMark = `SchedulerTask-${task.id}-Start`; - performance.mark(taskStartMark); - performance.clearMarks(taskStartMark); + if (eventLog !== null) { + logEvent([TaskStartEvent, time, task.id, task.priorityLevel]); } } } -export function markTaskCompleted(task: { - id: number, - priorityLevel: PriorityLevel, - label?: string, -}) { +export function markTaskCompleted( + task: { + id: number, + priorityLevel: PriorityLevel, + }, + time: number, +) { if (enableProfiling) { - if (enableSharedProfilingBuffer && profilingInfo !== null) { - profilingInfo[PRIORITY] = NoPriority; - profilingInfo[CURRENT_TASK_ID] = 0; - profilingInfo[QUEUE_SIZE]--; + if (profilingState !== null) { + profilingState[PRIORITY] = NoPriority; + profilingState[CURRENT_TASK_ID] = 0; + profilingState[QUEUE_SIZE]--; } - if (enableUserTimingAPI) { - 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); + + if (eventLog !== null) { + logEvent([TaskCompleteEvent, time, task.id]); } } } -export function markTaskCanceled(task: { - id: number, - priorityLevel: PriorityLevel, - label?: string, -}) { +export function markTaskCanceled( + task: { + id: number, + priorityLevel: PriorityLevel, + }, + time: number, +) { if (enableProfiling) { - if (enableSharedProfilingBuffer && profilingInfo !== null) { - profilingInfo[QUEUE_SIZE]--; + if (profilingState !== null) { + profilingState[QUEUE_SIZE]--; } - if (enableUserTimingAPI) { - 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); + + if (eventLog !== null) { + logEvent([TaskCancelEvent, time, task.id]); } } } -export function markTaskErrored(task: { - id: number, - priorityLevel: PriorityLevel, - label?: string, -}) { +export function markTaskErrored( + task: { + id: number, + priorityLevel: PriorityLevel, + }, + time: number, +) { if (enableProfiling) { - if (enableSharedProfilingBuffer && profilingInfo !== null) { - profilingInfo[PRIORITY] = NoPriority; - profilingInfo[CURRENT_TASK_ID] = 0; - profilingInfo[QUEUE_SIZE]--; + if (profilingState !== null) { + profilingState[PRIORITY] = NoPriority; + profilingState[CURRENT_TASK_ID] = 0; + profilingState[QUEUE_SIZE]--; } - if (enableUserTimingAPI) { - 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); + + if (eventLog !== null) { + logEvent([TaskErrorEvent, time, task.id]); } } } -export function markTaskRun(task: {id: number, priorityLevel: PriorityLevel}) { +export function markTaskRun( + task: {id: number, priorityLevel: PriorityLevel}, + time: number, +) { if (enableProfiling) { - if (enableSharedProfilingBuffer && profilingInfo !== null) { - profilingInfo[PRIORITY] = task.priorityLevel; - profilingInfo[CURRENT_TASK_ID] = task.id; + if (profilingState !== null) { + profilingState[PRIORITY] = task.priorityLevel; + profilingState[CURRENT_TASK_ID] = task.id; } - if (enableUserTimingAPI) { - runIdCounter++; - const runMark = `SchedulerTask-${task.id}-Run-${runIdCounter}`; - performance.mark(runMark); - performance.clearMarks(runMark); + + runIdCounter++; + + if (eventLog !== null) { + logEvent([TaskRunEvent, time, task.id, runIdCounter]); } } } -export function markTaskYield(task: {id: number}) { +export function markTaskYield(task: {id: number}, time: number) { if (enableProfiling) { - if (enableSharedProfilingBuffer && profilingInfo !== null) { - profilingInfo[PRIORITY] = NoPriority; - profilingInfo[CURRENT_TASK_ID] = 0; + if (profilingState !== null) { + profilingState[PRIORITY] = NoPriority; + profilingState[CURRENT_TASK_ID] = 0; } - if (enableUserTimingAPI) { - const yieldMark = `SchedulerTask-${task.id}-Yield-${runIdCounter}`; - performance.mark(yieldMark); - performance.clearMarks(yieldMark); + + if (eventLog !== null) { + logEvent([TaskYieldEvent, time, task.id, runIdCounter]); } } } -export function markSchedulerSuspended() { +export function markSchedulerSuspended(time: number) { if (enableProfiling) { - if (enableUserTimingAPI) { - mainThreadIdCounter++; - const suspendStartMark = - 'SchedulerSuspended-Start-' + mainThreadIdCounter; - performance.mark(suspendStartMark); - performance.clearMarks(suspendStartMark); + mainThreadIdCounter++; + + if (eventLog !== null) { + logEvent([SchedulerSuspendEvent, time, mainThreadIdCounter]); } } } -export function markSchedulerUnsuspended() { +export function markSchedulerUnsuspended(time: number) { if (enableProfiling) { - if (enableUserTimingAPI) { - const suspendedEndMark = 'SchedulerSuspended-End-' + mainThreadIdCounter; - performance.mark(suspendedEndMark); - performance.clearMarks(suspendedEndMark); + 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.internal.js b/packages/scheduler/src/__tests__/SchedulerProfiling-test.js similarity index 50% rename from packages/scheduler/src/__tests__/SchedulerProfiling-test.internal.js rename to packages/scheduler/src/__tests__/SchedulerProfiling-test.js index a38200a30b0fe..b9ae2b066a02f 100644 --- a/packages/scheduler/src/__tests__/SchedulerProfiling-test.internal.js +++ b/packages/scheduler/src/__tests__/SchedulerProfiling-test.js @@ -25,7 +25,6 @@ let cancelCallback; // let wrapCallback; // let getCurrentPriorityLevel; // let shouldYield; -let performance; function priorityLevelToString(priorityLevel) { switch (priorityLevel) { @@ -45,20 +44,19 @@ function priorityLevelToString(priorityLevel) { } describe('Scheduler', () => { - 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", () => {}); + 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_stopLoggingProfilingEvents).toBe(null); + expect(Scheduler.unstable_sharedProfilingBuffer).toBe(null); + }); return; } beforeEach(() => { jest.resetModules(); jest.mock('scheduler', () => require('scheduler/unstable_mock')); - - performance = global.performance = createUserTimingPolyfill(); - - require('scheduler/src/SchedulerFeatureFlags').enableUserTimingAPI = true; - require('scheduler/src/SchedulerFeatureFlags').enableSharedProfilingBuffer = true; Scheduler = require('scheduler'); sharedProfilingArray = new Int32Array( @@ -79,7 +77,6 @@ describe('Scheduler', () => { }); afterEach(() => { - performance.assertAllUserTimingsAreCleared(); if (sharedProfilingArray[2] !== 0) { throw Error( 'Test exited, but the shared profiling buffer indicates that a task ' + @@ -88,182 +85,160 @@ describe('Scheduler', () => { } }); - function createUserTimingPolyfill() { - let marks = new Map(); - let unclearedMarkCount = 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 stopProfilingAndPrintFlamegraph() { + const eventLog = new Int32Array( + Scheduler.unstable_stopLoggingProfilingEvents(), + ); + + const tasks = new Map(); + const mainThreadRuns = []; - return { - mark(name) { - if (marks.has(name)) { - throw Error(`Mark ${name} already exists`); + let i = 0; + processLog: while (i < eventLog.length) { + const instruction = eventLog[i]; + const time = eventLog[i + 1]; + switch (instruction) { + case 0: { + break processLog; } - 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'); + 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; } - const mark = marks.get(name); - if (mark === undefined) { - throw Error(`Mark "${name}" does not exist`); + case TaskCompleteEvent: { + 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; } - if (mark.cleared) { - throw Error(`Mark "${name}" already cleared.`); + case TaskErrorEvent: { + 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; } - 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}"`); - } + 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; } - - // 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; + case TaskRunEvent: + case TaskYieldEvent: { + 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; } - result += `${mainThreadLabelColumn}│${mainThreadTimelineColumn}\n`; + case SchedulerSuspendEvent: + case SchedulerResumeEvent: { + mainThreadRuns.push(time); + i += 3; + break; + } + default: { + throw Error('Unknown instruction type: ' + instruction); + } + } + } - const tasksByPriority = Array.from(tasks.values()).sort( - (t1, t2) => t1.priorityLevel - t2.priorityLevel, + // 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 ${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; + } - 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, + ); - const endIndex = task.end / msPerChar; - timelineColumn += (isRunning ? '█' : '░').repeat( - endIndex - timelineColumn.length, - ); + if (task.exitStatus !== 'completed') { + timelineColumn += `🡐 ${task.exitStatus}`; + } - if (task.exitStatus !== 'completed') { - timelineColumn += `🡐 ${task.exitStatus}`; - } + result += `${labelColumn}│${timelineColumn}\n`; + } - 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(', ')); - } - }, - }; + return '\n' + result; } const PRIORITY = 0; @@ -286,6 +261,8 @@ describe('Scheduler', () => { } it('creates a basic flamegraph', () => { + Scheduler.unstable_startLoggingProfilingEvents(); + Scheduler.unstable_advanceTime(100); scheduleCallback( NormalPriority, @@ -321,16 +298,18 @@ describe('Scheduler', () => { expect(getProfilingInfo()).toEqual('Empty Queue'); - expect(performance.printUserTimings()).toEqual( + expect(stopProfilingAndPrintFlamegraph()).toEqual( ` !!! Main thread │ ██ -[2] Bar [User-blocking] │ ░░░░██████ -[1] Foo [Normal] │ ████████░░░░░░░░██████ +Task 2 [User-blocking] │ ░░░░██████ +Task 1 [Normal] │ ████████░░░░░░░░██████ `, ); }); it('marks when a task is canceled', () => { + Scheduler.unstable_startLoggingProfilingEvents(); + const task = scheduleCallback(NormalPriority, () => { Scheduler.unstable_yieldValue(getProfilingInfo()); Scheduler.unstable_advanceTime(300); @@ -355,15 +334,17 @@ describe('Scheduler', () => { expect(Scheduler).toFlushWithoutYielding(); // The main thread row should end when the callback is cancelled. - expect(performance.printUserTimings()).toEqual( + expect(stopProfilingAndPrintFlamegraph()).toEqual( ` !!! Main thread │ ██ -[1] Task [Normal] │██████░░🡐 canceled +Task 1 [Normal] │██████░░🡐 canceled `, ); }); it('marks when a task errors', () => { + Scheduler.unstable_startLoggingProfilingEvents(); + scheduleCallback(NormalPriority, () => { Scheduler.unstable_advanceTime(300); throw Error('Oops'); @@ -378,30 +359,34 @@ describe('Scheduler', () => { expect(Scheduler).toFlushWithoutYielding(); // The main thread row should end when the callback is cancelled. - expect(performance.printUserTimings()).toEqual( + expect(stopProfilingAndPrintFlamegraph()).toEqual( ` !!! Main thread │ -[1] Task [Normal] │██████🡐 errored +Task 1 [Normal] │██████🡐 errored `, ); }); it('handles cancelling a task that already finished', () => { + Scheduler.unstable_startLoggingProfilingEvents(); + const task = scheduleCallback(NormalPriority, () => { Scheduler.unstable_yieldValue('A'); Scheduler.unstable_advanceTime(1000); }); expect(Scheduler).toFlushAndYield(['A']); cancelCallback(task); - expect(performance.printUserTimings()).toEqual( + expect(stopProfilingAndPrintFlamegraph()).toEqual( ` !!! Main thread │ -[1] Task [Normal] │████████████████████ +Task 1 [Normal] │████████████████████ `, ); }); it('handles cancelling a task multiple times', () => { + Scheduler.unstable_startLoggingProfilingEvents(); + scheduleCallback( NormalPriority, () => { @@ -424,16 +409,17 @@ describe('Scheduler', () => { cancelCallback(task); cancelCallback(task); expect(Scheduler).toFlushAndYield(['A']); - expect(performance.printUserTimings()).toEqual( + expect(stopProfilingAndPrintFlamegraph()).toEqual( ` !!! Main thread │████████████ -[1] A [Normal] │░░░░░░░░░░░░████████████████████ -[2] B [Normal] │ ░░░░░░░░🡐 canceled +Task 1 [Normal] │░░░░░░░░░░░░████████████████████ +Task 2 [Normal] │ ░░░░░░░░🡐 canceled `, ); }); it('handles cancelling a delayed task', () => { + Scheduler.unstable_startLoggingProfilingEvents(); const task = scheduleCallback( NormalPriority, () => Scheduler.unstable_yieldValue('A'), @@ -441,5 +427,20 @@ describe('Scheduler', () => { ); 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 2460a7213681d..360be98e603f6 100644 --- a/packages/scheduler/src/forks/SchedulerFeatureFlags.www.js +++ b/packages/scheduler/src/forks/SchedulerFeatureFlags.www.js @@ -12,8 +12,6 @@ export const { requestIdleCallbackBeforeFirstFrame, requestTimerEventBeforeFirstFrame, enableMessageLoopImplementation, - enableUserTimingAPI, - enableSharedProfilingBuffer, } = 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 8e6afbcc8ad11..c44f62529f496 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; From d374a95f8219afe17f115d6bc8751b87f00ea81c Mon Sep 17 00:00:00 2001 From: Andrew Clark Date: Tue, 13 Aug 2019 18:21:34 -0700 Subject: [PATCH 4/4] Record the current run ID Each synchronous block of Scheduler work is given a unique run ID. This is different than a task ID because a single task will have more than one run if it yields with a continuation. --- packages/scheduler/src/SchedulerProfiling.js | 11 ++++--- .../src/__tests__/SchedulerProfiling-test.js | 29 ++++++++++--------- 2 files changed, 23 insertions(+), 17 deletions(-) diff --git a/packages/scheduler/src/SchedulerProfiling.js b/packages/scheduler/src/SchedulerProfiling.js index 6b820497b8df5..cd13676f8bed6 100644 --- a/packages/scheduler/src/SchedulerProfiling.js +++ b/packages/scheduler/src/SchedulerProfiling.js @@ -15,7 +15,7 @@ import {NoPriority} from './SchedulerPriorities'; let runIdCounter: number = 0; let mainThreadIdCounter: number = 0; -const profilingStateSize = 3; +const profilingStateSize = 4; export const sharedProfilingBuffer = // $FlowFixMe Flow doesn't know about SharedArrayBuffer typeof SharedArrayBuffer === 'function' @@ -29,7 +29,8 @@ const profilingState = enableProfiling const PRIORITY = 0; const CURRENT_TASK_ID = 1; -const QUEUE_SIZE = 2; +const CURRENT_RUN_ID = 2; +const QUEUE_SIZE = 3; if (enableProfiling && profilingState !== null) { profilingState[PRIORITY] = NoPriority; @@ -162,13 +163,14 @@ export function markTaskRun( time: number, ) { if (enableProfiling) { + runIdCounter++; + if (profilingState !== null) { profilingState[PRIORITY] = task.priorityLevel; profilingState[CURRENT_TASK_ID] = task.id; + profilingState[CURRENT_RUN_ID] = runIdCounter; } - runIdCounter++; - if (eventLog !== null) { logEvent([TaskRunEvent, time, task.id, runIdCounter]); } @@ -180,6 +182,7 @@ export function markTaskYield(task: {id: number}, time: number) { if (profilingState !== null) { profilingState[PRIORITY] = NoPriority; profilingState[CURRENT_TASK_ID] = 0; + profilingState[CURRENT_RUN_ID] = 0; } if (eventLog !== null) { diff --git a/packages/scheduler/src/__tests__/SchedulerProfiling-test.js b/packages/scheduler/src/__tests__/SchedulerProfiling-test.js index b9ae2b066a02f..cfb4c73de3c39 100644 --- a/packages/scheduler/src/__tests__/SchedulerProfiling-test.js +++ b/packages/scheduler/src/__tests__/SchedulerProfiling-test.js @@ -76,8 +76,13 @@ describe('Scheduler', () => { // shouldYield = Scheduler.unstable_shouldYield; }); + const PRIORITY = 0; + const CURRENT_TASK_ID = 1; + const CURRENT_RUN_ID = 2; + const QUEUE_SIZE = 3; + afterEach(() => { - if (sharedProfilingArray[2] !== 0) { + if (sharedProfilingArray[QUEUE_SIZE] !== 0) { throw Error( 'Test exited, but the shared profiling buffer indicates that a task ' + 'is still running', @@ -241,9 +246,6 @@ describe('Scheduler', () => { return '\n' + result; } - const PRIORITY = 0; - const CURRENT_TASK_ID = 1; - const QUEUE_SIZE = 2; function getProfilingInfo() { const queueSize = sharedProfilingArray[QUEUE_SIZE]; if (queueSize === 0) { @@ -253,11 +255,12 @@ describe('Scheduler', () => { if (priorityLevel === 0) { return 'Suspended, Queue Size: ' + queueSize; } - return `Current Task: ${ - sharedProfilingArray[QUEUE_SIZE] - }, Priority: ${priorityLevelToString(priorityLevel)}, Queue Size: ${ - sharedProfilingArray[CURRENT_TASK_ID] - }`; + return ( + `Task: ${sharedProfilingArray[CURRENT_TASK_ID]}, ` + + `Run: ${sharedProfilingArray[CURRENT_RUN_ID]}, ` + + `Priority: ${priorityLevelToString(priorityLevel)}, ` + + `Queue Size: ${sharedProfilingArray[QUEUE_SIZE]}` + ); } it('creates a basic flamegraph', () => { @@ -287,13 +290,13 @@ describe('Scheduler', () => { {label: 'Foo'}, ); expect(Scheduler).toFlushAndYieldThrough([ - 'Current Task: 1, Priority: Normal, Queue Size: 1', + 'Task: 1, Run: 1, Priority: Normal, Queue Size: 1', 'Yield', ]); Scheduler.unstable_advanceTime(100); expect(Scheduler).toFlushAndYield([ - 'Current Task: 2, Priority: User-blocking, Queue Size: 2', - 'Current Task: 1, Priority: Normal, Queue Size: 1', + 'Task: 2, Run: 2, Priority: User-blocking, Queue Size: 2', + 'Task: 1, Run: 3, Priority: Normal, Queue Size: 1', ]); expect(getProfilingInfo()).toEqual('Empty Queue'); @@ -321,7 +324,7 @@ Task 1 [Normal] │ ████████░░░░░░░ }); expect(Scheduler).toFlushAndYieldThrough([ - 'Current Task: 1, Priority: Normal, Queue Size: 1', + 'Task: 1, Run: 1, Priority: Normal, Queue Size: 1', 'Yield', ]); Scheduler.unstable_advanceTime(100);