@samitouri / QOS-React-2 / commits / a34ca7bce6

[Scheduler] Profiling features (#16145)

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

Andrew Clark committed Aug 13, 2019 at 19:01 UTC a34ca7bce69c2f321daef0b8650ad6e7cfce366a

18 files changed +919 -35

.eslintrc.js

@@ -140,6 +140,8 @@ module.exports = {

140 ],

141

142 globals: {

143 + SharedArrayBuffer: true,

144 +

145 spyOnDev: true,

146 spyOnDevAndProd: true,

147 spyOnProd: true,

packages/react-reconciler/src/__tests__/ReactIncrementalPerf-test.internal.js

@@ -136,6 +136,7 @@ describe('ReactDebugFiberPerf', () => {

136 require('shared/ReactFeatureFlags').enableProfilerTimer = false;

137 require('shared/ReactFeatureFlags').replayFailedUnitOfWorkWithInvokeGuardedCallback = false;

138 require('shared/ReactFeatureFlags').debugRenderPhaseSideEffectsForStrictMode = false;

139 + require('scheduler/src/SchedulerFeatureFlags').enableProfiling = false;

140

141 // Import after the polyfill is set up:

142 React = require('react');

packages/scheduler/npm/umd/scheduler.development.js

+20

@@ -110,6 +110,20 @@

110 );

111 }

112

113 + function unstable_startLoggingProfilingEvents() {

114 + return global.React.__SECRET_INTERNALS_DO_NOT_USE_OR_YOU_WILL_BE_FIRED.Scheduler.unstable_startLoggingProfilingEvents.apply(

115 + this,

116 + arguments

117 + );

118 + }

119 +

120 + function unstable_stopLoggingProfilingEvents() {

121 + return global.React.__SECRET_INTERNALS_DO_NOT_USE_OR_YOU_WILL_BE_FIRED.Scheduler.unstable_stopLoggingProfilingEvents.apply(

122 + this,

123 + arguments

124 + );

125 + }

126 +

127 return Object.freeze({

128 unstable_now: unstable_now,

129 unstable_scheduleCallback: unstable_scheduleCallback,

@@ -124,6 +138,8 @@

138 unstable_pauseExecution: unstable_pauseExecution,

139 unstable_getFirstCallbackNode: unstable_getFirstCallbackNode,

140 unstable_forceFrameRate: unstable_forceFrameRate,

141 + unstable_startLoggingProfilingEvents: unstable_startLoggingProfilingEvents,

142 + unstable_stopLoggingProfilingEvents: unstable_stopLoggingProfilingEvents,

143 get unstable_IdlePriority() {

144 return global.React.__SECRET_INTERNALS_DO_NOT_USE_OR_YOU_WILL_BE_FIRED

145 .Scheduler.unstable_IdlePriority;

@@ -144,5 +160,9 @@

160 return global.React.__SECRET_INTERNALS_DO_NOT_USE_OR_YOU_WILL_BE_FIRED

161 .Scheduler.unstable_UserBlockingPriority;

162 },

163 + get unstable_sharedProfilingBuffer() {

164 + return global.React.__SECRET_INTERNALS_DO_NOT_USE_OR_YOU_WILL_BE_FIRED

165 + .Scheduler.unstable_getFirstCallbackNode;

166 + },

167 });

168 });

packages/scheduler/npm/umd/scheduler.production.min.js

+20

@@ -104,6 +104,20 @@

104 );

105 }

106

107 + function unstable_startLoggingProfilingEvents() {

108 + return global.React.__SECRET_INTERNALS_DO_NOT_USE_OR_YOU_WILL_BE_FIRED.Scheduler.unstable_startLoggingProfilingEvents.apply(

109 + this,

110 + arguments

111 + );

112 + }

113 +

114 + function unstable_stopLoggingProfilingEvents() {

115 + return global.React.__SECRET_INTERNALS_DO_NOT_USE_OR_YOU_WILL_BE_FIRED.Scheduler.unstable_stopLoggingProfilingEvents.apply(

116 + this,

117 + arguments

118 + );

119 + }

120 +

121 return Object.freeze({

122 unstable_now: unstable_now,

123 unstable_scheduleCallback: unstable_scheduleCallback,

@@ -118,6 +132,8 @@

132 unstable_pauseExecution: unstable_pauseExecution,

133 unstable_getFirstCallbackNode: unstable_getFirstCallbackNode,

134 unstable_forceFrameRate: unstable_forceFrameRate,

135 + unstable_startLoggingProfilingEvents: unstable_startLoggingProfilingEvents,

136 + unstable_stopLoggingProfilingEvents: unstable_stopLoggingProfilingEvents,

137 get unstable_IdlePriority() {

138 return global.React.__SECRET_INTERNALS_DO_NOT_USE_OR_YOU_WILL_BE_FIRED

139 .Scheduler.unstable_IdlePriority;

@@ -138,5 +154,9 @@

154 return global.React.__SECRET_INTERNALS_DO_NOT_USE_OR_YOU_WILL_BE_FIRED

155 .Scheduler.unstable_UserBlockingPriority;

156 },

157 + get unstable_sharedProfilingBuffer() {

158 + return global.React.__SECRET_INTERNALS_DO_NOT_USE_OR_YOU_WILL_BE_FIRED

159 + .Scheduler.unstable_getFirstCallbackNode;

160 + },

161 });

162 });

packages/scheduler/npm/umd/scheduler.profiling.min.js

+20

@@ -104,6 +104,20 @@

104 );

105 }

106

107 + function unstable_startLoggingProfilingEvents() {

108 + return global.React.__SECRET_INTERNALS_DO_NOT_USE_OR_YOU_WILL_BE_FIRED.Scheduler.unstable_startLoggingProfilingEvents.apply(

109 + this,

110 + arguments

111 + );

112 + }

113 +

114 + function unstable_stopLoggingProfilingEvents() {

115 + return global.React.__SECRET_INTERNALS_DO_NOT_USE_OR_YOU_WILL_BE_FIRED.Scheduler.unstable_stopLoggingProfilingEvents.apply(

116 + this,

117 + arguments

118 + );

119 + }

120 +

121 return Object.freeze({

122 unstable_now: unstable_now,

123 unstable_scheduleCallback: unstable_scheduleCallback,

@@ -118,6 +132,8 @@

132 unstable_pauseExecution: unstable_pauseExecution,

133 unstable_getFirstCallbackNode: unstable_getFirstCallbackNode,

134 unstable_forceFrameRate: unstable_forceFrameRate,

135 + unstable_startLoggingProfilingEvents: unstable_startLoggingProfilingEvents,

136 + unstable_stopLoggingProfilingEvents: unstable_stopLoggingProfilingEvents,

137 get unstable_IdlePriority() {

138 return global.React.__SECRET_INTERNALS_DO_NOT_USE_OR_YOU_WILL_BE_FIRED

139 .Scheduler.unstable_IdlePriority;

@@ -138,5 +154,9 @@

154 return global.React.__SECRET_INTERNALS_DO_NOT_USE_OR_YOU_WILL_BE_FIRED

155 .Scheduler.unstable_UserBlockingPriority;

156 },

157 + get unstable_sharedProfilingBuffer() {

158 + return global.React.__SECRET_INTERNALS_DO_NOT_USE_OR_YOU_WILL_BE_FIRED

159 + .Scheduler.unstable_getFirstCallbackNode;

160 + },

161 });

162 });

packages/scheduler/src/Scheduler.js

+131 -26

@@ -8,10 +8,14 @@

9 /* eslint-disable no-var */

11 -import {enableSchedulerDebugging} from './SchedulerFeatureFlags';

11 import {

13 - requestHostCallback,

12 + enableSchedulerDebugging,

13 + enableProfiling,

14 +} from './SchedulerFeatureFlags';

15 +import {

16 + requestHostCallback as requestHostCallbackWithoutProfiling,

17 requestHostTimeout,

18 + cancelHostCallback,

19 cancelHostTimeout,

20 shouldYieldToHost,

21 getCurrentTime,

@@ -21,11 +25,26 @@ import {

25 import {push, pop, peek} from './SchedulerMinHeap';

27 // TODO: Use symbols?

24 -var ImmediatePriority = 1;

25 -var UserBlockingPriority = 2;

26 -var NormalPriority = 3;

27 -var LowPriority = 4;

28 -var IdlePriority = 5;

28 +import {

29 + ImmediatePriority,

30 + UserBlockingPriority,

31 + NormalPriority,

32 + LowPriority,

33 + IdlePriority,

34 +} from './SchedulerPriorities';

35 +import {

36 + sharedProfilingBuffer,

37 + markTaskRun,

38 + markTaskYield,

39 + markTaskCompleted,

40 + markTaskCanceled,

41 + markTaskErrored,

42 + markSchedulerSuspended,

43 + markSchedulerUnsuspended,

44 + markTaskStart,

45 + stopLoggingProfilingEvents,

46 + startLoggingProfilingEvents,

47 +} from './SchedulerProfiling';

49 // Max 31 bit integer. The max integer size in V8 for 32-bit systems.

50 // Math.pow(2, 30) - 1

@@ -60,15 +79,17 @@ var isPerformingWork = false;

79 var isHostCallbackScheduled = false;

80 var isHostTimeoutScheduled = false;

63 -function flushTask(task, callback, currentTime) {

64 - currentPriorityLevel = task.priorityLevel;

65 - var didUserCallbackTimeout = task.expirationTime <= currentTime;

66 - var continuationCallback = callback(didUserCallbackTimeout);

67 - return typeof continuationCallback === 'function'

68 - ? continuationCallback

69 - : null;

82 +function requestHostCallbackWithProfiling(cb, time) {

83 + if (enableProfiling) {

84 + markSchedulerSuspended(time);

85 + requestHostCallbackWithoutProfiling(cb);

86 + }

87 }

89 +const requestHostCallback = enableProfiling

90 + ? requestHostCallbackWithProfiling

91 + : requestHostCallbackWithoutProfiling;

92 +

93 function advanceTimers(currentTime) {

94 // Check for tasks that are no longer delayed and add them to the queue.

95 let timer = peek(timerQueue);

@@ -81,6 +102,10 @@ function advanceTimers(currentTime) {

102 pop(timerQueue);

103 timer.sortIndex = timer.expirationTime;

104 push(taskQueue, timer);

105 + if (enableProfiling) {

106 + markTaskStart(timer);

107 + timer.isQueued = true;

108 + }

109 } else {

110 // Remaining timers are pending.

111 return;

@@ -96,7 +121,7 @@ function handleTimeout(currentTime) {

121 if (!isHostCallbackScheduled) {

122 if (peek(taskQueue) !== null) {

123 isHostCallbackScheduled = true;

99 - requestHostCallback(flushWork);

124 + requestHostCallback(flushWork, currentTime);

125 } else {

126 const firstTimer = peek(timerQueue);

127 if (firstTimer !== null) {

@@ -107,6 +132,10 @@ function handleTimeout(currentTime) {

132 }

133

134 function flushWork(hasTimeRemaining, initialTime) {

135 + if (isHostCallbackScheduled) {

136 + markSchedulerUnsuspended(initialTime);

137 + }

138 +

139 // We'll need a host callback the next time work is scheduled.

140 isHostCallbackScheduled = false;

141 if (isHostTimeoutScheduled) {

@@ -135,15 +164,24 @@ function flushWork(hasTimeRemaining, initialTime) {

164 const callback = currentTask.callback;

165 if (callback !== null) {

166 currentTask.callback = null;

138 - const continuation = flushTask(currentTask, callback, currentTime);

139 - if (continuation !== null) {

140 - currentTask.callback = continuation;

167 + currentPriorityLevel = currentTask.priorityLevel;

168 + const didUserCallbackTimeout =

169 + currentTask.expirationTime <= currentTime;

170 + markTaskRun(currentTask, currentTime);

171 + const continuationCallback = callback(didUserCallbackTimeout);

172 + currentTime = getCurrentTime();

173 + if (typeof continuationCallback === 'function') {

174 + currentTask.callback = continuationCallback;

175 + markTaskYield(currentTask, currentTime);

176 } else {

177 + if (enableProfiling) {

178 + markTaskCompleted(currentTask, currentTime);

179 + currentTask.isQueued = false;

180 + }

181 if (currentTask === peek(taskQueue)) {

182 pop(taskQueue);

183 }

184 }

146 - currentTime = getCurrentTime();

185 advanceTimers(currentTime);

186 } else {

187 pop(taskQueue);

@@ -152,6 +190,8 @@ function flushWork(hasTimeRemaining, initialTime) {

190 }

191 // Return whether there's additional work

192 if (currentTask !== null) {

193 + markSchedulerSuspended(currentTime);

194 + isHostCallbackScheduled = true;

195 return true;

196 } else {

197 let firstTimer = peek(timerQueue);

@@ -160,6 +200,18 @@ function flushWork(hasTimeRemaining, initialTime) {

200 }

201 return false;

202 }

203 + } catch (error) {

204 + if (currentTask !== null) {

205 + if (enableProfiling) {

206 + const currentTime = getCurrentTime();

207 + markTaskErrored(currentTask, currentTime);

208 + currentTask.isQueued = false;

209 + }

210 + if (currentTask === peek(taskQueue)) {

211 + pop(taskQueue);

212 + }

213 + }

214 + throw error;

215 } finally {

216 currentTask = null;

217 currentPriorityLevel = previousPriorityLevel;

@@ -250,6 +302,8 @@ function unstable_scheduleCallback(priorityLevel, callback, options) {

302

303 var startTime;

304 var timeout;

305 + // TODO: Expose the current label when profiling, somehow

306 + // var label;

307 if (typeof options === 'object' && options !== null) {

308 var delay = options.delay;

309 if (typeof delay === 'number' && delay > 0) {

@@ -261,6 +315,12 @@ function unstable_scheduleCallback(priorityLevel, callback, options) {

315 typeof options.timeout === 'number'

316 ? options.timeout

317 : timeoutForPriorityLevel(priorityLevel);

318 + // if (enableProfiling) {

319 + // var _label = options.label;

320 + // if (typeof _label === 'string') {

321 + // label = _label;

322 + // }

323 + // }

324 } else {

325 timeout = timeoutForPriorityLevel(priorityLevel);

326 startTime = currentTime;

@@ -269,7 +329,7 @@ function unstable_scheduleCallback(priorityLevel, callback, options) {

329 var expirationTime = startTime + timeout;

330

331 var newTask = {

272 - id: taskIdCounter++,

332 + id: ++taskIdCounter,

333 callback,

334 priorityLevel,

335 startTime,

@@ -277,6 +337,13 @@ function unstable_scheduleCallback(priorityLevel, callback, options) {

337 sortIndex: -1,

338 };

339

340 + if (enableProfiling) {

341 + newTask.isQueued = false;

342 + // if (typeof options === 'object' && options !== null) {

343 + // newTask.label = label;

344 + // }

345 + }

346 +

347 if (startTime > currentTime) {

348 // This is a delayed task.

349 newTask.sortIndex = startTime;

@@ -295,11 +362,15 @@ function unstable_scheduleCallback(priorityLevel, callback, options) {

362 } else {

363 newTask.sortIndex = expirationTime;

364 push(taskQueue, newTask);

365 + if (enableProfiling) {

366 + markTaskStart(newTask, currentTime);

367 + newTask.isQueued = true;

368 + }

369 // Schedule a host callback, if needed. If we're already performing work,

370 // wait until the next time we yield.

371 if (!isHostCallbackScheduled && !isPerformingWork) {

372 isHostCallbackScheduled = true;

302 - requestHostCallback(flushWork);

373 + requestHostCallback(flushWork, currentTime);

374 }

375 }

376

@@ -314,7 +385,12 @@ function unstable_continueExecution() {

385 isSchedulerPaused = false;

386 if (!isHostCallbackScheduled && !isPerformingWork) {

387 isHostCallbackScheduled = true;

317 - requestHostCallback(flushWork);

388 + if (enableProfiling) {

389 + const currentTime = getCurrentTime();

390 + requestHostCallbackWithProfiling(flushWork, currentTime);

391 + } else {

392 + requestHostCallback(flushWork);

393 + }

394 }

395 }

396

@@ -323,10 +399,26 @@ function unstable_getFirstCallbackNode() {

399 }

400

401 function unstable_cancelCallback(task) {

326 - // Null out the callback to indicate the task has been canceled. (Can't remove

327 - // from the queue because you can't remove arbitrary nodes from an array based

328 - // heap, only the first one.)

329 - task.callback = null;

402 + if (enableProfiling && task.isQueued) {

403 + const currentTime = getCurrentTime();

404 + markTaskCanceled(task, currentTime);

405 + task.isQueued = false;

406 + }

407 + if (task !== null && task === peek(taskQueue)) {

408 + pop(taskQueue);

409 + if (enableProfiling && !isPerformingWork && taskQueue.length === 0) {

410 + // The queue is now empty.

411 + const currentTime = getCurrentTime();

412 + markSchedulerUnsuspended(currentTime);

413 + isHostCallbackScheduled = false;

414 + cancelHostCallback();

415 + }

416 + } else {

417 + // Null out the callback to indicate the task has been canceled. (Can't

418 + // remove from the queue because you can't remove arbitrary nodes from an

419 + // array based heap, only the first one.)

420 + task.callback = null;

421 + }

422 }

423

424 function unstable_getCurrentPriorityLevel() {

@@ -370,3 +462,16 @@ export {

462 getCurrentTime as unstable_now,

463 forceFrameRate as unstable_forceFrameRate,

464 };

465 +

466 +export const unstable_startLoggingProfilingEvents = enableProfiling

467 + ? startLoggingProfilingEvents

468 + : null;

469 +

470 +export const unstable_stopLoggingProfilingEvents = enableProfiling

471 + ? stopLoggingProfilingEvents

472 + : null;

473 +

474 +// Expose a shared array buffer that contains profiling information.

475 +export const unstable_sharedProfilingBuffer = enableProfiling

476 + ? sharedProfilingBuffer

477 + : null;

packages/scheduler/src/SchedulerFeatureFlags.js

@@ -11,3 +11,4 @@ export const enableIsInputPending = false;

11 export const requestIdleCallbackBeforeFirstFrame = false;

12 export const requestTimerEventBeforeFirstFrame = false;

13 export const enableMessageLoopImplementation = false;

14 +export const enableProfiling = __PROFILE__;

packages/scheduler/src/SchedulerPriorities.js new

+18

@@ -0,0 +1,18 @@

1 +/**

2 + * Copyright (c) Facebook, Inc. and its affiliates.

3 + *

4 + * This source code is licensed under the MIT license found in the

5 + * LICENSE file in the root directory of this source tree.

6 + *

7 + * @flow

8 + */

9 +

10 +export type PriorityLevel = 0 | 1 | 2 | 3 | 4 | 5;

11 +

12 +// TODO: Use symbols?

13 +export const NoPriority = 0;

14 +export const ImmediatePriority = 1;

15 +export const UserBlockingPriority = 2;

16 +export const NormalPriority = 3;

17 +export const LowPriority = 4;

18 +export const IdlePriority = 5;

packages/scheduler/src/SchedulerProfiling.js new

+210

@@ -0,0 +1,210 @@

1 +/**

2 + * Copyright (c) Facebook, Inc. and its affiliates.

3 + *

4 + * This source code is licensed under the MIT license found in the

5 + * LICENSE file in the root directory of this source tree.

6 + *

7 + * @flow

8 + */

9 +

10 +import type {PriorityLevel} from './SchedulerPriorities';

11 +import {enableProfiling} from './SchedulerFeatureFlags';

12 +

13 +import {NoPriority} from './SchedulerPriorities';

14 +

15 +let runIdCounter: number = 0;

16 +let mainThreadIdCounter: number = 0;

17 +

18 +const profilingStateSize = 4;

19 +export const sharedProfilingBuffer =

20 + // $FlowFixMe Flow doesn't know about SharedArrayBuffer

21 + typeof SharedArrayBuffer === 'function'

22 + ? new SharedArrayBuffer(profilingStateSize * Int32Array.BYTES_PER_ELEMENT)

23 + : // $FlowFixMe Flow doesn't know about ArrayBuffer

24 + new ArrayBuffer(profilingStateSize * Int32Array.BYTES_PER_ELEMENT);

25 +

26 +const profilingState = enableProfiling

27 + ? new Int32Array(sharedProfilingBuffer)

28 + : null;

29 +

30 +const PRIORITY = 0;

31 +const CURRENT_TASK_ID = 1;

32 +const CURRENT_RUN_ID = 2;

33 +const QUEUE_SIZE = 3;

34 +

35 +if (enableProfiling && profilingState !== null) {

36 + profilingState[PRIORITY] = NoPriority;

37 + // This is maintained with a counter, because the size of the priority queue

38 + // array might include canceled tasks.

39 + profilingState[QUEUE_SIZE] = 0;

40 + profilingState[CURRENT_TASK_ID] = 0;

41 +}

42 +

43 +const INITIAL_EVENT_LOG_SIZE = 1000;

44 +

45 +let eventLogSize = 0;

46 +let eventLogBuffer = null;

47 +let eventLog = null;

48 +let eventLogIndex = 0;

49 +

50 +const TaskStartEvent = 1;

51 +const TaskCompleteEvent = 2;

52 +const TaskErrorEvent = 3;

53 +const TaskCancelEvent = 4;

54 +const TaskRunEvent = 5;

55 +const TaskYieldEvent = 6;

56 +const SchedulerSuspendEvent = 7;

57 +const SchedulerResumeEvent = 8;

58 +

59 +function logEvent(entries) {

60 + if (eventLog !== null) {

61 + const offset = eventLogIndex;

62 + eventLogIndex += entries.length;

63 + if (eventLogIndex + 1 > eventLogSize) {

64 + eventLogSize = eventLogIndex + 1;

65 + const newEventLog = new Int32Array(

66 + eventLogSize * Int32Array.BYTES_PER_ELEMENT,

67 + );

68 + newEventLog.set(eventLog);

69 + eventLogBuffer = newEventLog.buffer;

70 + eventLog = newEventLog;

71 + }

72 + eventLog.set(entries, offset);

73 + }

74 +}

75 +

76 +export function startLoggingProfilingEvents(): void {

77 + eventLogSize = INITIAL_EVENT_LOG_SIZE;

78 + eventLogBuffer = new ArrayBuffer(eventLogSize * Int32Array.BYTES_PER_ELEMENT);

79 + eventLog = new Int32Array(eventLogBuffer);

80 + eventLogIndex = 0;

81 +}

82 +

83 +export function stopLoggingProfilingEvents(): ArrayBuffer | null {

84 + const buffer = eventLogBuffer;

85 + eventLogBuffer = eventLog = null;

86 + return buffer;

87 +}

88 +

89 +export function markTaskStart(

90 + task: {id: number, priorityLevel: PriorityLevel},

91 + time: number,

92 +) {

93 + if (enableProfiling) {

94 + if (profilingState !== null) {

95 + profilingState[QUEUE_SIZE]++;

96 + }

97 + if (eventLog !== null) {

98 + logEvent([TaskStartEvent, time, task.id, task.priorityLevel]);

99 + }

100 + }

101 +}

102 +

103 +export function markTaskCompleted(

104 + task: {

105 + id: number,

106 + priorityLevel: PriorityLevel,

107 + },

108 + time: number,

109 +) {

110 + if (enableProfiling) {

111 + if (profilingState !== null) {

112 + profilingState[PRIORITY] = NoPriority;

113 + profilingState[CURRENT_TASK_ID] = 0;

114 + profilingState[QUEUE_SIZE]--;

115 + }

116 +

117 + if (eventLog !== null) {

118 + logEvent([TaskCompleteEvent, time, task.id]);

119 + }

120 + }

121 +}

122 +

123 +export function markTaskCanceled(

124 + task: {

125 + id: number,

126 + priorityLevel: PriorityLevel,

127 + },

128 + time: number,

129 +) {

130 + if (enableProfiling) {

131 + if (profilingState !== null) {

132 + profilingState[QUEUE_SIZE]--;

133 + }

134 +

135 + if (eventLog !== null) {

136 + logEvent([TaskCancelEvent, time, task.id]);

137 + }

138 + }

139 +}

140 +

141 +export function markTaskErrored(

142 + task: {

143 + id: number,

144 + priorityLevel: PriorityLevel,

145 + },

146 + time: number,

147 +) {

148 + if (enableProfiling) {

149 + if (profilingState !== null) {

150 + profilingState[PRIORITY] = NoPriority;

151 + profilingState[CURRENT_TASK_ID] = 0;

152 + profilingState[QUEUE_SIZE]--;

153 + }

154 +

155 + if (eventLog !== null) {

156 + logEvent([TaskErrorEvent, time, task.id]);

157 + }

158 + }

159 +}

160 +

161 +export function markTaskRun(

162 + task: {id: number, priorityLevel: PriorityLevel},

163 + time: number,

164 +) {

165 + if (enableProfiling) {

166 + runIdCounter++;

167 +

168 + if (profilingState !== null) {

169 + profilingState[PRIORITY] = task.priorityLevel;

170 + profilingState[CURRENT_TASK_ID] = task.id;

171 + profilingState[CURRENT_RUN_ID] = runIdCounter;

172 + }

173 +

174 + if (eventLog !== null) {

175 + logEvent([TaskRunEvent, time, task.id, runIdCounter]);

176 + }

177 + }

178 +}

179 +

180 +export function markTaskYield(task: {id: number}, time: number) {

181 + if (enableProfiling) {

182 + if (profilingState !== null) {

183 + profilingState[PRIORITY] = NoPriority;

184 + profilingState[CURRENT_TASK_ID] = 0;

185 + profilingState[CURRENT_RUN_ID] = 0;

186 + }

187 +

188 + if (eventLog !== null) {

189 + logEvent([TaskYieldEvent, time, task.id, runIdCounter]);

190 + }

191 + }

192 +}

193 +

194 +export function markSchedulerSuspended(time: number) {

195 + if (enableProfiling) {

196 + mainThreadIdCounter++;

197 +

198 + if (eventLog !== null) {

199 + logEvent([SchedulerSuspendEvent, time, mainThreadIdCounter]);

200 + }

201 + }

202 +}

203 +

204 +export function markSchedulerUnsuspended(time: number) {

205 + if (enableProfiling) {

206 + if (eventLog !== null) {

207 + logEvent([SchedulerResumeEvent, time, mainThreadIdCounter]);

208 + }

209 + }

210 +}

packages/scheduler/src/__tests__/SchedulerDOM-test.js

+7 -3

@@ -59,11 +59,15 @@ describe('SchedulerDOM', () => {

59 runPostMessageCallbacks(config);

60 }

62 - let frameSize = 33;

63 - let startOfLatestFrame = 0;

64 - let currentTime = 0;

62 + let frameSize;

63 + let startOfLatestFrame;

64 + let currentTime;

66 beforeEach(() => {

67 + frameSize = 33;

68 + startOfLatestFrame = 0;

69 + currentTime = 0;

70 +

71 delete global.performance;

72 global.requestAnimationFrame = function(cb) {

73 return rAFCallbacks.push(() => {

packages/scheduler/src/__tests__/SchedulerProfiling-test.js new

+449

@@ -0,0 +1,449 @@

1 +/**

2 + * Copyright (c) Facebook, Inc. and its affiliates.

3 + *

4 + * This source code is licensed under the MIT license found in the

5 + * LICENSE file in the root directory of this source tree.

6 + *

7 + * @emails react-core

8 + * @jest-environment node

9 + */

10 +

11 +/* eslint-disable no-for-of-loops/no-for-of-loops */

12 +

13 +'use strict';

14 +

15 +let Scheduler;

16 +let sharedProfilingArray;

17 +// let runWithPriority;

18 +let ImmediatePriority;

19 +let UserBlockingPriority;

20 +let NormalPriority;

21 +let LowPriority;

22 +let IdlePriority;

23 +let scheduleCallback;

24 +let cancelCallback;

25 +// let wrapCallback;

26 +// let getCurrentPriorityLevel;

27 +// let shouldYield;

28 +

29 +function priorityLevelToString(priorityLevel) {

30 + switch (priorityLevel) {

31 + case ImmediatePriority:

32 + return 'Immediate';

33 + case UserBlockingPriority:

34 + return 'User-blocking';

35 + case NormalPriority:

36 + return 'Normal';

37 + case LowPriority:

38 + return 'Low';

39 + case IdlePriority:

40 + return 'Idle';

41 + default:

42 + return null;

43 + }

44 +}

45 +

46 +describe('Scheduler', () => {

47 + if (!__PROFILE__) {

48 + // The tests in this suite only apply when profiling is on

49 + it('profiling APIs are not available', () => {

50 + Scheduler = require('scheduler');

51 + expect(Scheduler.unstable_stopLoggingProfilingEvents).toBe(null);

52 + expect(Scheduler.unstable_sharedProfilingBuffer).toBe(null);

53 + });

54 + return;

55 + }

56 +

57 + beforeEach(() => {

58 + jest.resetModules();

59 + jest.mock('scheduler', () => require('scheduler/unstable_mock'));

60 + Scheduler = require('scheduler');

61 +

62 + sharedProfilingArray = new Int32Array(

63 + Scheduler.unstable_sharedProfilingBuffer,

64 + );

65 +

66 + // runWithPriority = Scheduler.unstable_runWithPriority;

67 + ImmediatePriority = Scheduler.unstable_ImmediatePriority;

68 + UserBlockingPriority = Scheduler.unstable_UserBlockingPriority;

69 + NormalPriority = Scheduler.unstable_NormalPriority;

70 + LowPriority = Scheduler.unstable_LowPriority;

71 + IdlePriority = Scheduler.unstable_IdlePriority;

72 + scheduleCallback = Scheduler.unstable_scheduleCallback;

73 + cancelCallback = Scheduler.unstable_cancelCallback;

74 + // wrapCallback = Scheduler.unstable_wrapCallback;

75 + // getCurrentPriorityLevel = Scheduler.unstable_getCurrentPriorityLevel;

76 + // shouldYield = Scheduler.unstable_shouldYield;

77 + });

78 +

79 + const PRIORITY = 0;

80 + const CURRENT_TASK_ID = 1;

81 + const CURRENT_RUN_ID = 2;

82 + const QUEUE_SIZE = 3;

83 +

84 + afterEach(() => {

85 + if (sharedProfilingArray[QUEUE_SIZE] !== 0) {

86 + throw Error(

87 + 'Test exited, but the shared profiling buffer indicates that a task ' +

88 + 'is still running',

89 + );

90 + }

91 + });

92 +

93 + const TaskStartEvent = 1;

94 + const TaskCompleteEvent = 2;

95 + const TaskErrorEvent = 3;

96 + const TaskCancelEvent = 4;

97 + const TaskRunEvent = 5;

98 + const TaskYieldEvent = 6;

99 + const SchedulerSuspendEvent = 7;

100 + const SchedulerResumeEvent = 8;

101 +

102 + function stopProfilingAndPrintFlamegraph() {

103 + const eventLog = new Int32Array(

104 + Scheduler.unstable_stopLoggingProfilingEvents(),

105 + );

106 +

107 + const tasks = new Map();

108 + const mainThreadRuns = [];

109 +

110 + let i = 0;

111 + processLog: while (i < eventLog.length) {

112 + const instruction = eventLog[i];

113 + const time = eventLog[i + 1];

114 + switch (instruction) {

115 + case 0: {

116 + break processLog;

117 + }

118 + case TaskStartEvent: {

119 + const taskId = eventLog[i + 2];

120 + const priorityLevel = eventLog[i + 3];

121 + const task = {

122 + id: taskId,

123 + priorityLevel,

124 + label: null,

125 + start: time,

126 + end: -1,

127 + exitStatus: null,

128 + runs: [],

129 + };

130 + tasks.set(taskId, task);

131 + i += 4;

132 + break;

133 + }

134 + case TaskCompleteEvent: {

135 + const taskId = eventLog[i + 2];

136 + const task = tasks.get(taskId);

137 + if (task === undefined) {

138 + throw Error('Task does not exist.');

139 + }

140 + task.end = time;

141 + task.exitStatus = 'completed';

142 + i += 3;

143 + break;

144 + }

145 + case TaskErrorEvent: {

146 + const taskId = eventLog[i + 2];

147 + const task = tasks.get(taskId);

148 + if (task === undefined) {

149 + throw Error('Task does not exist.');

150 + }

151 + task.end = time;

152 + task.exitStatus = 'errored';

153 + i += 3;

154 + break;

155 + }

156 + case TaskCancelEvent: {

157 + const taskId = eventLog[i + 2];

158 + const task = tasks.get(taskId);

159 + if (task === undefined) {

160 + throw Error('Task does not exist.');

161 + }

162 + task.end = time;

163 + task.exitStatus = 'canceled';

164 + i += 3;

165 + break;

166 + }

167 + case TaskRunEvent:

168 + case TaskYieldEvent: {

169 + const taskId = eventLog[i + 2];

170 + const task = tasks.get(taskId);

171 + if (task === undefined) {

172 + throw Error('Task does not exist.');

173 + }

174 + task.runs.push(time);

175 + i += 4;

176 + break;

177 + }

178 + case SchedulerSuspendEvent:

179 + case SchedulerResumeEvent: {

180 + mainThreadRuns.push(time);

181 + i += 3;

182 + break;

183 + }

184 + default: {

185 + throw Error('Unknown instruction type: ' + instruction);

186 + }

187 + }

188 + }

189 +

190 + // Now we can render the tasks as a flamegraph.

191 + const labelColumnWidth = 30;

192 + const msPerChar = 50;

193 +

194 + let result = '';

195 +

196 + const mainThreadLabelColumn = '!!! Main thread ';

197 + let mainThreadTimelineColumn = '';

198 + let isMainThreadBusy = false;

199 + for (const time of mainThreadRuns) {

200 + const index = time / msPerChar;

201 + mainThreadTimelineColumn += (isMainThreadBusy ? '█' : ' ').repeat(

202 + index - mainThreadTimelineColumn.length,

203 + );

204 + isMainThreadBusy = !isMainThreadBusy;

205 + }

206 + result += `${mainThreadLabelColumn}│${mainThreadTimelineColumn}\n`;

207 +

208 + const tasksByPriority = Array.from(tasks.values()).sort(

209 + (t1, t2) => t1.priorityLevel - t2.priorityLevel,

210 + );

211 +

212 + for (const task of tasksByPriority) {

213 + let label = task.label;

214 + if (label === undefined) {

215 + label = 'Task';

216 + }

217 + let labelColumn = `Task ${task.id} [${priorityLevelToString(

218 + task.priorityLevel,

219 + )}]`;

220 + labelColumn += ' '.repeat(labelColumnWidth - labelColumn.length - 1);

221 +

222 + // Add empty space up until the start mark

223 + let timelineColumn = ' '.repeat(task.start / msPerChar);

224 +

225 + let isRunning = false;

226 + for (const time of task.runs) {

227 + const index = time / msPerChar;

228 + timelineColumn += (isRunning ? '█' : '░').repeat(

229 + index - timelineColumn.length,

230 + );

231 + isRunning = !isRunning;

232 + }

233 +

234 + const endIndex = task.end / msPerChar;

235 + timelineColumn += (isRunning ? '█' : '░').repeat(

236 + endIndex - timelineColumn.length,

237 + );

238 +

239 + if (task.exitStatus !== 'completed') {

240 + timelineColumn += `🡐 ${task.exitStatus}`;

241 + }

242 +

243 + result += `${labelColumn}│${timelineColumn}\n`;

244 + }

245 +

246 + return '\n' + result;

247 + }

248 +

249 + function getProfilingInfo() {

250 + const queueSize = sharedProfilingArray[QUEUE_SIZE];

251 + if (queueSize === 0) {

252 + return 'Empty Queue';

253 + }

254 + const priorityLevel = sharedProfilingArray[PRIORITY];

255 + if (priorityLevel === 0) {

256 + return 'Suspended, Queue Size: ' + queueSize;

257 + }

258 + return (

259 + `Task: ${sharedProfilingArray[CURRENT_TASK_ID]}, ` +

260 + `Run: ${sharedProfilingArray[CURRENT_RUN_ID]}, ` +

261 + `Priority: ${priorityLevelToString(priorityLevel)}, ` +

262 + `Queue Size: ${sharedProfilingArray[QUEUE_SIZE]}`

263 + );

264 + }

265 +

266 + it('creates a basic flamegraph', () => {

267 + Scheduler.unstable_startLoggingProfilingEvents();

268 +

269 + Scheduler.unstable_advanceTime(100);

270 + scheduleCallback(

271 + NormalPriority,

272 + () => {

273 + Scheduler.unstable_advanceTime(300);

274 + Scheduler.unstable_yieldValue(getProfilingInfo());

275 + scheduleCallback(

276 + UserBlockingPriority,

277 + () => {

278 + Scheduler.unstable_yieldValue(getProfilingInfo());

279 + Scheduler.unstable_advanceTime(300);

280 + },

281 + {label: 'Bar'},

282 + );

283 + Scheduler.unstable_advanceTime(100);

284 + Scheduler.unstable_yieldValue('Yield');

285 + return () => {

286 + Scheduler.unstable_yieldValue(getProfilingInfo());

287 + Scheduler.unstable_advanceTime(300);

288 + };

289 + },

290 + {label: 'Foo'},

291 + );

292 + expect(Scheduler).toFlushAndYieldThrough([

293 + 'Task: 1, Run: 1, Priority: Normal, Queue Size: 1',

294 + 'Yield',

295 + ]);

296 + Scheduler.unstable_advanceTime(100);

297 + expect(Scheduler).toFlushAndYield([

298 + 'Task: 2, Run: 2, Priority: User-blocking, Queue Size: 2',

299 + 'Task: 1, Run: 3, Priority: Normal, Queue Size: 1',

300 + ]);

301 +

302 + expect(getProfilingInfo()).toEqual('Empty Queue');

303 +

304 + expect(stopProfilingAndPrintFlamegraph()).toEqual(

305 + `

306 +!!! Main thread │ ██

307 +Task 2 [User-blocking] │ ░░░░██████

308 +Task 1 [Normal] │ ████████░░░░░░░░██████

309 +`,

310 + );

311 + });

312 +

313 + it('marks when a task is canceled', () => {

314 + Scheduler.unstable_startLoggingProfilingEvents();

315 +

316 + const task = scheduleCallback(NormalPriority, () => {

317 + Scheduler.unstable_yieldValue(getProfilingInfo());

318 + Scheduler.unstable_advanceTime(300);

319 + Scheduler.unstable_yieldValue('Yield');

320 + return () => {

321 + Scheduler.unstable_yieldValue('Continuation');

322 + Scheduler.unstable_advanceTime(200);

323 + };

324 + });

325 +

326 + expect(Scheduler).toFlushAndYieldThrough([

327 + 'Task: 1, Run: 1, Priority: Normal, Queue Size: 1',

328 + 'Yield',

329 + ]);

330 + Scheduler.unstable_advanceTime(100);

331 +

332 + cancelCallback(task);

333 +

334 + // Advance more time. This should not affect the size of the main

335 + // thread row, since the Scheduler queue is empty.

336 + Scheduler.unstable_advanceTime(1000);

337 + expect(Scheduler).toFlushWithoutYielding();

338 +

339 + // The main thread row should end when the callback is cancelled.

340 + expect(stopProfilingAndPrintFlamegraph()).toEqual(

341 + `

342 +!!! Main thread │ ██

343 +Task 1 [Normal] │██████░░🡐 canceled

344 +`,

345 + );

346 + });

347 +

348 + it('marks when a task errors', () => {

349 + Scheduler.unstable_startLoggingProfilingEvents();

350 +

351 + scheduleCallback(NormalPriority, () => {

352 + Scheduler.unstable_advanceTime(300);

353 + throw Error('Oops');

354 + });

355 +

356 + expect(Scheduler).toFlushAndThrow('Oops');

357 + Scheduler.unstable_advanceTime(100);

358 +

359 + // Advance more time. This should not affect the size of the main

360 + // thread row, since the Scheduler queue is empty.

361 + Scheduler.unstable_advanceTime(1000);

362 + expect(Scheduler).toFlushWithoutYielding();

363 +

364 + // The main thread row should end when the callback is cancelled.

365 + expect(stopProfilingAndPrintFlamegraph()).toEqual(

366 + `

367 +!!! Main thread │

368 +Task 1 [Normal] │██████🡐 errored

369 +`,

370 + );

371 + });

372 +

373 + it('handles cancelling a task that already finished', () => {

374 + Scheduler.unstable_startLoggingProfilingEvents();

375 +

376 + const task = scheduleCallback(NormalPriority, () => {

377 + Scheduler.unstable_yieldValue('A');

378 + Scheduler.unstable_advanceTime(1000);

379 + });

380 + expect(Scheduler).toFlushAndYield(['A']);

381 + cancelCallback(task);

382 + expect(stopProfilingAndPrintFlamegraph()).toEqual(

383 + `

384 +!!! Main thread │

385 +Task 1 [Normal] │████████████████████

386 +`,

387 + );

388 + });

389 +

390 + it('handles cancelling a task multiple times', () => {

391 + Scheduler.unstable_startLoggingProfilingEvents();

392 +

393 + scheduleCallback(

394 + NormalPriority,

395 + () => {

396 + Scheduler.unstable_yieldValue('A');

397 + Scheduler.unstable_advanceTime(1000);

398 + },

399 + {label: 'A'},

400 + );

401 + Scheduler.unstable_advanceTime(200);

402 + const task = scheduleCallback(

403 + NormalPriority,

404 + () => {

405 + Scheduler.unstable_yieldValue('B');

406 + Scheduler.unstable_advanceTime(1000);

407 + },

408 + {label: 'B'},

409 + );

410 + Scheduler.unstable_advanceTime(400);

411 + cancelCallback(task);

412 + cancelCallback(task);

413 + cancelCallback(task);

414 + expect(Scheduler).toFlushAndYield(['A']);

415 + expect(stopProfilingAndPrintFlamegraph()).toEqual(

416 + `

417 +!!! Main thread │████████████

418 +Task 1 [Normal] │░░░░░░░░░░░░████████████████████

419 +Task 2 [Normal] │ ░░░░░░░░🡐 canceled

420 +`,

421 + );

422 + });

423 +

424 + it('handles cancelling a delayed task', () => {

425 + Scheduler.unstable_startLoggingProfilingEvents();

426 + const task = scheduleCallback(

427 + NormalPriority,

428 + () => Scheduler.unstable_yieldValue('A'),

429 + {delay: 1000},

430 + );

431 + cancelCallback(task);

432 + expect(Scheduler).toFlushWithoutYielding();

433 + expect(stopProfilingAndPrintFlamegraph()).toEqual(

434 + `

435 +!!! Main thread │

436 +`,

437 + );

438 + });

439 +

440 + it('resizes event log buffer if there are many events', () => {

441 + const tasks = [];

442 + for (let i = 0; i < 5000; i++) {

443 + tasks.push(scheduleCallback(NormalPriority, () => {}));

444 + }

445 + expect(getProfilingInfo()).toEqual('Suspended, Queue Size: 5000');

446 + tasks.forEach(task => cancelCallback(task));

447 + expect(getProfilingInfo()).toEqual('Empty Queue');

448 + });

449 +});

packages/scheduler/src/forks/SchedulerFeatureFlags.www.js

@@ -13,3 +13,5 @@ export const {

13 requestTimerEventBeforeFirstFrame,

14 enableMessageLoopImplementation,

15 } = require('SchedulerFeatureFlags');

16 +

17 +export const enableProfiling = __PROFILE__;

packages/scheduler/src/forks/SchedulerHostConfig.default.js

+11 -5

@@ -53,8 +53,9 @@ if (

53 }

54 }

55 };

56 + const initialTime = Date.now();

57 getCurrentTime = function() {

57 - return Date.now();

58 + return Date.now() - initialTime;

59 };

60 requestHostCallback = function(cb) {

61 if (_callback !== null) {

@@ -111,10 +112,15 @@ if (

112 typeof requestIdleCallback === 'function' &&

113 typeof cancelIdleCallback === 'function';

114

114 - getCurrentTime =

115 - typeof performance === 'object' && typeof performance.now === 'function'

116 - ? () => performance.now()

117 - : () => Date.now();

115 + if (

116 + typeof performance === 'object' &&

117 + typeof performance.now === 'function'

118 + ) {

119 + getCurrentTime = () => performance.now();

120 + } else {

121 + const initialTime = Date.now();

122 + getCurrentTime = () => Date.now() - initialTime;

123 + }

124

125 let isRAFLoopRunning = false;

126 let isMessageLoopRunning = false;

scripts/rollup/bundles.js

+7 -1

@@ -411,7 +411,13 @@ const bundles = [

411

412 /******* React Scheduler (experimental) *******/

413 {

414 - bundleTypes: [NODE_DEV, NODE_PROD, FB_WWW_DEV, FB_WWW_PROD],

414 + bundleTypes: [

415 + NODE_DEV,

416 + NODE_PROD,

417 + FB_WWW_DEV,

418 + FB_WWW_PROD,

419 + FB_WWW_PROFILING,

420 + ],

421 moduleType: ISOMORPHIC,

422 entry: 'scheduler',

423 global: 'Scheduler',

scripts/rollup/validate/eslintrc.cjs.js

@@ -21,6 +21,11 @@ module.exports = {

21 process: true,

22 setImmediate: true,

23 Buffer: true,

24 +

25 + // Scheduler profiling

26 + SharedArrayBuffer: true,

27 + Int32Array: true,

28 + ArrayBuffer: true,

29 },

30 parserOptions: {

31 ecmaVersion: 5,

scripts/rollup/validate/eslintrc.fb.js

@@ -22,6 +22,11 @@ module.exports = {

22 // Node.js Server Rendering

23 setImmediate: true,

24 Buffer: true,

25 +

26 + // Scheduler profiling

27 + SharedArrayBuffer: true,

28 + Int32Array: true,

29 + ArrayBuffer: true,

30 },

31 parserOptions: {

32 ecmaVersion: 5,

scripts/rollup/validate/eslintrc.rn.js

@@ -21,6 +21,11 @@ module.exports = {

21 // Fabric. See https://github.com/facebook/react/pull/15490

22 // for more information

23 nativeFabricUIManager: true,

24 +

25 + // Scheduler profiling

26 + SharedArrayBuffer: true,

27 + Int32Array: true,

28 + ArrayBuffer: true,

29 },

30 parserOptions: {

31 ecmaVersion: 5,

scripts/rollup/validate/eslintrc.umd.js

@@ -24,6 +24,11 @@ module.exports = {

24 define: true,

25 require: true,

26 global: true,

27 +

28 + // Scheduler profiling

29 + SharedArrayBuffer: true,

30 + Int32Array: true,

31 + ArrayBuffer: true,

32 },

33 parserOptions: {

34 ecmaVersion: 5,