Metrics tracking launch times for native locator (microsoft#23854)

Author: DonJayamanne

src/client/pythonEnvironments/base/locators/common/nativePythonFinder.ts

@@ -20,6 +20,7 @@ import { createLogOutputChannel } from '../../../../common/vscodeApis/windowApis
 import { sendNativeTelemetry, NativePythonTelemetry } from './nativePythonTelemetry';
 import { NativePythonEnvironmentKind } from './nativePythonUtils';
 import type { IExtensionContext } from '../../../../common/types';
+import { StopWatch } from '../../../../common/utils/stopWatch';
 
 const untildify = require('untildify');
 
@@ -100,6 +101,12 @@ class NativePythonFinderImpl extends DisposableBase implements NativePythonFinde
 
     private readonly outputChannel = this._register(createLogOutputChannel('Python Locator', { log: true }));
 
+    private initialRefreshMetrics = {
+        timeToSpawn: 0,
+        timeToConfigure: 0,
+        timeToRefresh: 0,
+    };
+
     constructor(private readonly cacheDirectory?: Uri) {
         super();
         this.connection = this.start();
@@ -199,7 +206,9 @@ class NativePythonFinderImpl extends DisposableBase implements NativePythonFinde
         const writable = new PassThrough();
         const disposables: Disposable[] = [];
         try {
+            const stopWatch = new StopWatch();
             const proc = ch.spawn(PYTHON_ENV_TOOLS_PATH, ['server'], { env: process.env });
+            this.initialRefreshMetrics.timeToSpawn = stopWatch.elapsedTime;
             proc.stdout.pipe(readable, { end: false });
             proc.stderr.on('data', (data) => this.outputChannel.error(data.toString()));
             writable.pipe(proc.stdin, { end: false });
@@ -251,7 +260,9 @@ class NativePythonFinderImpl extends DisposableBase implements NativePythonFinde
                         this.outputChannel.trace(data.message);
                 }
             }),
-            connection.onNotification('telemetry', (data: NativePythonTelemetry) => sendNativeTelemetry(data)),
+            connection.onNotification('telemetry', (data: NativePythonTelemetry) =>
+                sendNativeTelemetry(data, this.initialRefreshMetrics),
+            ),
             connection.onClose(() => {
                 disposables.forEach((d) => d.dispose());
             }),
@@ -269,6 +280,7 @@ class NativePythonFinderImpl extends DisposableBase implements NativePythonFinde
         const discovered = disposable.add(new EventEmitter<NativeEnvInfo | NativeEnvManagerInfo>());
         const completed = createDeferred<void>();
         const pendingPromises: Promise<void>[] = [];
+        const stopWatch = new StopWatch();
 
         const notifyUponCompletion = () => {
             const initialCount = pendingPromises.length;
@@ -339,7 +351,10 @@ class NativePythonFinderImpl extends DisposableBase implements NativePythonFinde
             this.configure().then(() =>
                 this.connection
                     .sendRequest<{ duration: number }>('refresh', refreshOptions)
-                    .then(({ duration }) => this.outputChannel.info(`Refresh completed in ${duration}ms`))
+                    .then(({ duration }) => {
+                        this.outputChannel.info(`Refresh completed in ${duration}ms`);
+                        this.initialRefreshMetrics.timeToRefresh = stopWatch.elapsedTime;
+                    })
                     .catch((ex) => this.outputChannel.error('Refresh error', ex)),
             ),
         );
@@ -371,8 +386,10 @@ class NativePythonFinderImpl extends DisposableBase implements NativePythonFinde
             return;
         }
         try {
+            const stopWatch = new StopWatch();
             this.lastConfiguration = options;
             await this.connection.sendRequest('configure', options);
+            this.initialRefreshMetrics.timeToConfigure = stopWatch.elapsedTime;
         } catch (ex) {
             this.outputChannel.error('Refresh error', ex);
         }

src/client/pythonEnvironments/base/locators/common/nativePythonTelemetry.ts

@@ -81,7 +81,14 @@ export type RefreshPerformance = {
 
 let refreshTelemetrySent = false;
 
-export function sendNativeTelemetry(data: NativePythonTelemetry): void {
+export function sendNativeTelemetry(
+    data: NativePythonTelemetry,
+    initialRefreshMetrics: {
+        timeToSpawn: number;
+        timeToConfigure: number;
+        timeToRefresh: number;
+    },
+): void {
     switch (data.event) {
         case 'MissingCondaEnvironments': {
             sendTelemetryEvent(
@@ -124,6 +131,9 @@ export function sendNativeTelemetry(data: NativePythonTelemetry): void {
                 locatorVirtualEnvWrapper: data.data.refreshPerformance.locators.VirtualEnvWrapper || 0,
                 locatorWindowsRegistry: data.data.refreshPerformance.locators.WindowsRegistry || 0,
                 locatorWindowsStore: data.data.refreshPerformance.locators.WindowsStore || 0,
+                timeToSpawn: initialRefreshMetrics.timeToSpawn,
+                timeToConfigure: initialRefreshMetrics.timeToConfigure,
+                timeToRefresh: initialRefreshMetrics.timeToRefresh,
             });
             break;
         }

src/client/telemetry/index.ts

@@ -1755,38 +1755,111 @@ export interface IEventNamePropertyMapping {
         "locatorVirtualEnv" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true, "owner": "donjayamanne" },
         "locatorVirtualEnvWrapper" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true, "owner": "donjayamanne" },
         "locatorWindowsRegistry" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true, "owner": "donjayamanne" },
-        "locatorWindowsStore" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true, "owner": "donjayamanne" }
+        "locatorWindowsStore" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true, "owner": "donjayamanne" },
+        "timeToSpawn" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true, "owner": "donjayamanne" },
+        "timeToConfigure" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true, "owner": "donjayamanne" },
+        "timeToRefresh" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true, "owner": "donjayamanne" }
        }
      */
     [EventName.NATIVE_FINDER_PERF]: {
         /**
          * Total duration to find envs using native locator.
+         * This is the time from the perspective of the Native Locator.
+         * I.e. starting from the time the request to refresh was received until the end of the refresh.
          */
         duration: number;
+        /**
+         * Time taken by all locators to find the environments.
+         * I.e. time for Conda + Poetry + Pyenv, etc (note: all of them run in parallel).
+         */
         breakdownLocators?: number;
+        /**
+         * Time taken to find Python environments in the paths found in the PATH env variable.
+         */
         breakdownPath?: number;
+        /**
+         * Time taken to find Python environments in the global virtual env locations.
+         */
         breakdownGlobalVirtualEnvs?: number;
+        /**
+         * Time taken to find Python environments in the workspaces.
+         */
         breakdownWorkspaces?: number;
+        /**
+         * Time taken to find all global Conda environments.
+         */
         locatorConda?: number;
+        /**
+         * Time taken to find all Homebrew environments.
+         */
         locatorHomebrew?: number;
+        /**
+         * Time taken to find all global Python environments on Linux.
+         */
         locatorLinuxGlobalPython?: number;
+        /**
+         * Time taken to find all Python environments belonging to Mac Command Line Tools .
+         */
         locatorMacCmdLineTools?: number;
+        /**
+         * Time taken to find all Python environments belonging to Mac Python Org.
+         */
         locatorMacPythonOrg?: number;
+        /**
+         * Time taken to find all Python environments belonging to Mac XCode.
+         */
         locatorMacXCode?: number;
+        /**
+         * Time taken to find all Pipenv environments.
+         */
         locatorPipEnv?: number;
+        /**
+         * Time taken to find all Poetry environments.
+         */
         locatorPoetry?: number;
+        /**
+         * Time taken to find all Pyenv environments.
+         */
         locatorPyEnv?: number;
+        /**
+         * Time taken to find all Venv environments.
+         */
         locatorVenv?: number;
+        /**
+         * Time taken to find all VirtualEnv environments.
+         */
         locatorVirtualEnv?: number;
+        /**
+         * Time taken to find all VirtualEnvWrapper environments.
+         */
         locatorVirtualEnvWrapper?: number;
+        /**
+         * Time taken to find all Windows Registry environments.
+         */
         locatorWindowsRegistry?: number;
+        /**
+         * Time taken to find all Windows Store environments.
+         */
         locatorWindowsStore?: number;
+        /**
+         * Total time taken to spawn the Native Python finder process.
+         */
+        timeToSpawn?: number;
+        /**
+         * Total time taken to configure the Native Python finder process.
+         */
+        timeToConfigure?: number;
+        /**
+         * Total time taken to refresh the Environments (from perspective of Python extension).
+         * Time = total time taken to process the `refresh` request.
+         */
+        timeToRefresh?: number;
     };
     /**
      * Telemetry event sent when discovery of all python environments using the native locator(virtualenv, conda, pipenv etc.) finishes.
      */
     /* __GDPR__
-       "python_interpreter_discovery_native" : {
+       "python_interpreter_discovery_invalid_native" : {
             "duration" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true, "owner": "donjayamanne" },
             "invalidVersionsCondaEnvs" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true, "owner": "donjayamanne" },
             "invalidVersionsCustomEnvs" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true, "owner": "donjayamanne" },