From f427aed437f70906cd0eb7d56ca362307b817923 Mon Sep 17 00:00:00 2001 From: Connor Peet Date: Tue, 17 May 2022 08:26:16 -0700 Subject: [PATCH] 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 --- .../common/remoteTelemetryChannel.ts | 4 ++ .../remote/common/remote.contribution.ts | 44 +++++++++++++++++++ .../common/abstractRemoteAgentService.ts | 34 +++++++++++++- .../common/remoteAgentEnvironmentChannel.ts | 4 ++ .../remote/common/remoteAgentService.ts | 7 +++ .../test/browser/workbenchTestServices.ts | 1 + 6 files changed, 92 insertions(+), 2 deletions(-) diff --git a/src/vs/platform/telemetry/common/remoteTelemetryChannel.ts b/src/vs/platform/telemetry/common/remoteTelemetryChannel.ts index 66bd712a808..97fb3ec4989 100644 --- a/src/vs/platform/telemetry/common/remoteTelemetryChannel.ts +++ b/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`); diff --git a/src/vs/workbench/contrib/remote/common/remote.contribution.ts b/src/vs/workbench/contrib/remote/common/remote.contribution.ts index eb62a41277f..a2d8b9671ae 100644 --- a/src/vs/workbench/contrib/remote/common/remote.contribution.ts +++ b/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('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('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('remoteConnectionFailure', { + web: isWeb, + remoteName: getRemoteName(this._environmentService.remoteAuthority), + latencyMs: bestLatency + }); + } } const workbenchContributionsRegistry = Registry.as(WorkbenchExtensions.Workbench); diff --git a/src/vs/workbench/services/remote/common/abstractRemoteAgentService.ts b/src/vs/workbench/services/remote/common/abstractRemoteAgentService.ts index 3268cc37382..0eba0de6b00 100644 --- a/src/vs/workbench/services/remote/common/abstractRemoteAgentService.ts +++ b/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 { + return this._withTelemetryChannel( + async channel => { + const start = Date.now(); + await RemoteExtensionEnvironmentChannelClient.ping(channel); + return Date.now() - start; + }, + undefined + ); + } + private _withChannel(callback: (channel: IChannel, connection: IRemoteAgentConnection) => Promise, fallback: R): Promise { const connection = this.getConnection(); if (!connection) { @@ -153,6 +164,8 @@ export class RemoteAgentConnection extends Disposable implements IRemoteAgentCon readonly remoteAuthority: string; private _connection: Promise> | 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> { 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(); }); diff --git a/src/vs/workbench/services/remote/common/remoteAgentEnvironmentChannel.ts b/src/vs/workbench/services/remote/common/remoteAgentEnvironmentChannel.ts index 5d33f408514..35bfae00a4d 100644 --- a/src/vs/workbench/services/remote/common/remoteAgentEnvironmentChannel.ts +++ b/src/vs/workbench/services/remote/common/remoteAgentEnvironmentChannel.ts @@ -138,4 +138,8 @@ export class RemoteExtensionEnvironmentChannelClient { static flushTelemetry(channel: IChannel): Promise { return channel.call('flushTelemetry'); } + + static async ping(channel: IChannel): Promise { + await channel.call('ping'); + } } diff --git a/src/vs/workbench/services/remote/common/remoteAgentService.ts b/src/vs/workbench/services/remote/common/remoteAgentService.ts index b7508ffc4a7..6a899e927be 100644 --- a/src/vs/workbench/services/remote/common/remoteAgentService.ts +++ b/src/vs/workbench/services/remote/common/remoteAgentService.ts @@ -36,6 +36,12 @@ export interface IRemoteAgentService { */ getExtensionHostExitInfo(reconnectionToken: string): Promise; + /** + * Gets the round trip time from the remote extension host. Note that this + * may be delayed if the extension host is busy. + */ + getRoundTripTime(): Promise; + whenExtensionsReady(): Promise; /** * Scan remote extensions. @@ -65,4 +71,5 @@ export interface IRemoteAgentConnection { getChannel(channelName: string): T; withChannel(channelName: string, callback: (channel: T) => Promise): Promise; registerChannel>(channelName: string, channel: T): void; + getInitialConnectionTimeMs(): Promise; } diff --git a/src/vs/workbench/test/browser/workbenchTestServices.ts b/src/vs/workbench/test/browser/workbenchTestServices.ts index 9a1025debd8..5bd962101c9 100644 --- a/src/vs/workbench/test/browser/workbenchTestServices.ts +++ b/src/vs/workbench/test/browser/workbenchTestServices.ts @@ -1920,4 +1920,5 @@ export class TestRemoteAgentService implements IRemoteAgentService { async updateTelemetryLevel(telemetryLevel: TelemetryLevel): Promise { } async logTelemetry(eventName: string, data?: ITelemetryData): Promise { } async flushTelemetry(): Promise { } + async getRoundTripTime(): Promise { return undefined; } }