Skip to content

Commit

Permalink
[Scheduler] Mark user-timing events
Browse files Browse the repository at this point in the history
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.
  • Loading branch information
acdlite committed Jul 23, 2019
1 parent 19354db commit 807db7f
Show file tree
Hide file tree
Showing 7 changed files with 606 additions and 9 deletions.
Original file line number Diff line number Diff line change
Expand Up @@ -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');
Expand Down
84 changes: 75 additions & 9 deletions packages/scheduler/src/Scheduler.js
Original file line number Diff line number Diff line change
Expand Up @@ -8,23 +8,37 @@

/* eslint-disable no-var */

import {enableSchedulerDebugging} from './SchedulerFeatureFlags';
import {
requestHostCallback,
enableSchedulerDebugging,
enableProfiling,
} from './SchedulerFeatureFlags';
import {
requestHostCallback as requestHostCallbackWithoutProfiling,
cancelHostCallback,
requestHostTimeout,
cancelHostTimeout,
shouldYieldToHost,
getCurrentTime,
forceFrameRate,
requestPaint,
} from './SchedulerHostConfig';

// TODO: Use symbols?
var ImmediatePriority = 1;
var UserBlockingPriority = 2;
var NormalPriority = 3;
var LowPriority = 4;
var IdlePriority = 5;
import {
ImmediatePriority,
UserBlockingPriority,
NormalPriority,
LowPriority,
IdlePriority,
} from './SchedulerPriorities';
import {
markTaskRun,
markTaskYield,
markTaskCompleted,
markTaskCanceled,
markTaskErrored,
markSchedulerSuspended,
markSchedulerUnsuspended,
markTaskStart,
} from './SchedulerProfiling';

// Max 31 bit integer. The max integer size in V8 for 32-bit systems.
// Math.pow(2, 30) - 1
Expand All @@ -44,6 +58,9 @@ var IDLE_PRIORITY = maxSigned31BitInt;
var firstTask = null;
var firstDelayedTask = null;

// Only used for profiling
var taskIdCounter = 0;

// Pausing the scheduler is useful for debugging.
var isSchedulerPaused = false;

Expand Down Expand Up @@ -72,6 +89,17 @@ function scheduler_flushTaskAtPriority_Idle(callback, didTimeout) {
return callback(didTimeout);
}

function requestHostCallbackWithProfiling(cb) {
if (enableProfiling) {
markSchedulerSuspended();
requestHostCallbackWithoutProfiling(cb);
}
}

const requestHostCallback = enableProfiling
? requestHostCallbackWithProfiling
: requestHostCallbackWithoutProfiling;

function flushTask(task, currentTime) {
// Remove the task from the list before calling the callback. That way the
// list is in a consistent state even if the callback throws.
Expand All @@ -98,6 +126,7 @@ function flushTask(task, currentTime) {
currentTask = task;
var continuationCallback;
try {
markTaskRun(task);
var didUserCallbackTimeout = task.expirationTime <= currentTime;
// Add an extra function to the callstack. Profiling tools can use this
// to infer the priority of work that appears higher in the stack.
Expand Down Expand Up @@ -134,6 +163,7 @@ function flushTask(task, currentTime) {
break;
}
} catch (error) {
markTaskErrored(task);
throw error;
} finally {
currentPriorityLevel = previousPriorityLevel;
Expand All @@ -143,6 +173,7 @@ function flushTask(task, currentTime) {
// A callback may return a continuation. The continuation should be scheduled
// with the same priority and expiration as the just-finished callback.
if (typeof continuationCallback === 'function') {
markTaskYield(task);
var expirationTime = task.expirationTime;
var continuationTask = task;
continuationTask.callback = continuationCallback;
Expand Down Expand Up @@ -180,6 +211,8 @@ function flushTask(task, currentTime) {
continuationTask.next = nextAfterContinuation;
continuationTask.previous = previous;
}
} else {
markTaskCompleted(task);
}
}

Expand Down Expand Up @@ -229,6 +262,10 @@ function flushWork(hasTimeRemaining, initialTime) {
return;
}

if (isHostCallbackScheduled) {
markSchedulerUnsuspended();
}

// We'll need a host callback the next time work is scheduled.
isHostCallbackScheduled = false;
if (isHostTimeoutScheduled) {
Expand Down Expand Up @@ -271,6 +308,8 @@ function flushWork(hasTimeRemaining, initialTime) {
}
// Return whether there's additional work
if (firstTask !== null) {
isHostCallbackScheduled = true;
markSchedulerSuspended();
return true;
} else {
if (firstDelayedTask !== null) {
Expand Down Expand Up @@ -369,6 +408,7 @@ function unstable_scheduleCallback(priorityLevel, callback, options) {

var startTime;
var timeout;
var label;
if (typeof options === 'object' && options !== null) {
var delay = options.delay;
if (typeof delay === 'number' && delay > 0) {
Expand All @@ -380,6 +420,12 @@ function unstable_scheduleCallback(priorityLevel, callback, options) {
typeof options.timeout === 'number'
? options.timeout
: timeoutForPriorityLevel(priorityLevel);
if (enableProfiling) {
var _label = options.label;
if (typeof _label === 'string') {
label = _label;
}
}
} else {
timeout = timeoutForPriorityLevel(priorityLevel);
startTime = currentTime;
Expand All @@ -396,6 +442,14 @@ function unstable_scheduleCallback(priorityLevel, callback, options) {
previous: null,
};

if (enableProfiling) {
taskIdCounter++;
newTask.id = taskIdCounter;
if (typeof options === 'object' && options !== null) {
newTask.label = label;
}
}

if (startTime > currentTime) {
// This is a delayed task.
insertDelayedTask(newTask, startTime);
Expand Down Expand Up @@ -424,6 +478,7 @@ function unstable_scheduleCallback(priorityLevel, callback, options) {
}

function insertScheduledTask(newTask, expirationTime) {
markTaskStart(newTask);
// Insert the new task into the list, ordered first by its timeout, then by
// insertion. So the new task is inserted after any other task the
// same timeout
Expand Down Expand Up @@ -514,11 +569,22 @@ function unstable_cancelCallback(task) {
return;
}

markTaskCanceled(task);

if (task === next) {
if (task === firstTask) {
firstTask = null;
if (!isPerformingWork) {
isHostCallbackScheduled = false;
cancelHostCallback();
markSchedulerUnsuspended();
}
} else if (task === firstDelayedTask) {
firstDelayedTask = null;
if (!isPerformingWork) {
isHostTimeoutScheduled = false;
cancelHostTimeout();
}
}
} else {
if (task === firstTask) {
Expand Down
1 change: 1 addition & 0 deletions packages/scheduler/src/SchedulerFeatureFlags.js
Original file line number Diff line number Diff line change
Expand Up @@ -10,3 +10,4 @@ export const enableSchedulerDebugging = false;
export const enableIsInputPending = false;
export const requestIdleCallbackBeforeFirstFrame = false;
export const requestTimerEventBeforeFirstFrame = false;
export const enableProfiling = __PROFILE__;
17 changes: 17 additions & 0 deletions packages/scheduler/src/SchedulerPriorities.js
Original file line number Diff line number Diff line change
@@ -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;
114 changes: 114 additions & 0 deletions packages/scheduler/src/SchedulerProfiling.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,114 @@
/**
* Copyright (c) Facebook, Inc. and its affiliates.
*
* This source code is licensed under the MIT license found in the
* LICENSE file in the root directory of this source tree.
*
* @flow
*/

import type {PriorityLevel} from './SchedulerPriorities';
import {enableProfiling as enableProfilingFeatureFlag} from './SchedulerFeatureFlags';

const enableProfiling =
enableProfilingFeatureFlag &&
typeof performance !== 'undefined' &&
typeof performance.mark === 'function' &&
typeof performance.clearMarks === 'function';

let runIdCounter: number = 0;
let mainThreadIdCounter: number = 0;

export function markTaskStart(task: {id: number}) {
if (enableProfiling) {
// Use extra field to track if delayed task starts.
const taskStartMark = `SchedulerTask-${task.id}-Start`;
performance.mark(taskStartMark);
performance.clearMarks(taskStartMark);
}
}

export function markTaskCompleted(task: {
id: number,
priorityLevel: PriorityLevel,
label?: string,
}) {
if (enableProfiling) {
const info = JSON.stringify({
priorityLevel: task.priorityLevel,
label: task.label,
exitStatus: 'completed',
});
const taskEndMark = `SchedulerTask-${task.id}-End-${info}`;
performance.mark(taskEndMark);
performance.clearMarks(taskEndMark);
}
}

export function markTaskCanceled(task: {
id: number,
priorityLevel: PriorityLevel,
label?: string,
}) {
if (enableProfiling) {
const info = JSON.stringify({
priorityLevel: task.priorityLevel,
label: task.label,
exitStatus: 'canceled',
});
const taskEndMark = `SchedulerTask-${task.id}-End-${info}`;
performance.mark(taskEndMark);
performance.clearMarks(taskEndMark);
}
}

export function markTaskErrored(task: {
id: number,
priorityLevel: PriorityLevel,
label?: string,
}) {
if (enableProfiling) {
const info = JSON.stringify({
priorityLevel: task.priorityLevel,
label: task.label,
exitStatus: 'errored',
});
const taskEndMark = `SchedulerTask-${task.id}-End-${info}`;
performance.mark(taskEndMark);
performance.clearMarks(taskEndMark);
}
}

export function markTaskRun(task: {id: number}) {
if (enableProfiling) {
runIdCounter++;
const runMark = `SchedulerTask-${task.id}-Run-${runIdCounter}`;
performance.mark(runMark);
performance.clearMarks(runMark);
}
}

export function markTaskYield(task: {id: number}) {
if (enableProfiling) {
const yieldMark = `SchedulerTask-${task.id}-Yield-${runIdCounter}`;
performance.mark(yieldMark);
performance.clearMarks(yieldMark);
}
}

export function markSchedulerSuspended() {
if (enableProfiling) {
mainThreadIdCounter++;
const suspendStartMark = 'SchedulerSuspended-Start-' + mainThreadIdCounter;
performance.mark(suspendStartMark);
performance.clearMarks(suspendStartMark);
}
}

export function markSchedulerUnsuspended() {
if (enableProfiling) {
const suspendedEndMark = 'SchedulerSuspended-End-' + mainThreadIdCounter;
performance.mark(suspendedEndMark);
performance.clearMarks(suspendedEndMark);
}
}
Loading

0 comments on commit 807db7f

Please sign in to comment.