Skip to content

Commit

Permalink
[WIP][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 17, 2019
1 parent b22cf43 commit e826e9f
Show file tree
Hide file tree
Showing 7 changed files with 625 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
75 changes: 66 additions & 9 deletions packages/scheduler/src/Scheduler.js
Original file line number Diff line number Diff line change
Expand Up @@ -8,23 +8,38 @@

/* 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,
markTaskEnd,
markSchedulerSuspended,
markSchedulerUnsuspended,
TaskCompleted,
TaskErrored,
TaskCanceled,
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 +59,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 +90,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 +127,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 +164,7 @@ function flushTask(task, currentTime) {
break;
}
} catch (error) {
markTaskEnd(task, TaskErrored);
throw error;
} finally {
currentPriorityLevel = previousPriorityLevel;
Expand All @@ -143,6 +174,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 +212,8 @@ function flushTask(task, currentTime) {
continuationTask.next = nextAfterContinuation;
continuationTask.previous = previous;
}
} else {
markTaskEnd(task, TaskCompleted);
}
}

Expand Down Expand Up @@ -229,6 +263,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 +309,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 @@ -396,6 +436,11 @@ function unstable_scheduleCallback(priorityLevel, callback, options) {
previous: null,
};

if (enableProfiling) {
taskIdCounter++;
newTask.id = taskIdCounter;
}

if (startTime > currentTime) {
// This is a delayed task.
insertDelayedTask(newTask, startTime);
Expand Down Expand Up @@ -424,6 +469,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 +560,22 @@ function unstable_cancelCallback(task) {
return;
}

markTaskEnd(task, TaskCanceled);

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 @@ -8,3 +8,4 @@

export const enableSchedulerDebugging = false;
export const enableIsInputPending = 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;
132 changes: 132 additions & 0 deletions packages/scheduler/src/SchedulerProfiling.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,132 @@
/**
* 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';
import {
ImmediatePriority,
UserBlockingPriority,
NormalPriority,
LowPriority,
IdlePriority,
} from './SchedulerPriorities';

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

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

export const TaskCompleted = 0;
export const TaskErrored = 1;
export const TaskCanceled = 2;

function priorityLevelToString(priorityLevel) {
if (enableProfiling) {
switch (priorityLevel) {
case ImmediatePriority:
return 'Immediate';
case UserBlockingPriority:
return 'User-blocking';
case NormalPriority:
return 'Normal';
case LowPriority:
return 'Low';
case IdlePriority:
return 'Idle';
}
}
}

export function markTaskStart(task: {id: number, _didStart: true | void}) {
if (enableProfiling) {
// Use extra field to track if delayed task starts.
task._didStart = true;
performance.mark(`SchedulerTask-Start-${task.id}`);
}
}

export function markTaskEnd(task: {
id: number,
_didStart: true | void,
priorityLevel: PriorityLevel,
}) {
if (enableProfiling) {
if (task._didStart !== true) {
// This is a delayed task that never started running. In this case,
// there is not start mark that we can measure.
// TODO: Better model for delayed tasks. Mark when they are first posted
// and when delay elapses.
return;
}
const info = JSON.stringify({priorityLevel: task.priorityLevel});
const taskEndMark = `SchedulerTask-End-${task.id}-${info}`;
performance.mark(taskEndMark);

// Record that the task finished
const taskStartMark = `SchedulerTask-Start-${task.id}`;
const priorityString = priorityLevelToString(task.priorityLevel);
const taskMeasure = `[${task.id}] ${
priorityString === undefined ? 'Unknown' : priorityString
} priority`;
try {
// This could throw if one of the marks was already cleared, either
// because of a bug in Scheduler or code elsewhere.
performance.measure(taskMeasure, taskStartMark, taskEndMark);
} catch (e) {
// Ignore the error. Print the message to the console in dev.
if (__DEV__) {
console.error(e.message);
}
}
performance.clearMarks(taskStartMark);
performance.clearMarks(taskEndMark);
performance.clearMeasures(taskMeasure);
}
}

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

export function markTaskYield(task: {id: number}) {
if (enableProfiling) {
const yieldMark = `SchedulerTask-Yield-${task.id}`;
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 e826e9f

Please sign in to comment.