Measure input latency and text render time

src/vs/base/browser/performance.ts

@@ -0,0 +1,262 @@
+/*---------------------------------------------------------------------------------------------
+ *  Copyright (c) Microsoft Corporation. All rights reserved.
+ *  Licensed under the MIT License. See License.txt in the project root for license information.
+ *--------------------------------------------------------------------------------------------*/
+
+export namespace inputLatency {
+
+	// Measurements are recorded as totals, the average is calculated when the final measurements
+	// are created.
+	interface ICumulativeMeasurement {
+		total: number;
+		min: number;
+		max: number;
+	}
+	const totalKeydownTime: ICumulativeMeasurement = { total: 0, min: Number.MAX_VALUE, max: 0 };
+	const totalInputTime: ICumulativeMeasurement = { ...totalKeydownTime };
+	const totalRenderTime: ICumulativeMeasurement = { ...totalKeydownTime };
+	const totalInputLatencyTime: ICumulativeMeasurement = { ...totalKeydownTime };
+	let measurementsCount = 0;
+
+
+
+	// The state of each event, this helps ensure the integrity of the measurement and that
+	// something unexpected didn't happen that could skew the measurement.
+	const enum EventPhase {
+		Before = 0,
+		InProgress = 1,
+		Finished = 2
+	}
+	const state = {
+		keydown: EventPhase.Before,
+		input: EventPhase.Before,
+		render: EventPhase.Before,
+	};
+
+	/**
+	 * Record the start of the keydown event.
+	 */
+	export function onKeyDown() {
+		/** Direct Check C. See explanation in {@link recordIfFinished} */
+		recordIfFinished();
+		performance.mark('inputlatency/start');
+		performance.mark('keydown/start');
+		state.keydown = EventPhase.InProgress;
+		queueMicrotask(markKeyDownEnd);
+	}
+
+	/**
+	 * Mark the end of the keydown event.
+	 */
+	function markKeyDownEnd() {
+		performance.mark('keydown/end');
+		state.keydown = EventPhase.Finished;
+	}
+
+	/**
+	 * Record the start of the beforeinput event.
+	 */
+	export function onBeforeInput() {
+		performance.mark('input/start');
+		state.input = EventPhase.InProgress;
+		/** Schedule Task A. See explanation in {@link recordIfFinished} */
+		scheduleRecordIfFinishedTask();
+	}
+
+	/**
+	 * Record the start of the input event.
+	 */
+	export function onInput() {
+		queueMicrotask(markInputEnd);
+	}
+
+	function markInputEnd() {
+		performance.mark('input/end');
+		state.input = EventPhase.Finished;
+	}
+
+	/**
+	 * Record the start of the keyup event.
+	 */
+	export function onKeyUp() {
+		/** Direct Check D. See explanation in {@link recordIfFinished} */
+		recordIfFinished();
+	}
+
+	/**
+	 * Record the start of the selectionchange event.
+	 */
+	export function onSelectionChange() {
+		/** Direct Check E. See explanation in {@link recordIfFinished} */
+		recordIfFinished();
+	}
+
+	/**
+	 * Record the start of the animation frame performing the rendering.
+	 */
+	export function onRenderStart() {
+		// Render may be triggered during input, but we only measure the following animation frame
+		if (state.keydown === EventPhase.Finished && state.input === EventPhase.Finished && state.render === EventPhase.Before) {
+			// Only measure the first render after keyboard input
+			performance.mark('render/start');
+			state.render = EventPhase.InProgress;
+			queueMicrotask(markRenderEnd);
+			/** Schedule Task B. See explanation in {@link recordIfFinished} */
+			scheduleRecordIfFinishedTask();
+		}
+	}
+
+	/**
+	 * Mark the end of the animation frame performing the rendering.
+	 */
+	function markRenderEnd() {
+		performance.mark('render/end');
+		state.render = EventPhase.Finished;
+	}
+
+	function scheduleRecordIfFinishedTask() {
+		// Here we can safely assume that the `setTimeout` will not be
+		// artificially delayed by 4ms because we schedule it from
+		// event handlers
+		setTimeout(recordIfFinished);
+	}
+
+	/**
+	 * Record the input latency sample if input handling and rendering are finished.
+	 *
+	 * The challenge here is that we want to record the latency in such a way that it includes
+	 * also the layout and painting work the browser does during the animation frame task.
+	 *
+	 * Simply scheduling a new task (via `setTimeout`) from the animation frame task would
+	 * schedule the new task at the end of the task queue (after other code that uses `setTimeout`),
+	 * so we need to use multiple strategies to make sure our task runs before others:
+	 *
+	 * We schedule tasks (A and B):
+	 *    - we schedule a task A (via a `setTimeout` call) when the input starts in `markInputStart`.
+	 *      If the animation frame task is scheduled quickly by the browser, then task A has a very good
+	 *      chance of being the very first task after the animation frame and thus will record the input latency.
+	 *    - however, if the animation frame task is scheduled a bit later, then task A might execute
+	 *      before the animation frame task. We therefore schedule another task B from `markRenderStart`.
+	 *
+	 * We do direct checks in browser event handlers (C, D, E):
+	 *    - if the browser has multiple keydown events queued up, they will be scheduled before the `setTimeout` tasks,
+	 *      so we do a direct check in the keydown event handler (C).
+	 *    - depending on timing, sometimes the animation frame is scheduled even before the `keyup` event, so we
+	 *      do a direct check there too (E).
+	 *    - the browser oftentimes emits a `selectionchange` event after an `input`, so we do a direct check there (D).
+	 */
+	function recordIfFinished() {
+		if (state.keydown === EventPhase.Finished && state.input === EventPhase.Finished && state.render === EventPhase.Finished) {
+			performance.mark('inputlatency/end');
+
+			performance.measure('keydown', 'keydown/start', 'keydown/end');
+			performance.measure('input', 'input/start', 'input/end');
+			performance.measure('render', 'render/start', 'render/end');
+			performance.measure('inputlatency', 'inputlatency/start', 'inputlatency/end');
+
+			addMeasure('keydown', totalKeydownTime);
+			addMeasure('input', totalInputTime);
+			addMeasure('render', totalRenderTime);
+			addMeasure('inputlatency', totalInputLatencyTime);
+
+			// console.info(
+			// 	`input latency=${performance.getEntriesByName('inputlatency')[0].duration.toFixed(1)} [` +
+			// 	`keydown=${performance.getEntriesByName('keydown')[0].duration.toFixed(1)}, ` +
+			// 	`input=${performance.getEntriesByName('input')[0].duration.toFixed(1)}, ` +
+			// 	`render=${performance.getEntriesByName('render')[0].duration.toFixed(1)}` +
+			// 	`]`
+			// );
+
+			measurementsCount++;
+
+			reset();
+		}
+	}
+
+	function addMeasure(entryName: string, cumulativeMeasurement: ICumulativeMeasurement): void {
+		const duration = performance.getEntriesByName(entryName)[0].duration;
+		cumulativeMeasurement.total += duration;
+		cumulativeMeasurement.min = Math.min(cumulativeMeasurement.min, duration);
+		cumulativeMeasurement.max = Math.max(cumulativeMeasurement.max, duration);
+	}
+
+	/**
+	 * Clear the current sample.
+	 */
+	function reset() {
+		performance.clearMarks('keydown/start');
+		performance.clearMarks('keydown/end');
+		performance.clearMarks('input/start');
+		performance.clearMarks('input/end');
+		performance.clearMarks('render/start');
+		performance.clearMarks('render/end');
+		performance.clearMarks('inputlatency/start');
+		performance.clearMarks('inputlatency/end');
+
+		performance.clearMeasures('keydown');
+		performance.clearMeasures('input');
+		performance.clearMeasures('render');
+		performance.clearMeasures('inputlatency');
+
+		state.keydown = EventPhase.Before;
+		state.input = EventPhase.Before;
+		state.render = EventPhase.Before;
+	}
+
+	export interface IInputLatencyMeasurements {
+		keydown: IInputLatencySingleMeasurement;
+		input: IInputLatencySingleMeasurement;
+		render: IInputLatencySingleMeasurement;
+		total: IInputLatencySingleMeasurement;
+		sampleCount: number;
+	}
+
+	export interface IInputLatencySingleMeasurement {
+		average: number;
+		min: number;
+		max: number;
+	}
+
+	/**
+	 * Gets all input latency samples and clears the internal buffers to start recording a new set
+	 * of samples.
+	 */
+	export function getAndClearMeasurements(): IInputLatencyMeasurements | undefined {
+		if (measurementsCount === 0) {
+			return undefined;
+		}
+
+		// Assemble the result
+		const result = {
+			keydown: cumulativeToFinalMeasurement(totalKeydownTime),
+			input: cumulativeToFinalMeasurement(totalInputTime),
+			render: cumulativeToFinalMeasurement(totalRenderTime),
+			total: cumulativeToFinalMeasurement(totalInputLatencyTime),
+			sampleCount: measurementsCount
+		};
+
+		// Clear the cumulative measurements
+		clearCumulativeMeasurement(totalKeydownTime);
+		clearCumulativeMeasurement(totalInputTime);
+		clearCumulativeMeasurement(totalRenderTime);
+		clearCumulativeMeasurement(totalInputLatencyTime);
+		measurementsCount = 0;
+
+		return result;
+	}
+
+	function cumulativeToFinalMeasurement(cumulative: ICumulativeMeasurement): IInputLatencySingleMeasurement {
+		return {
+			average: cumulative.total / measurementsCount,
+			max: cumulative.max,
+			min: cumulative.min,
+		};
+	}
+
+	function clearCumulativeMeasurement(cumulative: ICumulativeMeasurement): void {
+		cumulative.total = 0;
+		cumulative.min = Number.MAX_VALUE;
+		cumulative.max = 0;
+	}
+
+}

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

@@ -7,6 +7,7 @@ import * as browser from 'vs/base/browser/browser';
 import * as dom from 'vs/base/browser/dom';
 import { DomEmitter } from 'vs/base/browser/event';
 import { IKeyboardEvent, StandardKeyboardEvent } from 'vs/base/browser/keyboardEvent';
+import { inputLatency } from 'vs/base/browser/performance';
 import { RunOnceScheduler } from 'vs/base/common/async';
 import { Emitter, Event } from 'vs/base/common/event';
 import { KeyCode } from 'vs/base/common/keyCodes';
@@ -488,6 +489,8 @@ export class TextAreaInput extends Disposable {
 		// so throttle multiple `selectionchange` events that burst in a short period of time.
 		let previousSelectionChangeEventTime = 0;
 		return dom.addDisposableListener(document, 'selectionchange', (e) => {
+			inputLatency.onSelectionChange();
+
 			if (!this._hasFocus) {
 				return;
 			}
@@ -703,6 +706,11 @@ export class TextAreaWrapper extends Disposable implements ICompleteTextAreaWrap
 		super();
 		this._ignoreSelectionChangeTime = 0;
 
+		this._register(this.onKeyDown(() => inputLatency.onKeyDown()));
+		this._register(this.onBeforeInput(() => inputLatency.onBeforeInput()));
+		this._register(this.onInput(() => inputLatency.onInput()));
+		this._register(this.onKeyUp(() => inputLatency.onKeyUp()));
+
 		this._register(dom.addDisposableListener(this._actual, TextAreaSyntethicEvents.Tap, () => this._onSyntheticTap.fire()));
 	}
 

src/vs/editor/browser/view.ts

@@ -49,6 +49,7 @@ import { getThemeTypeSelector, IColorTheme } from 'vs/platform/theme/common/them
 import { EditorOption } from 'vs/editor/common/config/editorOptions';
 import { PointerHandlerLastRenderData } from 'vs/editor/browser/controller/mouseTarget';
 import { BlockDecorations } from 'vs/editor/browser/viewParts/blockDecorations/blockDecorations';
+import { inputLatency } from 'vs/base/browser/performance';
 
 
 export interface IContentWidgetData {
@@ -222,6 +223,7 @@ export class View extends ViewEventHandler {
 	}
 
 	private _flushAccumulatedAndRenderNow(): void {
+		inputLatency.onRenderStart();
 		this._renderNow();
 	}
 

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

@@ -0,0 +1,60 @@
+/*---------------------------------------------------------------------------------------------
+ *  Copyright (c) Microsoft Corporation. All rights reserved.
+ *  Licensed under the MIT License. See License.txt in the project root for license information.
+ *--------------------------------------------------------------------------------------------*/
+
+import { inputLatency } from 'vs/base/browser/performance';
+import { RunOnceScheduler } from 'vs/base/common/async';
+import { Event } from 'vs/base/common/event';
+import { Disposable, MutableDisposable } from 'vs/base/common/lifecycle';
+import { ITelemetryService } from 'vs/platform/telemetry/common/telemetry';
+import { IWorkbenchContribution } from 'vs/workbench/common/contributions';
+import { IEditorService } from 'vs/workbench/services/editor/common/editorService';
+
+export class InputLatencyContrib extends Disposable implements IWorkbenchContribution {
+	private readonly _listener = this._register(new MutableDisposable());
+	private readonly _scheduler: RunOnceScheduler;
+
+	constructor(
+		@IEditorService private readonly _editorService: IEditorService,
+		@ITelemetryService private readonly _telemetryService: ITelemetryService
+	) {
+		super();
+
+		// The current sampling strategy is when the active editor changes, start sampling and
+		// report the results after 60 seconds. It's done this way as we don't want to sample
+		// everything, just somewhat randomly, and using an interval would utilize CPU when the
+		// application is inactive.
+		this._scheduler = this._register(new RunOnceScheduler(() => {
+			this._logSamples();
+			this._setupListener();
+		}, 60000));
+
+		this._setupListener();
+	}
+
+	private _setupListener(): void {
+		this._listener.value = Event.once(this._editorService.onDidActiveEditorChange)(() => this._scheduler.schedule());
+	}
+
+	private _logSamples(): void {
+		const measurements = inputLatency.getAndClearMeasurements();
+		if (!measurements) {
+			return;
+		}
+
+		type PerformanceInputLatencyClassification = {
+			owner: 'tyriar';
+			comment: 'This is a set of samples of the time (in milliseconds) that various events took when typing in the editor';
+			keydown: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; comment: 'The min, max and average time it took for the keydown event to execute.' };
+			input: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; comment: 'The min, max and average time it took for the input event to execute.' };
+			render: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; comment: 'The min, max and average time it took for the render animation frame to execute.' };
+			total: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; comment: 'The min, max and average input latency.' };
+			sampleCount: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; comment: 'The number of samples measured.' };
+		};
+
+		type PerformanceInputLatencyEvent = inputLatency.IInputLatencyMeasurements;
+
+		this._telemetryService.publicLog2<PerformanceInputLatencyEvent, PerformanceInputLatencyClassification>('performance.inputLatency', measurements);
+	}
+}

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

@@ -15,6 +15,7 @@ import { PerfviewContrib, PerfviewInput } from 'vs/workbench/contrib/performance
 import { IEditorService } from 'vs/workbench/services/editor/common/editorService';
 import { InstantiationService, Trace } from 'vs/platform/instantiation/common/instantiationService';
 import { EventProfiling } from 'vs/base/common/event';
+import { InputLatencyContrib } from 'vs/workbench/contrib/performance/browser/inputLatencyContrib';
 
 // -- startup performance view
 
@@ -127,3 +128,10 @@ registerAction2(class PrintEventProfiling extends Action2 {
 		}
 	}
 });
+
+// -- input latency
+
+Registry.as<IWorkbenchContributionsRegistry>(Extensions.Workbench).registerWorkbenchContribution(
+	InputLatencyContrib,
+	LifecyclePhase.Eventually
+);