Skip to content

Commit f952317

Browse files
TyriarTyriar
authored
Merge pull request microsoft#163184 from microsoft/tyriar/measure_latency
Measure input latency and text render time
2 parents 7c62095 + fb4e8de commit f952317

File tree

5 files changed

+340
-0
lines changed

5 files changed

+340
-0
lines changed

‎src/vs/base/browser/performance.ts

Lines changed: 262 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,262 @@
1+
/*---------------------------------------------------------------------------------------------
2+
* Copyright (c) Microsoft Corporation. All rights reserved.
3+
* Licensed under the MIT License. See License.txt in the project root for license information.
4+
*--------------------------------------------------------------------------------------------*/
5+
6+
export namespace inputLatency {
7+
8+
// Measurements are recorded as totals, the average is calculated when the final measurements
9+
// are created.
10+
interface ICumulativeMeasurement {
11+
total: number;
12+
min: number;
13+
max: number;
14+
}
15+
const totalKeydownTime: ICumulativeMeasurement = { total: 0, min: Number.MAX_VALUE, max: 0 };
16+
const totalInputTime: ICumulativeMeasurement = { ...totalKeydownTime };
17+
const totalRenderTime: ICumulativeMeasurement = { ...totalKeydownTime };
18+
const totalInputLatencyTime: ICumulativeMeasurement = { ...totalKeydownTime };
19+
let measurementsCount = 0;
20+
21+
22+
23+
// The state of each event, this helps ensure the integrity of the measurement and that
24+
// something unexpected didn't happen that could skew the measurement.
25+
const enum EventPhase {
26+
Before = 0,
27+
InProgress = 1,
28+
Finished = 2
29+
}
30+
const state = {
31+
keydown: EventPhase.Before,
32+
input: EventPhase.Before,
33+
render: EventPhase.Before,
34+
};
35+
36+
/**
37+
* Record the start of the keydown event.
38+
*/
39+
export function onKeyDown() {
40+
/** Direct Check C. See explanation in {@link recordIfFinished} */
41+
recordIfFinished();
42+
performance.mark('inputlatency/start');
43+
performance.mark('keydown/start');
44+
state.keydown = EventPhase.InProgress;
45+
queueMicrotask(markKeyDownEnd);
46+
}
47+
48+
/**
49+
* Mark the end of the keydown event.
50+
*/
51+
function markKeyDownEnd() {
52+
performance.mark('keydown/end');
53+
state.keydown = EventPhase.Finished;
54+
}
55+
56+
/**
57+
* Record the start of the beforeinput event.
58+
*/
59+
export function onBeforeInput() {
60+
performance.mark('input/start');
61+
state.input = EventPhase.InProgress;
62+
/** Schedule Task A. See explanation in {@link recordIfFinished} */
63+
scheduleRecordIfFinishedTask();
64+
}
65+
66+
/**
67+
* Record the start of the input event.
68+
*/
69+
export function onInput() {
70+
queueMicrotask(markInputEnd);
71+
}
72+
73+
function markInputEnd() {
74+
performance.mark('input/end');
75+
state.input = EventPhase.Finished;
76+
}
77+
78+
/**
79+
* Record the start of the keyup event.
80+
*/
81+
export function onKeyUp() {
82+
/** Direct Check D. See explanation in {@link recordIfFinished} */
83+
recordIfFinished();
84+
}
85+
86+
/**
87+
* Record the start of the selectionchange event.
88+
*/
89+
export function onSelectionChange() {
90+
/** Direct Check E. See explanation in {@link recordIfFinished} */
91+
recordIfFinished();
92+
}
93+
94+
/**
95+
* Record the start of the animation frame performing the rendering.
96+
*/
97+
export function onRenderStart() {
98+
// Render may be triggered during input, but we only measure the following animation frame
99+
if (state.keydown === EventPhase.Finished && state.input === EventPhase.Finished && state.render === EventPhase.Before) {
100+
// Only measure the first render after keyboard input
101+
performance.mark('render/start');
102+
state.render = EventPhase.InProgress;
103+
queueMicrotask(markRenderEnd);
104+
/** Schedule Task B. See explanation in {@link recordIfFinished} */
105+
scheduleRecordIfFinishedTask();
106+
}
107+
}
108+
109+
/**
110+
* Mark the end of the animation frame performing the rendering.
111+
*/
112+
function markRenderEnd() {
113+
performance.mark('render/end');
114+
state.render = EventPhase.Finished;
115+
}
116+
117+
function scheduleRecordIfFinishedTask() {
118+
// Here we can safely assume that the `setTimeout` will not be
119+
// artificially delayed by 4ms because we schedule it from
120+
// event handlers
121+
setTimeout(recordIfFinished);
122+
}
123+
124+
/**
125+
* Record the input latency sample if input handling and rendering are finished.
126+
*
127+
* The challenge here is that we want to record the latency in such a way that it includes
128+
* also the layout and painting work the browser does during the animation frame task.
129+
*
130+
* Simply scheduling a new task (via `setTimeout`) from the animation frame task would
131+
* schedule the new task at the end of the task queue (after other code that uses `setTimeout`),
132+
* so we need to use multiple strategies to make sure our task runs before others:
133+
*
134+
* We schedule tasks (A and B):
135+
* - we schedule a task A (via a `setTimeout` call) when the input starts in `markInputStart`.
136+
* If the animation frame task is scheduled quickly by the browser, then task A has a very good
137+
* chance of being the very first task after the animation frame and thus will record the input latency.
138+
* - however, if the animation frame task is scheduled a bit later, then task A might execute
139+
* before the animation frame task. We therefore schedule another task B from `markRenderStart`.
140+
*
141+
* We do direct checks in browser event handlers (C, D, E):
142+
* - if the browser has multiple keydown events queued up, they will be scheduled before the `setTimeout` tasks,
143+
* so we do a direct check in the keydown event handler (C).
144+
* - depending on timing, sometimes the animation frame is scheduled even before the `keyup` event, so we
145+
* do a direct check there too (E).
146+
* - the browser oftentimes emits a `selectionchange` event after an `input`, so we do a direct check there (D).
147+
*/
148+
function recordIfFinished() {
149+
if (state.keydown === EventPhase.Finished && state.input === EventPhase.Finished && state.render === EventPhase.Finished) {
150+
performance.mark('inputlatency/end');
151+
152+
performance.measure('keydown', 'keydown/start', 'keydown/end');
153+
performance.measure('input', 'input/start', 'input/end');
154+
performance.measure('render', 'render/start', 'render/end');
155+
performance.measure('inputlatency', 'inputlatency/start', 'inputlatency/end');
156+
157+
addMeasure('keydown', totalKeydownTime);
158+
addMeasure('input', totalInputTime);
159+
addMeasure('render', totalRenderTime);
160+
addMeasure('inputlatency', totalInputLatencyTime);
161+
162+
// console.info(
163+
// `input latency=${performance.getEntriesByName('inputlatency')[0].duration.toFixed(1)} [` +
164+
// `keydown=${performance.getEntriesByName('keydown')[0].duration.toFixed(1)}, ` +
165+
// `input=${performance.getEntriesByName('input')[0].duration.toFixed(1)}, ` +
166+
// `render=${performance.getEntriesByName('render')[0].duration.toFixed(1)}` +
167+
// `]`
168+
// );
169+
170+
measurementsCount++;
171+
172+
reset();
173+
}
174+
}
175+
176+
function addMeasure(entryName: string, cumulativeMeasurement: ICumulativeMeasurement): void {
177+
const duration = performance.getEntriesByName(entryName)[0].duration;
178+
cumulativeMeasurement.total += duration;
179+
cumulativeMeasurement.min = Math.min(cumulativeMeasurement.min, duration);
180+
cumulativeMeasurement.max = Math.max(cumulativeMeasurement.max, duration);
181+
}
182+
183+
/**
184+
* Clear the current sample.
185+
*/
186+
function reset() {
187+
performance.clearMarks('keydown/start');
188+
performance.clearMarks('keydown/end');
189+
performance.clearMarks('input/start');
190+
performance.clearMarks('input/end');
191+
performance.clearMarks('render/start');
192+
performance.clearMarks('render/end');
193+
performance.clearMarks('inputlatency/start');
194+
performance.clearMarks('inputlatency/end');
195+
196+
performance.clearMeasures('keydown');
197+
performance.clearMeasures('input');
198+
performance.clearMeasures('render');
199+
performance.clearMeasures('inputlatency');
200+
201+
state.keydown = EventPhase.Before;
202+
state.input = EventPhase.Before;
203+
state.render = EventPhase.Before;
204+
}
205+
206+
export interface IInputLatencyMeasurements {
207+
keydown: IInputLatencySingleMeasurement;
208+
input: IInputLatencySingleMeasurement;
209+
render: IInputLatencySingleMeasurement;
210+
total: IInputLatencySingleMeasurement;
211+
sampleCount: number;
212+
}
213+
214+
export interface IInputLatencySingleMeasurement {
215+
average: number;
216+
min: number;
217+
max: number;
218+
}
219+
220+
/**
221+
* Gets all input latency samples and clears the internal buffers to start recording a new set
222+
* of samples.
223+
*/
224+
export function getAndClearMeasurements(): IInputLatencyMeasurements | undefined {
225+
if (measurementsCount === 0) {
226+
return undefined;
227+
}
228+
229+
// Assemble the result
230+
const result = {
231+
keydown: cumulativeToFinalMeasurement(totalKeydownTime),
232+
input: cumulativeToFinalMeasurement(totalInputTime),
233+
render: cumulativeToFinalMeasurement(totalRenderTime),
234+
total: cumulativeToFinalMeasurement(totalInputLatencyTime),
235+
sampleCount: measurementsCount
236+
};
237+
238+
// Clear the cumulative measurements
239+
clearCumulativeMeasurement(totalKeydownTime);
240+
clearCumulativeMeasurement(totalInputTime);
241+
clearCumulativeMeasurement(totalRenderTime);
242+
clearCumulativeMeasurement(totalInputLatencyTime);
243+
measurementsCount = 0;
244+
245+
return result;
246+
}
247+
248+
function cumulativeToFinalMeasurement(cumulative: ICumulativeMeasurement): IInputLatencySingleMeasurement {
249+
return {
250+
average: cumulative.total / measurementsCount,
251+
max: cumulative.max,
252+
min: cumulative.min,
253+
};
254+
}
255+
256+
function clearCumulativeMeasurement(cumulative: ICumulativeMeasurement): void {
257+
cumulative.total = 0;
258+
cumulative.min = Number.MAX_VALUE;
259+
cumulative.max = 0;
260+
}
261+
262+
}

‎src/vs/editor/browser/controller/textAreaInput.ts

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -7,6 +7,7 @@ import * as browser from 'vs/base/browser/browser';
77
import * as dom from 'vs/base/browser/dom';
88
import { DomEmitter } from 'vs/base/browser/event';
99
import { IKeyboardEvent, StandardKeyboardEvent } from 'vs/base/browser/keyboardEvent';
10+
import { inputLatency } from 'vs/base/browser/performance';
1011
import { RunOnceScheduler } from 'vs/base/common/async';
1112
import { Emitter, Event } from 'vs/base/common/event';
1213
import { KeyCode } from 'vs/base/common/keyCodes';
@@ -488,6 +489,8 @@ export class TextAreaInput extends Disposable {
488489
// so throttle multiple `selectionchange` events that burst in a short period of time.
489490
let previousSelectionChangeEventTime = 0;
490491
return dom.addDisposableListener(document, 'selectionchange', (e) => {
492+
inputLatency.onSelectionChange();
493+
491494
if (!this._hasFocus) {
492495
return;
493496
}
@@ -703,6 +706,11 @@ export class TextAreaWrapper extends Disposable implements ICompleteTextAreaWrap
703706
super();
704707
this._ignoreSelectionChangeTime = 0;
705708

709+
this._register(this.onKeyDown(() => inputLatency.onKeyDown()));
710+
this._register(this.onBeforeInput(() => inputLatency.onBeforeInput()));
711+
this._register(this.onInput(() => inputLatency.onInput()));
712+
this._register(this.onKeyUp(() => inputLatency.onKeyUp()));
713+
706714
this._register(dom.addDisposableListener(this._actual, TextAreaSyntethicEvents.Tap, () => this._onSyntheticTap.fire()));
707715
}
708716

‎src/vs/editor/browser/view.ts

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -49,6 +49,7 @@ import { getThemeTypeSelector, IColorTheme } from 'vs/platform/theme/common/them
4949
import { EditorOption } from 'vs/editor/common/config/editorOptions';
5050
import { PointerHandlerLastRenderData } from 'vs/editor/browser/controller/mouseTarget';
5151
import { BlockDecorations } from 'vs/editor/browser/viewParts/blockDecorations/blockDecorations';
52+
import { inputLatency } from 'vs/base/browser/performance';
5253

5354

5455
export interface IContentWidgetData {
@@ -222,6 +223,7 @@ export class View extends ViewEventHandler {
222223
}
223224

224225
private _flushAccumulatedAndRenderNow(): void {
226+
inputLatency.onRenderStart();
225227
this._renderNow();
226228
}
227229

‎src/vs/workbench/contrib/performance/browser/inputLatencyContrib.ts

Lines changed: 60 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,60 @@
1+
/*---------------------------------------------------------------------------------------------
2+
* Copyright (c) Microsoft Corporation. All rights reserved.
3+
* Licensed under the MIT License. See License.txt in the project root for license information.
4+
*--------------------------------------------------------------------------------------------*/
5+
6+
import { inputLatency } from 'vs/base/browser/performance';
7+
import { RunOnceScheduler } from 'vs/base/common/async';
8+
import { Event } from 'vs/base/common/event';
9+
import { Disposable, MutableDisposable } from 'vs/base/common/lifecycle';
10+
import { ITelemetryService } from 'vs/platform/telemetry/common/telemetry';
11+
import { IWorkbenchContribution } from 'vs/workbench/common/contributions';
12+
import { IEditorService } from 'vs/workbench/services/editor/common/editorService';
13+
14+
export class InputLatencyContrib extends Disposable implements IWorkbenchContribution {
15+
private readonly _listener = this._register(new MutableDisposable());
16+
private readonly _scheduler: RunOnceScheduler;
17+
18+
constructor(
19+
@IEditorService private readonly _editorService: IEditorService,
20+
@ITelemetryService private readonly _telemetryService: ITelemetryService
21+
) {
22+
super();
23+
24+
// The current sampling strategy is when the active editor changes, start sampling and
25+
// report the results after 60 seconds. It's done this way as we don't want to sample
26+
// everything, just somewhat randomly, and using an interval would utilize CPU when the
27+
// application is inactive.
28+
this._scheduler = this._register(new RunOnceScheduler(() => {
29+
this._logSamples();
30+
this._setupListener();
31+
}, 60000));
32+
33+
this._setupListener();
34+
}
35+
36+
private _setupListener(): void {
37+
this._listener.value = Event.once(this._editorService.onDidActiveEditorChange)(() => this._scheduler.schedule());
38+
}
39+
40+
private _logSamples(): void {
41+
const measurements = inputLatency.getAndClearMeasurements();
42+
if (!measurements) {
43+
return;
44+
}
45+
46+
type PerformanceInputLatencyClassification = {
47+
owner: 'tyriar';
48+
comment: 'This is a set of samples of the time (in milliseconds) that various events took when typing in the editor';
49+
keydown: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; comment: 'The min, max and average time it took for the keydown event to execute.' };
50+
input: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; comment: 'The min, max and average time it took for the input event to execute.' };
51+
render: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; comment: 'The min, max and average time it took for the render animation frame to execute.' };
52+
total: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; comment: 'The min, max and average input latency.' };
53+
sampleCount: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; comment: 'The number of samples measured.' };
54+
};
55+
56+
type PerformanceInputLatencyEvent = inputLatency.IInputLatencyMeasurements;
57+
58+
this._telemetryService.publicLog2<PerformanceInputLatencyEvent, PerformanceInputLatencyClassification>('performance.inputLatency', measurements);
59+
}
60+
}

‎src/vs/workbench/contrib/performance/browser/performance.contribution.ts

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -15,6 +15,7 @@ import { PerfviewContrib, PerfviewInput } from 'vs/workbench/contrib/performance
1515
import { IEditorService } from 'vs/workbench/services/editor/common/editorService';
1616
import { InstantiationService, Trace } from 'vs/platform/instantiation/common/instantiationService';
1717
import { EventProfiling } from 'vs/base/common/event';
18+
import { InputLatencyContrib } from 'vs/workbench/contrib/performance/browser/inputLatencyContrib';
1819

1920
// -- startup performance view
2021

@@ -127,3 +128,10 @@ registerAction2(class PrintEventProfiling extends Action2 {
127128
}
128129
}
129130
});
131+
132+
// -- input latency
133+
134+
Registry.as<IWorkbenchContributionsRegistry>(Extensions.Workbench).registerWorkbenchContribution(
135+
InputLatencyContrib,
136+
LifecyclePhase.Eventually
137+
);

0 commit comments

Comments
 (0)