Merge pull request #161621 from microsoft/joh/renderer-auto-profile

Explore auto-profiling of the renderer

src/vs/platform/native/common/native.ts

@@ -163,6 +163,11 @@ export interface ICommonNativeHostService {
 	toggleSharedProcessWindow(): Promise<void>;
 	sendInputEvent(event: MouseInputEvent): Promise<void>;
 
+	// Perf Introspection
+	startHeartbeat(session: string): Promise<boolean>;
+	sendHeartbeat(session: string): Promise<boolean>;
+	stopHeartbeat(session: string): Promise<boolean>;
+
 	// Connectivity
 	resolveProxy(url: string): Promise<string | undefined>;
 	findFreePort(startPort: number, giveUpAfter: number, timeout: number, stride?: number): Promise<number>;

src/vs/platform/native/electron-main/nativeHostMainService.ts

@@ -41,6 +41,8 @@ import { isWorkspaceIdentifier, toWorkspaceIdentifier } from 'vs/platform/worksp
 import { IWorkspacesManagementMainService } from 'vs/platform/workspaces/electron-main/workspacesManagementMainService';
 import { VSBuffer } from 'vs/base/common/buffer';
 import { hasWSLFeatureInstalled } from 'vs/platform/remote/node/wsl';
+import { WindowProfiler } from 'vs/platform/profiling/electron-main/windowProfiling';
+import { ITelemetryService } from 'vs/platform/telemetry/common/telemetry';
 
 export interface INativeHostMainService extends AddFirstParameterToFunctions<ICommonNativeHostService, Promise<unknown> /* only methods, not events */, number | undefined /* window ID */> { }
 
@@ -59,7 +61,8 @@ export class NativeHostMainService extends Disposable implements INativeHostMain
 		@ILogService private readonly logService: ILogService,
 		@IProductService private readonly productService: IProductService,
 		@IThemeMainService private readonly themeMainService: IThemeMainService,
-		@IWorkspacesManagementMainService private readonly workspacesManagementMainService: IWorkspacesManagementMainService
+		@IWorkspacesManagementMainService private readonly workspacesManagementMainService: IWorkspacesManagementMainService,
+		@ITelemetryService private readonly telemetryService: ITelemetryService,
 	) {
 		super();
 	}
@@ -777,6 +780,44 @@ export class NativeHostMainService extends Disposable implements INativeHostMain
 
 	//#endregion
 
+	// #region Performance
+
+	private readonly _profilingSessions = new Map<number, WindowProfiler>();
+
+	async startHeartbeat(windowId: number | undefined, sessionId: string): Promise<boolean> {
+		const win = this.windowById(windowId);
+		if (!win || !win.win) {
+			return false;
+		}
+		if (!this._profilingSessions.has(win.id)) {
+			const session = new WindowProfiler(win.win, sessionId, this.logService, this.telemetryService);
+			this._profilingSessions.set(win.id, session);
+			session.start();
+		}
+		return true;
+	}
+
+	async sendHeartbeat(windowId: number | undefined, _sessionId: string): Promise<boolean> {
+		const win = this.windowById(windowId);
+		if (!win || !this._profilingSessions.has(win.id)) {
+			return false;
+		}
+		this._profilingSessions.get(win.id)!.receiveHeartbeat();
+		return false;
+	}
+
+	async stopHeartbeat(windowId: number | undefined, _sessionId: string): Promise<boolean> {
+		const win = this.windowById(windowId);
+		if (!win || !this._profilingSessions.has(win.id)) {
+			return false;
+		}
+		this._profilingSessions.get(win.id)!.stop();
+		this._profilingSessions.delete(win.id);
+		return false;
+	}
+
+	// #endregion
+
 
 	//#region Registry (windows)
 

src/vs/platform/profiling/common/profiling.ts

@@ -48,7 +48,7 @@ export namespace Utils {
 	export function rewriteAbsolutePaths(profile: IV8Profile, replace: string = 'noAbsolutePaths') {
 		for (const node of profile.nodes) {
 			if (node.callFrame && node.callFrame.url) {
-				if (isAbsolute(node.callFrame.url) || /^\w[\w\d+.-]*:\/\/\//.test(node.callFrame.url)) {
+				if (isAbsolute(node.callFrame.url) || /^\w[\w\d+.-]*:\/\/\/?/.test(node.callFrame.url)) {
 					node.callFrame.url = join(replace, basename(node.callFrame.url));
 				}
 			}

src/vs/platform/profiling/electron-main/windowProfiling.ts

@@ -0,0 +1,261 @@
+/*---------------------------------------------------------------------------------------------
+ *  Copyright (c) Microsoft Corporation. All rights reserved.
+ *  Licensed under the MIT License. See License.txt in the project root for license information.
+ *--------------------------------------------------------------------------------------------*/
+
+import type { Profile, ProfileNode, ProfileResult } from 'v8-inspect-profiler';
+import { BrowserWindow } from 'electron';
+import { timeout } from 'vs/base/common/async';
+import { DisposableStore, toDisposable } from 'vs/base/common/lifecycle';
+import { ILogService } from 'vs/platform/log/common/log';
+import { Promises } from 'vs/base/node/pfs';
+import { tmpdir } from 'os';
+import { join } from 'vs/base/common/path';
+import { ITelemetryService } from 'vs/platform/telemetry/common/telemetry';
+import { Utils } from 'vs/platform/profiling/common/profiling';
+
+
+type TelemetrySampleData = {
+	sessionId: string;
+	selfTime: number;
+	totalTime: number;
+	functionName: string;
+	callstack: string;
+};
+
+type TelemetrySampleDataClassification = {
+	owner: 'jrieken';
+	comment: 'A callstack that took a long time to execute';
+	sessionId: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; comment: 'Session identifier that allows to correlate samples from one profile' };
+	selfTime: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; comment: 'Self time of the sample' };
+	totalTime: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; comment: 'Total time of the sample' };
+	functionName: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; comment: 'The name of the sample' };
+	callstack: { classification: 'CallstackOrException'; purpose: 'PerformanceAndHealth'; comment: 'The stacktrace leading into the sample' };
+};
+
+class Node {
+
+	// these are set later
+	parent: Node | undefined;
+	children: Node[] = [];
+	selfTime: number = -1;
+	totalTime: number = -1;
+
+	constructor(
+		readonly node: ProfileNode,
+		readonly callFrame: typeof node.callFrame,
+	) {
+		// noop
+	}
+
+	toString() {
+		return `${this.callFrame.url}#${this.callFrame.functionName}@${this.callFrame.lineNumber}:${this.callFrame.columnNumber}`;
+	}
+
+	static makeTotals(call: Node) {
+		if (call.totalTime !== -1) {
+			return call.totalTime;
+		}
+		let result = call.selfTime;
+		for (const child of call.children) {
+			result += Node.makeTotals(child);
+		}
+		call.totalTime = result;
+		return result;
+	}
+}
+
+export class WindowProfiler {
+
+	private _profileAtOrAfter: number = 0;
+	private _session = new DisposableStore();
+	private _isProfiling?: Promise<any>;
+
+	private _isStarted: boolean = false;
+
+	constructor(
+		private readonly _window: BrowserWindow,
+		private readonly _sessionId: string,
+		@ILogService private readonly _logService: ILogService,
+		@ITelemetryService private readonly _telemetryService: ITelemetryService,
+	) {
+		// noop
+	}
+
+	async stop() {
+
+		await this._isProfiling;
+
+		this._logService.warn('[perf] STOPPING to monitor renderer', this._sessionId);
+		this._session.clear();
+
+		try {
+			const inspector = this._window.webContents.debugger;
+			await inspector.sendCommand('Profiler.disable');
+			inspector.detach();
+		} catch (error) {
+			this._logService.error('[perf] FAILED to disable profiler', this._sessionId);
+		}
+	}
+
+	receiveHeartbeat(): void {
+		this._profileAtOrAfter = Date.now() + 1000;
+		// this._logService.info('[perf] received heartbeat', this.id);
+	}
+
+	async start() {
+		if (this._isStarted) {
+			this._logService.warn('[perf] already STARTED, ignoring request', this._sessionId);
+			return;
+		}
+
+		try {
+			const inspector = this._window.webContents.debugger;
+			inspector.attach();
+			await inspector.sendCommand('Profiler.enable');
+		} catch (error) {
+			this._logService.error('[perf] FAILED to enable profiler', this._sessionId);
+			return;
+		}
+
+		this._logService.warn('[perf] started to EXPECT frequent heartbeat', this._sessionId);
+
+		this._session.clear();
+		this._profileAtOrAfter = Date.now();
+
+		const handle = setInterval(() => {
+			if (Date.now() >= this._profileAtOrAfter) {
+				clearInterval(handle);
+				this._captureRendererProfile();
+			}
+		}, 500);
+
+		this._session.add(toDisposable(() => {
+			this._isStarted = false;
+			clearInterval(handle);
+		}));
+	}
+
+
+	private async _captureRendererProfile(): Promise<void> {
+		this._logService.warn('[perf] MISSED heartbeat, trying to profile renderer', this._sessionId);
+
+		const profiling = (async () => {
+			const inspector = this._window.webContents.debugger;
+			await inspector.sendCommand('Profiler.start');
+			this._logService.warn('[perf] profiling STARTED', this._sessionId);
+			await timeout(5000);
+			const res: ProfileResult = await inspector.sendCommand('Profiler.stop');
+			this._logService.warn('[perf] profiling DONE', this._sessionId);
+			await this._store(res.profile);
+			this._digest(res.profile);
+		})();
+
+		this._isProfiling = profiling
+			.catch(err => {
+				this._logService.error('[perf] profiling the renderer FAILED', this._sessionId);
+				this._logService.error(err);
+			}).finally(() => {
+				this._isProfiling = undefined;
+			});
+	}
+
+	private async _store(profile: Profile): Promise<void> {
+		try {
+			const path = join(tmpdir(), `renderer-profile-${Date.now()}.cpuprofile`);
+			await Promises.writeFile(path, JSON.stringify(profile));
+			this._logService.info('[perf] stored profile to DISK', this._sessionId, path);
+		} catch (error) {
+			this._logService.error('[perf] FAILED to write profile to disk', this._sessionId, error);
+		}
+	}
+
+	private _digest(profile: Profile): void {
+		// https://chromedevtools.github.io/devtools-protocol/tot/Profiler/#type-Profile
+
+		if (!profile.samples || !profile.timeDeltas) {
+			this._logService.warn('[perf] INVALID profile: no samples or timeDeltas', this._sessionId);
+			return;
+		}
+
+		// PII removal - no absolute paths
+		Utils.rewriteAbsolutePaths(profile, 'piiRemoved');
+
+		// create nodes
+		const all = new Map<number, Node>();
+		for (const node of profile.nodes) {
+			all.set(node.id, new Node(node, node.callFrame));
+		}
+
+		// set children/parents
+		for (const node of profile.nodes) {
+			if (node.children) {
+				const parent = all.get(node.id)!;
+				for (const id of node.children) {
+					const child = all.get(id)!;
+					parent.children.push(child);
+					child.parent = parent;
+				}
+			}
+		}
+
+		// SELF times
+		const duration = (profile.endTime - profile.startTime);
+		let lastNodeTime = duration - profile.timeDeltas[0];
+		for (let i = 0; i < profile.samples.length - 1; i++) {
+			const sample = profile.samples[i];
+			const node = all.get(sample);
+			if (node) {
+				const duration = profile.timeDeltas[i + 1];
+				node.selfTime += duration;
+				lastNodeTime -= duration;
+			}
+		}
+		const lastNode = all.get(profile.samples[profile.samples.length - 1]);
+		if (lastNode) {
+			lastNode.selfTime += lastNodeTime;
+		}
+
+		// TOTAL times
+		all.forEach(Node.makeTotals);
+
+		const sorted = Array.from(all.values()).sort((a, b) => b.selfTime - a.selfTime);
+
+		if (sorted[0].callFrame.functionName === '(idle)') {
+			this._logService.warn('[perf] top stack is IDLE, ignoring this profile...', this._sessionId);
+			this._telemetryService.publicLog2<TelemetrySampleData, TelemetrySampleDataClassification>('prof.sample', {
+				sessionId: this._sessionId,
+				selfTime: 0,
+				totalTime: 0,
+				functionName: '(idle)',
+				callstack: ''
+			});
+			return;
+		}
+
+		for (let i = 0; i < sorted.length; i++) {
+			if (i > 4) {
+				// report top 5
+				break;
+			}
+			const node = sorted[i];
+			const callstack: string[] = [];
+			let candidate: Node | undefined = node;
+			while (candidate) {
+				callstack.push(candidate.toString());
+				candidate = candidate.parent;
+			}
+
+			const data: TelemetrySampleData = {
+				sessionId: this._sessionId,
+				selfTime: node.selfTime / 1000,
+				totalTime: node.totalTime / 1000,
+				functionName: node.callFrame.functionName,
+				callstack: callstack.join('\n')
+			};
+			this._telemetryService.publicLog2<TelemetrySampleData, TelemetrySampleDataClassification>('prof.freeze.sample', data);
+
+			console.log(data);
+		}
+	}
+}

src/vs/workbench/contrib/performance/electron-sandbox/performance.contribution.ts

@@ -8,6 +8,14 @@ import { Registry } from 'vs/platform/registry/common/platform';
 import { Extensions, IWorkbenchContributionsRegistry } from 'vs/workbench/common/contributions';
 import { StartupProfiler } from './startupProfiler';
 import { StartupTimings } from './startupTimings';
+import { RendererProfiling } from 'vs/workbench/contrib/performance/electron-sandbox/rendererAutoProfiler';
+
+
+Registry.as<IWorkbenchContributionsRegistry>(Extensions.Workbench).registerWorkbenchContribution(
+	RendererProfiling,
+	'RendererProfiling',
+	LifecyclePhase.Eventually
+);
 
 // -- startup profiler
 

src/vs/workbench/contrib/performance/electron-sandbox/rendererAutoProfiler.ts

@@ -0,0 +1,155 @@
+/*---------------------------------------------------------------------------------------------
+ *  Copyright (c) Microsoft Corporation. All rights reserved.
+ *  Licensed under the MIT License. See License.txt in the project root for license information.
+ *--------------------------------------------------------------------------------------------*/
+
+import { DisposableStore, toDisposable } from 'vs/base/common/lifecycle';
+import { generateUuid } from 'vs/base/common/uuid';
+import { ICommandService } from 'vs/platform/commands/common/commands';
+import { ILogService } from 'vs/platform/log/common/log';
+import { INativeHostService } from 'vs/platform/native/electron-sandbox/native';
+import { ITelemetryService } from 'vs/platform/telemetry/common/telemetry';
+import { IViewDescriptorService } from 'vs/workbench/common/views';
+import { IEditorService } from 'vs/workbench/services/editor/common/editorService';
+import { ITimerService } from 'vs/workbench/services/timer/browser/timerService';
+
+
+export class RendererProfiling {
+
+	private readonly _disposables = new DisposableStore();
+
+	constructor(
+		@ITimerService timerService: ITimerService,
+		@INativeHostService nativeHostService: INativeHostService,
+		@ILogService logService: ILogService,
+		@ICommandService commandService: ICommandService,
+		@ITelemetryService telemetryService: ITelemetryService,
+		@IViewDescriptorService viewsDescriptorService: IViewDescriptorService,
+		@IEditorService editorService: IEditorService,
+	) {
+
+		timerService.whenReady().then(() => {
+
+			// SLOW threshold
+			const slowThreshold = (timerService.startupMetrics.timers.ellapsedRequire / 2) | 0;
+
+			// Keep a record of the last events
+			const eventHistory = new RingBuffer<{ command: string; timestamp: number }>(5);
+			this._disposables.add(commandService.onWillExecuteCommand(e => eventHistory.push({ command: e.commandId, timestamp: Date.now() })));
+
+			const sessionDisposables = this._disposables.add(new DisposableStore());
+
+			const obs = new PerformanceObserver(list => {
+
+				let maxDuration = 0;
+				for (const entry of list.getEntries()) {
+					maxDuration = Math.max(maxDuration, entry.duration);
+				}
+				obs.takeRecords();
+
+				if (maxDuration < slowThreshold) {
+					return;
+				}
+
+				// pause observation, we'll take a detailed look
+				obs.disconnect();
+
+				const sessionId = generateUuid();
+				logService.warn(`[perf] Renderer reported VERY LONG TASK (${maxDuration}ms), starting auto profiling session '${sessionId}'`);
+
+				// all visible views
+				const views = viewsDescriptorService.viewContainers.map(container => {
+					const model = viewsDescriptorService.getViewContainerModel(container);
+					return model.visibleViewDescriptors.map(view => view.id);
+				});
+
+				const editors = editorService.visibleEditors.map(editor => editor.typeId);
+
+				// send telemetry event
+				telemetryService.publicLog2<TelemetryEventData, TelemetryEventClassification>('perf.freeze.events', {
+					sessionId: sessionId,
+					timestamp: Date.now() - maxDuration,
+					recentCommands: JSON.stringify(eventHistory.values()),
+					views: JSON.stringify(views.flat()),
+					editors: JSON.stringify(editors),
+				});
+
+				// start heartbeat monitoring
+				nativeHostService.startHeartbeat(sessionId).then(success => {
+					if (!success) {
+						logService.warn('[perf] FAILED to start heartbeat sending');
+						return;
+					}
+
+					// start sending a repeated heartbeat which is expected to be received by the main side
+					const handle1 = setInterval(() => nativeHostService.sendHeartbeat(sessionId), 500);
+
+					// stop heartbeat after 20s
+					const handle2 = setTimeout(() => sessionDisposables.clear(), 20 * 1000);
+
+					// cleanup
+					// - stop heartbeat
+					// - reconnect perf observer
+					sessionDisposables.add(toDisposable(() => {
+						clearInterval(handle1);
+						clearTimeout(handle2);
+						nativeHostService.stopHeartbeat(sessionId);
+						logService.warn(`[perf] STOPPING to send heartbeat`);
+
+						obs.observe({ entryTypes: ['longtask'] });
+					}));
+				});
+			});
+
+			this._disposables.add(toDisposable(() => obs.disconnect()));
+			obs.observe({ entryTypes: ['longtask'] });
+		});
+	}
+
+	dispose(): void {
+		this._disposables.dispose();
+	}
+}
+
+type TelemetryEventData = {
+	sessionId: string;
+	timestamp: number;
+	recentCommands: string;
+	views: string;
+	editors: string;
+};
+
+type TelemetryEventClassification = {
+	owner: 'jrieken';
+	comment: 'Insight about what happened before/while a long task was reported';
+	sessionId: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; comment: 'Session identifier that allows to correlate CPU samples and events' };
+	timestamp: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; comment: 'Unix time at which the long task approximately happened' };
+	recentCommands: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; comment: 'Events prior to the long task' };
+	views: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; comment: 'Visible views' };
+	editors: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; comment: 'Visible editor' };
+};
+
+class RingBuffer<T> {
+
+	private static _value = {};
+
+	private readonly _data: any[];
+
+	private _index: number = 0;
+	private _size: number = 0;
+
+	constructor(size: number) {
+		this._size = size;
+		this._data = new Array(size);
+		this._data.fill(RingBuffer._value, 0, size);
+	}
+
+	push(value: T): void {
+		this._data[this._index] = value;
+		this._index = (this._index + 1) % this._size;
+	}
+
+	values(): T[] {
+		return [...this._data.slice(this._index), ...this._data.slice(0, this._index)].filter(a => a !== RingBuffer._value);
+	}
+}

src/vs/workbench/test/electron-browser/workbenchTestServices.ts

@@ -188,7 +188,6 @@ export class TestSharedProcessService implements ISharedProcessService {
 }
 
 export class TestNativeHostService implements INativeHostService {
-
 	declare readonly _serviceBrand: undefined;
 
 	readonly windowId = -1;
@@ -276,6 +275,9 @@ export class TestNativeHostService implements INativeHostService {
 	async hasClipboard(format: string, type?: 'selection' | 'clipboard' | undefined): Promise<boolean> { return false; }
 	async sendInputEvent(event: MouseInputEvent): Promise<void> { }
 	async windowsGetStringRegKey(hive: 'HKEY_CURRENT_USER' | 'HKEY_LOCAL_MACHINE' | 'HKEY_CLASSES_ROOT' | 'HKEY_USERS' | 'HKEY_CURRENT_CONFIG', path: string, name: string): Promise<string | undefined> { return undefined; }
+	async startHeartbeat(): Promise<boolean> { return false; }
+	async sendHeartbeat(): Promise<boolean> { return false; }
+	async stopHeartbeat(): Promise<boolean> { return false; }
 }
 
 export function workbenchInstantiationService(disposables = new DisposableStore()): ITestInstantiationService {