[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.

Author: acdlite

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');

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,14 +323,20 @@ function unstable_scheduleCallback(priorityLevel, callback, options) {
   var expirationTime = startTime + timeout;
 
   var newTask = {
-    id: taskIdCounter++,
+    id: ++taskIdCounter,
     callback,
     priorityLevel,
     startTime,
     expirationTime,
     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() {

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;

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;

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);
+    }
+  }
+}