add additional telemetry for connection latency and duration (#149398)

* server: add telemetry for initial connection time

* feat: measure approximate rtt to the remote extension host

* fixup! remove unused property

* fixup! address pr comments

src/vs/platform/telemetry/common/remoteTelemetryChannel.ts

@@ -45,6 +45,10 @@ export class ServerTelemetryChannel extends Disposable implements IServerChannel
 
 				return Promise.resolve();
 			}
+
+			case 'ping': {
+				return;
+			}
 		}
 		// Command we cannot handle so we throw an error
 		throw new Error(`IPC Command ${command} not found`);

src/vs/workbench/contrib/remote/common/remote.contribution.ts

@@ -31,6 +31,7 @@ import { ITelemetryService } from 'vs/platform/telemetry/common/telemetry';
 import { getRemoteName } from 'vs/platform/remote/common/remoteHosts';
 import { IDownloadService } from 'vs/platform/download/common/download';
 import { DownloadServiceChannel } from 'vs/platform/download/common/downloadIpc';
+import { timeout } from 'vs/base/common/async';
 
 export class LabelContribution implements IWorkbenchContribution {
 	constructor(
@@ -165,6 +166,9 @@ class RemoteInvalidWorkspaceDetector extends Disposable implements IWorkbenchCon
 	}
 }
 
+const EXT_HOST_LATENCY_SAMPLES = 5;
+const EXT_HOST_LATENCY_DELAY = 2_000;
+
 class InitialRemoteConnectionHealthContribution implements IWorkbenchContribution {
 
 	constructor(
@@ -185,17 +189,22 @@ class InitialRemoteConnectionHealthContribution implements IWorkbenchContributio
 				owner: 'alexdima';
 				comment: 'The initial connection succeeded';
 				web: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth' };
+				connectionTimeMs: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; comment: 'Time, in ms, until connected'; isMeasurement: true };
 				remoteName: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth' };
 			};
 			type RemoteConnectionSuccessEvent = {
 				web: boolean;
+				connectionTimeMs: number | undefined;
 				remoteName: string | undefined;
 			};
 			this._telemetryService.publicLog2<RemoteConnectionSuccessEvent, RemoteConnectionSuccessClassification>('remoteConnectionSuccess', {
 				web: isWeb,
+				connectionTimeMs: await this._remoteAgentService.getConnection()?.getInitialConnectionTimeMs(),
 				remoteName: getRemoteName(this._environmentService.remoteAuthority)
 			});
 
+			await this._measureExtHostLatency();
+
 		} catch (err) {
 
 			type RemoteConnectionFailureClassification = {
@@ -203,21 +212,56 @@ class InitialRemoteConnectionHealthContribution implements IWorkbenchContributio
 				comment: 'The initial connection failed';
 				web: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth' };
 				remoteName: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth' };
+				connectionTimeMs: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; comment: 'Time, in ms, until connection failure'; isMeasurement: true };
 				message: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth' };
 			};
 			type RemoteConnectionFailureEvent = {
 				web: boolean;
 				remoteName: string | undefined;
+				connectionTimeMs: number | undefined;
 				message: string;
 			};
 			this._telemetryService.publicLog2<RemoteConnectionFailureEvent, RemoteConnectionFailureClassification>('remoteConnectionFailure', {
 				web: isWeb,
+				connectionTimeMs: await this._remoteAgentService.getConnection()?.getInitialConnectionTimeMs(),
 				remoteName: getRemoteName(this._environmentService.remoteAuthority),
 				message: err ? err.message : ''
 			});
 
 		}
 	}
+
+	private async _measureExtHostLatency() {
+		// Get the minimum latency, since latency spikes could be caused by a busy extension host.
+		let bestLatency = Infinity;
+		for (let i = 0; i < EXT_HOST_LATENCY_SAMPLES; i++) {
+			const rtt = await this._remoteAgentService.getRoundTripTime();
+			if (rtt === undefined) {
+				return;
+			}
+			bestLatency = Math.min(bestLatency, rtt / 2);
+			await timeout(EXT_HOST_LATENCY_DELAY);
+		}
+
+		type RemoteConnectionFailureClassification = {
+			owner: 'connor4312';
+			comment: 'The latency to the remote extension host';
+			web: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; comment: 'Whether this is running on web' };
+			remoteName: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; comment: 'Anonymized remote name' };
+			latencyMs: { classification: 'SystemMetaData'; purpose: 'PerformanceAndHealth'; comment: 'Latency to the remote, in milliseconds'; isMeasurement: true };
+		};
+		type RemoteConnectionFailureEvent = {
+			web: boolean;
+			remoteName: string | undefined;
+			latencyMs: number;
+		};
+
+		this._telemetryService.publicLog2<RemoteConnectionFailureEvent, RemoteConnectionFailureClassification>('remoteConnectionFailure', {
+			web: isWeb,
+			remoteName: getRemoteName(this._environmentService.remoteAuthority),
+			latencyMs: bestLatency
+		});
+	}
 }
 
 const workbenchContributionsRegistry = Registry.as<IWorkbenchContributionsRegistry>(WorkbenchExtensions.Workbench);

src/vs/workbench/services/remote/common/abstractRemoteAgentService.ts

@@ -7,7 +7,7 @@ import { Disposable } from 'vs/base/common/lifecycle';
 import { IChannel, IServerChannel, getDelayedChannel, IPCLogger } from 'vs/base/parts/ipc/common/ipc';
 import { Client } from 'vs/base/parts/ipc/common/ipc.net';
 import { IWorkbenchEnvironmentService } from 'vs/workbench/services/environment/common/environmentService';
-import { connectRemoteAgentManagement, IConnectionOptions, ISocketFactory, PersistentConnectionEvent } from 'vs/platform/remote/common/remoteAgentConnection';
+import { connectRemoteAgentManagement, IConnectionOptions, ISocketFactory, ManagementPersistentConnection, PersistentConnectionEvent } from 'vs/platform/remote/common/remoteAgentConnection';
 import { IExtensionHostExitInfo, IRemoteAgentConnection, IRemoteAgentService } from 'vs/workbench/services/remote/common/remoteAgentService';
 import { IRemoteAuthorityResolverService } from 'vs/platform/remote/common/remoteAuthorityResolver';
 import { RemoteAgentConnectionContext, IRemoteAgentEnvironment } from 'vs/platform/remote/common/remoteAgentEnvironment';
@@ -125,6 +125,17 @@ export abstract class AbstractRemoteAgentService extends Disposable implements I
 		);
 	}
 
+	getRoundTripTime(): Promise<number | undefined> {
+		return this._withTelemetryChannel(
+			async channel => {
+				const start = Date.now();
+				await RemoteExtensionEnvironmentChannelClient.ping(channel);
+				return Date.now() - start;
+			},
+			undefined
+		);
+	}
+
 	private _withChannel<R>(callback: (channel: IChannel, connection: IRemoteAgentConnection) => Promise<R>, fallback: R): Promise<R> {
 		const connection = this.getConnection();
 		if (!connection) {
@@ -153,6 +164,8 @@ export class RemoteAgentConnection extends Disposable implements IRemoteAgentCon
 	readonly remoteAuthority: string;
 	private _connection: Promise<Client<RemoteAgentConnectionContext>> | null;
 
+	private _initialConnectionMs: number | undefined;
+
 	constructor(
 		remoteAuthority: string,
 		private readonly _commit: string | undefined,
@@ -181,6 +194,16 @@ export class RemoteAgentConnection extends Disposable implements IRemoteAgentCon
 		this._getOrCreateConnection().then(client => client.registerChannel(channelName, channel));
 	}
 
+	async getInitialConnectionTimeMs() {
+		try {
+			await this._getOrCreateConnection();
+		} catch {
+			// ignored -- time is measured even if connection fails
+		}
+
+		return this._initialConnectionMs!;
+	}
+
 	private _getOrCreateConnection(): Promise<Client<RemoteAgentConnectionContext>> {
 		if (!this._connection) {
 			this._connection = this._createConnection();
@@ -209,7 +232,14 @@ export class RemoteAgentConnection extends Disposable implements IRemoteAgentCon
 			logService: this._logService,
 			ipcLogger: false ? new IPCLogger(`Local \u2192 Remote`, `Remote \u2192 Local`) : null
 		};
-		const connection = this._register(await connectRemoteAgentManagement(options, this.remoteAuthority, `renderer`));
+		let connection: ManagementPersistentConnection;
+		let start = Date.now();
+		try {
+			connection = this._register(await connectRemoteAgentManagement(options, this.remoteAuthority, `renderer`));
+		} finally {
+			this._initialConnectionMs = Date.now() - start;
+		}
+
 		connection.protocol.onDidDispose(() => {
 			connection.dispose();
 		});

src/vs/workbench/services/remote/common/remoteAgentEnvironmentChannel.ts

@@ -138,4 +138,8 @@ export class RemoteExtensionEnvironmentChannelClient {
 	static flushTelemetry(channel: IChannel): Promise<void> {
 		return channel.call<void>('flushTelemetry');
 	}
+
+	static async ping(channel: IChannel): Promise<void> {
+		await channel.call<void>('ping');
+	}
 }

src/vs/workbench/services/remote/common/remoteAgentService.ts

@@ -36,6 +36,12 @@ export interface IRemoteAgentService {
 	 */
 	getExtensionHostExitInfo(reconnectionToken: string): Promise<IExtensionHostExitInfo | null>;
 
+	/**
+	 * Gets the round trip time from the remote extension host. Note that this
+	 * may be delayed if the extension host is busy.
+	 */
+	getRoundTripTime(): Promise<number | undefined>;
+
 	whenExtensionsReady(): Promise<void>;
 	/**
 	 * Scan remote extensions.
@@ -65,4 +71,5 @@ export interface IRemoteAgentConnection {
 	getChannel<T extends IChannel>(channelName: string): T;
 	withChannel<T extends IChannel, R>(channelName: string, callback: (channel: T) => Promise<R>): Promise<R>;
 	registerChannel<T extends IServerChannel<RemoteAgentConnectionContext>>(channelName: string, channel: T): void;
+	getInitialConnectionTimeMs(): Promise<number>;
 }

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

@@ -1920,4 +1920,5 @@ export class TestRemoteAgentService implements IRemoteAgentService {
 	async updateTelemetryLevel(telemetryLevel: TelemetryLevel): Promise<void> { }
 	async logTelemetry(eventName: string, data?: ITelemetryData): Promise<void> { }
 	async flushTelemetry(): Promise<void> { }
+	async getRoundTripTime(): Promise<number | undefined> { return undefined; }
 }