diff --git a/src/vs/base/browser/performance.ts b/src/vs/base/browser/performance.ts new file mode 100644 index 0000000000000..38a9cf3c8dbfe --- /dev/null +++ b/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; + } + +} diff --git a/src/vs/editor/browser/controller/textAreaInput.ts b/src/vs/editor/browser/controller/textAreaInput.ts index e5bad61b425c1..0a45967147f29 100644 --- a/src/vs/editor/browser/controller/textAreaInput.ts +++ b/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())); } diff --git a/src/vs/editor/browser/view.ts b/src/vs/editor/browser/view.ts index 9fe5e921ae7fc..85b95fbfe1219 100644 --- a/src/vs/editor/browser/view.ts +++ b/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(); } diff --git a/src/vs/workbench/contrib/performance/browser/inputLatencyContrib.ts b/src/vs/workbench/contrib/performance/browser/inputLatencyContrib.ts new file mode 100644 index 0000000000000..4f85f56e7dd2a --- /dev/null +++ b/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('performance.inputLatency', measurements); + } +} diff --git a/src/vs/workbench/contrib/performance/browser/performance.contribution.ts b/src/vs/workbench/contrib/performance/browser/performance.contribution.ts index b7fbee24b67b8..bf9833721c1fe 100644 --- a/src/vs/workbench/contrib/performance/browser/performance.contribution.ts +++ b/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(Extensions.Workbench).registerWorkbenchContribution( + InputLatencyContrib, + LifecyclePhase.Eventually +);