[Scheduler Profiler] Use microsecond precision (#17010)
The `performance.now` returns a timestamp in milliseconds as a float. The browser has the option to adjust the precision of the float, but it's usually more precise than a millisecond. However, this precision is lost when the timestamp is logged by the Scheduler profiler, because we store the numbers in an Int32Array. This change multiplies the millisecond float value by 1000, giving us three more degrees of precision.
Andrew Clark committed
Oct 7, 2019 at 09:16 UTC
cd1b167ad40c5c62cf2a0b32451fe2aebb669d08
2 files changed
+25
-21
packages/scheduler/src/SchedulerProfiling.js
+19
-16
@@ -103,13 +103,16 @@ export function stopLoggingProfilingEvents(): ArrayBuffer | null {
103
104
export function markTaskStart(
105
task: {id: number, priorityLevel: PriorityLevel},
106
- time: number,
106
+ ms: number,
107
) {
108
if (enableProfiling) {
109
profilingState[QUEUE_SIZE]++;
110
111
if (eventLog !== null) {
112
- logEvent([TaskStartEvent, time, task.id, task.priorityLevel]);
112
+ // performance.now returns a float, representing milliseconds. When the
113
+ // event is logged, it's coerced to an int. Convert to microseconds to
114
+ // maintain extra degrees of precision.
115
+ logEvent([TaskStartEvent, ms * 1000, task.id, task.priorityLevel]);
116
}
117
}
118
}
@@ -119,7 +122,7 @@ export function markTaskCompleted(
122
id: number,
123
priorityLevel: PriorityLevel,
124
},
122
- time: number,
125
+ ms: number,
126
) {
127
if (enableProfiling) {
128
profilingState[PRIORITY] = NoPriority;
@@ -127,7 +130,7 @@ export function markTaskCompleted(
130
profilingState[QUEUE_SIZE]--;
131
132
if (eventLog !== null) {
130
- logEvent([TaskCompleteEvent, time, task.id]);
133
+ logEvent([TaskCompleteEvent, ms * 1000, task.id]);
134
}
135
}
136
}
@@ -137,13 +140,13 @@ export function markTaskCanceled(
140
id: number,
141
priorityLevel: PriorityLevel,
142
},
140
- time: number,
143
+ ms: number,
144
) {
145
if (enableProfiling) {
146
profilingState[QUEUE_SIZE]--;
147
148
if (eventLog !== null) {
146
- logEvent([TaskCancelEvent, time, task.id]);
149
+ logEvent([TaskCancelEvent, ms * 1000, task.id]);
150
}
151
}
152
}
@@ -153,7 +156,7 @@ export function markTaskErrored(
156
id: number,
157
priorityLevel: PriorityLevel,
158
},
156
- time: number,
159
+ ms: number,
160
) {
161
if (enableProfiling) {
162
profilingState[PRIORITY] = NoPriority;
@@ -161,14 +164,14 @@ export function markTaskErrored(
164
profilingState[QUEUE_SIZE]--;
165
166
if (eventLog !== null) {
164
- logEvent([TaskErrorEvent, time, task.id]);
167
+ logEvent([TaskErrorEvent, ms * 1000, task.id]);
168
}
169
}
170
}
171
172
export function markTaskRun(
173
task: {id: number, priorityLevel: PriorityLevel},
171
- time: number,
174
+ ms: number,
175
) {
176
if (enableProfiling) {
177
runIdCounter++;
@@ -178,37 +181,37 @@ export function markTaskRun(
181
profilingState[CURRENT_RUN_ID] = runIdCounter;
182
183
if (eventLog !== null) {
181
- logEvent([TaskRunEvent, time, task.id, runIdCounter]);
184
+ logEvent([TaskRunEvent, ms * 1000, task.id, runIdCounter]);
185
}
186
}
187
}
188
186
-export function markTaskYield(task: {id: number}, time: number) {
189
+export function markTaskYield(task: {id: number}, ms: number) {
190
if (enableProfiling) {
191
profilingState[PRIORITY] = NoPriority;
192
profilingState[CURRENT_TASK_ID] = 0;
193
profilingState[CURRENT_RUN_ID] = 0;
194
195
if (eventLog !== null) {
193
- logEvent([TaskYieldEvent, time, task.id, runIdCounter]);
196
+ logEvent([TaskYieldEvent, ms * 1000, task.id, runIdCounter]);
197
}
198
}
199
}
200
198
-export function markSchedulerSuspended(time: number) {
201
+export function markSchedulerSuspended(ms: number) {
202
if (enableProfiling) {
203
mainThreadIdCounter++;
204
205
if (eventLog !== null) {
203
- logEvent([SchedulerSuspendEvent, time, mainThreadIdCounter]);
206
+ logEvent([SchedulerSuspendEvent, ms * 1000, mainThreadIdCounter]);
207
}
208
}
209
}
210
208
-export function markSchedulerUnsuspended(time: number) {
211
+export function markSchedulerUnsuspended(ms: number) {
212
if (enableProfiling) {
213
if (eventLog !== null) {
211
- logEvent([SchedulerResumeEvent, time, mainThreadIdCounter]);
214
+ logEvent([SchedulerResumeEvent, ms * 1000, mainThreadIdCounter]);
215
}
216
}
217
}
packages/scheduler/src/__tests__/SchedulerProfiling-test.js
+6
-5
@@ -213,7 +213,8 @@ describe('Scheduler', () => {
213
214
// Now we can render the tasks as a flamegraph.
215
const labelColumnWidth = 30;
216
- const msPerChar = 50;
216
+ // Scheduler event times are in microseconds
217
+ const microsecondsPerChar = 50000;
218
219
let result = '';
220
@@ -221,7 +222,7 @@ describe('Scheduler', () => {
222
let mainThreadTimelineColumn = '';
223
let isMainThreadBusy = true;
224
for (const time of mainThreadRuns) {
224
- const index = time / msPerChar;
225
+ const index = time / microsecondsPerChar;
226
mainThreadTimelineColumn += (isMainThreadBusy ? '█' : '░').repeat(
227
index - mainThreadTimelineColumn.length,
228
);
@@ -244,18 +245,18 @@ describe('Scheduler', () => {
245
labelColumn += ' '.repeat(labelColumnWidth - labelColumn.length - 1);
246
247
// Add empty space up until the start mark
247
- let timelineColumn = ' '.repeat(task.start / msPerChar);
248
+ let timelineColumn = ' '.repeat(task.start / microsecondsPerChar);
249
250
let isRunning = false;
251
for (const time of task.runs) {
251
- const index = time / msPerChar;
252
+ const index = time / microsecondsPerChar;
253
timelineColumn += (isRunning ? '█' : '░').repeat(
254
index - timelineColumn.length,
255
);
256
isRunning = !isRunning;
257
}
258
258
- const endIndex = task.end / msPerChar;
259
+ const endIndex = task.end / microsecondsPerChar;
260
timelineColumn += (isRunning ? '█' : '░').repeat(
261
endIndex - timelineColumn.length,
262
);