Add more logging and some tweaks (microsoft#23425)

anthonykim1 · May 16, 2024 · 885d63b · 885d63b
1 parent 6ddcc05
commit 885d63b
Show file tree

Hide file tree

Showing 14 changed files with 118 additions and 44 deletions.
diff --git a/native_locator/Cargo.toml b/native_locator/Cargo.toml
@@ -12,7 +12,8 @@ serde_json = "1.0.93"
 serde_repr = "0.1.10"
 regex = "1.10.4"
 log = "0.4.21"
-env_logger = "0.11.3"
+env_logger = "0.10.2"
+
 
 [lib]
 doctest = false
diff --git a/src/client/common/utils/async.ts b/src/client/common/utils/async.ts
@@ -155,6 +155,7 @@ export async function* chain<T>(
 ): IAsyncIterableIterator<T> {
     const promises = iterators.map(getNext);
     let numRunning = iterators.length;
+
     while (numRunning > 0) {
         // Promise.race will not fail, because each promise calls getNext,
         // Which handles failures by wrapping each iterator in a try/catch block.

diff --git a/src/client/pythonEnvironments/base/info/environmentInfoService.ts b/src/client/pythonEnvironments/base/info/environmentInfoService.ts
@@ -106,6 +106,13 @@ class EnvironmentInfoService implements IEnvironmentInfoService {
         }
 
         const deferred = createDeferred<InterpreterInformation>();
+        const info = EnvironmentInfoService.getInterpreterInfo(env);
+        if (info !== undefined) {
+            this.cache.set(normCasePath(interpreterPath), deferred);
+            deferred.resolve(info);
+            return info;
+        }
+
         this.cache.set(normCasePath(interpreterPath), deferred);
         this._getEnvironmentInfo(env, priority)
             .then((r) => {
@@ -205,6 +212,22 @@ class EnvironmentInfoService implements IEnvironmentInfoService {
             }
         });
     }
+
+    private static getInterpreterInfo(env: PythonEnvInfo): InterpreterInformation | undefined {
+        if (env.version.major > -1 && env.version.minor > -1 && env.version.micro > -1 && env.location) {
+            return {
+                arch: env.arch,
+                executable: {
+                    filename: env.executable.filename,
+                    ctime: -1,
+                    mtime: -1,
+                    sysPrefix: env.location,
+                },
+                version: env.version,
+            };
+        }
+        return undefined;
+    }
 }
 
 function addToQueue(

diff --git a/src/client/pythonEnvironments/base/locators/composite/envsCollectionService.ts b/src/client/pythonEnvironments/base/locators/composite/envsCollectionService.ts
@@ -5,7 +5,7 @@ import { Event, EventEmitter } from 'vscode';
 import '../../../../common/extensions';
 import { createDeferred, Deferred } from '../../../../common/utils/async';
 import { StopWatch } from '../../../../common/utils/stopWatch';
-import { traceError, traceVerbose } from '../../../../logging';
+import { traceError, traceInfo, traceVerbose } from '../../../../logging';
 import { sendTelemetryEvent } from '../../../../telemetry';
 import { EventName } from '../../../../telemetry/constants';
 import { normalizePath } from '../../../common/externalDependencies';
@@ -107,14 +107,18 @@ export class EnvsCollectionService extends PythonEnvsWatcher<PythonEnvCollection
     }
 
     public triggerRefresh(query?: PythonLocatorQuery, options?: TriggerRefreshOptions): Promise<void> {
-        const stopWatch = new StopWatch();
         let refreshPromise = this.getRefreshPromiseForQuery(query);
         if (!refreshPromise) {
             if (options?.ifNotTriggerredAlready && this.hasRefreshFinished(query)) {
                 // Do not trigger another refresh if a refresh has previously finished.
                 return Promise.resolve();
             }
-            refreshPromise = this.startRefresh(query).then(() => this.sendTelemetry(query, stopWatch));
+            const stopWatch = new StopWatch();
+            traceInfo(`Starting Environment refresh`);
+            refreshPromise = this.startRefresh(query).then(() => {
+                this.sendTelemetry(query, stopWatch);
+                traceInfo(`Environment refresh took ${stopWatch.elapsedTime} milliseconds`);
+            });
         }
         return refreshPromise;
     }
@@ -139,17 +143,21 @@ export class EnvsCollectionService extends PythonEnvsWatcher<PythonEnvCollection
             pending: 0,
         };
         const updatesDone = createDeferred<void>();
-
+        const stopWatch = new StopWatch();
         if (iterator.onUpdated !== undefined) {
             const listener = iterator.onUpdated(async (event) => {
                 if (isProgressEvent(event)) {
                     switch (event.stage) {
                         case ProgressReportStage.discoveryFinished:
                             state.done = true;
                             listener.dispose();
+                            traceInfo(`Environments refresh finished (event): ${stopWatch.elapsedTime} milliseconds`);
                             break;
                         case ProgressReportStage.allPathsDiscovered:
                             if (!query) {
+                                traceInfo(
+                                    `Environments refresh paths discovered (event): ${stopWatch.elapsedTime} milliseconds`,
+                                );
                                 // Only mark as all paths discovered when querying for all envs.
                                 this.progress.fire(event);
                             }
@@ -178,6 +186,7 @@ export class EnvsCollectionService extends PythonEnvsWatcher<PythonEnvCollection
             seen.push(env);
             this.cache.addEnv(env);
         }
+        traceInfo(`Environments refresh paths discovered: ${stopWatch.elapsedTime} milliseconds`);
         await updatesDone.promise;
         // If query for all envs is done, `seen` should contain the list of all envs.
         await this.cache.validateCache(seen, query === undefined);

diff --git a/src/client/pythonEnvironments/base/locators/lowLevel/activeStateLocator.ts b/src/client/pythonEnvironments/base/locators/lowLevel/activeStateLocator.ts
@@ -6,21 +6,23 @@
 import { ActiveState } from '../../../common/environmentManagers/activestate';
 import { PythonEnvKind } from '../../info';
 import { BasicEnvInfo, IPythonEnvsIterator } from '../../locator';
-import { traceError, traceVerbose } from '../../../../logging';
+import { traceError, traceInfo, traceVerbose } from '../../../../logging';
 import { LazyResourceBasedLocator } from '../common/resourceBasedLocator';
 import { findInterpretersInDir } from '../../../common/commonUtils';
+import { StopWatch } from '../../../../common/utils/stopWatch';
 
 export class ActiveStateLocator extends LazyResourceBasedLocator {
     public readonly providerId: string = 'activestate';
 
     // eslint-disable-next-line class-methods-use-this
     public async *doIterEnvs(): IPythonEnvsIterator<BasicEnvInfo> {
+        const stopWatch = new StopWatch();
         const state = await ActiveState.getState();
         if (state === undefined) {
             traceVerbose(`Couldn't locate the state binary.`);
             return;
         }
-        traceVerbose(`Searching for active state environments`);
+        traceInfo(`Searching for active state environments`);
         const projects = await state.getProjects();
         if (projects === undefined) {
             traceVerbose(`Couldn't fetch State Tool projects.`);
@@ -41,6 +43,6 @@ export class ActiveStateLocator extends LazyResourceBasedLocator {
                 }
             }
         }
-        traceVerbose(`Finished searching for active state environments`);
+        traceInfo(`Finished searching for active state environments: ${stopWatch.elapsedTime} milliseconds`);
     }
 }
diff --git a/src/client/pythonEnvironments/base/locators/lowLevel/condaLocator.ts b/src/client/pythonEnvironments/base/locators/lowLevel/condaLocator.ts
@@ -4,8 +4,9 @@ import '../../../../common/extensions';
 import { PythonEnvKind } from '../../info';
 import { BasicEnvInfo, IPythonEnvsIterator } from '../../locator';
 import { Conda, getCondaEnvironmentsTxt } from '../../../common/environmentManagers/conda';
-import { traceError, traceVerbose } from '../../../../logging';
+import { traceError, traceInfo, traceVerbose } from '../../../../logging';
 import { FSWatchingLocator } from './fsWatchingLocator';
+import { StopWatch } from '../../../../common/utils/stopWatch';
 
 export class CondaEnvironmentLocator extends FSWatchingLocator {
     public readonly providerId: string = 'conda-envs';
@@ -20,6 +21,8 @@ export class CondaEnvironmentLocator extends FSWatchingLocator {
 
     // eslint-disable-next-line class-methods-use-this
     public async *doIterEnvs(_: unknown): IPythonEnvsIterator<BasicEnvInfo> {
+        const stopWatch = new StopWatch();
+        traceInfo('Searching for conda environments');
         const conda = await Conda.getConda();
         if (conda === undefined) {
             traceVerbose(`Couldn't locate the conda binary.`);
@@ -38,6 +41,6 @@ export class CondaEnvironmentLocator extends FSWatchingLocator {
                 traceError(`Failed to process conda env: ${JSON.stringify(env)}`, ex);
             }
         }
-        traceVerbose(`Finished searching for conda environments`);
+        traceInfo(`Finished searching for conda environments: ${stopWatch.elapsedTime} milliseconds`);
     }
 }
diff --git a/src/client/pythonEnvironments/base/locators/lowLevel/customVirtualEnvLocator.ts b/src/client/pythonEnvironments/base/locators/lowLevel/customVirtualEnvLocator.ts
@@ -23,7 +23,8 @@ import {
 } from '../../../common/environmentManagers/simplevirtualenvs';
 import '../../../../common/extensions';
 import { asyncFilter } from '../../../../common/utils/arrayUtils';
-import { traceError, traceVerbose } from '../../../../logging';
+import { traceError, traceInfo, traceVerbose } from '../../../../logging';
+import { StopWatch } from '../../../../common/utils/stopWatch';
 /**
  * Default number of levels of sub-directories to recurse when looking for interpreters.
  */
@@ -99,6 +100,8 @@ export class CustomVirtualEnvironmentLocator extends FSWatchingLocator {
     // eslint-disable-next-line class-methods-use-this
     protected doIterEnvs(): IPythonEnvsIterator<BasicEnvInfo> {
         async function* iterator() {
+            const stopWatch = new StopWatch();
+            traceInfo('Searching for custom virtual environments');
             const envRootDirs = await getCustomVirtualEnvDirs();
             const envGenerators = envRootDirs.map((envRootDir) => {
                 async function* generator() {
@@ -132,7 +135,7 @@ export class CustomVirtualEnvironmentLocator extends FSWatchingLocator {
             });
 
             yield* iterable(chain(envGenerators));
-            traceVerbose(`Finished searching for custom virtual envs`);
+            traceInfo(`Finished searching for custom virtual envs: ${stopWatch.elapsedTime} milliseconds`);
         }
 
         return iterator();

diff --git a/src/client/pythonEnvironments/base/locators/lowLevel/globalVirtualEnvronmentLocator.ts b/src/client/pythonEnvironments/base/locators/lowLevel/globalVirtualEnvronmentLocator.ts
@@ -19,7 +19,8 @@ import {
 } from '../../../common/environmentManagers/simplevirtualenvs';
 import '../../../../common/extensions';
 import { asyncFilter } from '../../../../common/utils/arrayUtils';
-import { traceError, traceVerbose } from '../../../../logging';
+import { traceError, traceInfo, traceVerbose } from '../../../../logging';
+import { StopWatch } from '../../../../common/utils/stopWatch';
 
 const DEFAULT_SEARCH_DEPTH = 2;
 /**
@@ -118,6 +119,8 @@ export class GlobalVirtualEnvironmentLocator extends FSWatchingLocator {
         const searchDepth = this.searchDepth ?? DEFAULT_SEARCH_DEPTH;
 
         async function* iterator() {
+            const stopWatch = new StopWatch();
+            traceInfo('Searching for global virtual environments');
             const envRootDirs = await getGlobalVirtualEnvDirs();
             const envGenerators = envRootDirs.map((envRootDir) => {
                 async function* generator() {
@@ -152,7 +155,7 @@ export class GlobalVirtualEnvironmentLocator extends FSWatchingLocator {
             });
 
             yield* iterable(chain(envGenerators));
-            traceVerbose(`Finished searching for global virtual envs`);
+            traceInfo(`Finished searching for global virtual envs: ${stopWatch.elapsedTime} milliseconds`);
         }
 
         return iterator();

diff --git a/src/client/pythonEnvironments/base/locators/lowLevel/microsoftStoreLocator.ts b/src/client/pythonEnvironments/base/locators/lowLevel/microsoftStoreLocator.ts
@@ -12,7 +12,8 @@ import {
     isStorePythonInstalled,
     getMicrosoftStoreAppsRoot,
 } from '../../../common/environmentManagers/microsoftStoreEnv';
-import { traceVerbose } from '../../../../logging';
+import { traceInfo } from '../../../../logging';
+import { StopWatch } from '../../../../common/utils/stopWatch';
 
 /**
  * This is a glob pattern which matches following file names:
@@ -87,13 +88,14 @@ export class MicrosoftStoreLocator extends FSWatchingLocator {
 
     protected doIterEnvs(): IPythonEnvsIterator<BasicEnvInfo> {
         const iterator = async function* (kind: PythonEnvKind) {
-            traceVerbose('Searching for windows store envs');
+            const stopWatch = new StopWatch();
+            traceInfo('Searching for windows store envs');
             const exes = await getMicrosoftStorePythonExes();
             yield* exes.map(async (executablePath: string) => ({
                 kind,
                 executablePath,
             }));
-            traceVerbose(`Finished searching for windows store envs`);
+            traceInfo(`Finished searching for windows store envs: ${stopWatch.elapsedTime} milliseconds`);
         };
         return iterator(this.kind);
     }

diff --git a/src/client/pythonEnvironments/base/locators/lowLevel/nativeLocator.ts b/src/client/pythonEnvironments/base/locators/lowLevel/nativeLocator.ts
@@ -7,7 +7,7 @@ import { ILocator, BasicEnvInfo, IPythonEnvsIterator } from '../../locator';
 import { PythonEnvsChangedEvent } from '../../watcher';
 import { PythonEnvKind, PythonVersion } from '../../info';
 import { Conda } from '../../../common/environmentManagers/conda';
-import { traceError } from '../../../../logging';
+import { traceError, traceInfo } from '../../../../logging';
 import type { KnownEnvironmentTools } from '../../../../api/types';
 import { setPyEnvBinary } from '../../../common/environmentManagers/pyenv';
 import {
@@ -17,6 +17,7 @@ import {
     createNativeGlobalPythonFinder,
 } from '../common/nativePythonFinder';
 import { disposeAll } from '../../../../common/utils/resourceLifecycle';
+import { StopWatch } from '../../../../common/utils/stopWatch';
 
 function categoryToKind(category: string): PythonEnvKind {
     switch (category.toLowerCase()) {
@@ -96,6 +97,8 @@ export class NativeLocator implements ILocator<BasicEnvInfo>, IDisposable {
     }
 
     public iterEnvs(): IPythonEnvsIterator<BasicEnvInfo> {
+        const stopWatch = new StopWatch();
+        traceInfo('Searching for Python environments using Native Locator');
         const promise = this.finder.startSearch();
         const envs: BasicEnvInfo[] = [];
         const disposables: IDisposable[] = [];
@@ -133,9 +136,17 @@ export class NativeLocator implements ILocator<BasicEnvInfo>, IDisposable {
         );
 
         const iterator = async function* (): IPythonEnvsIterator<BasicEnvInfo> {
+            // When this promise is complete, we know that the search is complete.
             await promise;
+            traceInfo(
+                `Finished searching for Python environments using Native Locator: ${stopWatch.elapsedTime} milliseconds`,
+            );
             yield* envs;
+            traceInfo(
+                `Finished yielding Python environments using Native Locator: ${stopWatch.elapsedTime} milliseconds`,
+            );
         };
+
         return iterator();
     }
 }
diff --git a/src/client/pythonEnvironments/base/locators/lowLevel/posixKnownPathsLocator.ts b/src/client/pythonEnvironments/base/locators/lowLevel/posixKnownPathsLocator.ts
@@ -9,7 +9,8 @@ import { commonPosixBinPaths, getPythonBinFromPosixPaths } from '../../../common
 import { isPyenvShimDir } from '../../../common/environmentManagers/pyenv';
 import { getOSType, OSType } from '../../../../common/utils/platform';
 import { isMacDefaultPythonPath } from '../../../common/environmentManagers/macDefault';
-import { traceError, traceVerbose } from '../../../../logging';
+import { traceError, traceInfo, traceVerbose } from '../../../../logging';
+import { StopWatch } from '../../../../common/utils/stopWatch';
 
 export class PosixKnownPathsLocator extends Locator<BasicEnvInfo> {
     public readonly providerId = 'posixKnownPaths';
@@ -26,7 +27,8 @@ export class PosixKnownPathsLocator extends Locator<BasicEnvInfo> {
         }
 
         const iterator = async function* (kind: PythonEnvKind) {
-            traceVerbose('Searching for interpreters in posix paths locator');
+            const stopWatch = new StopWatch();
+            traceInfo('Searching for interpreters in posix paths locator');
             try {
                 // Filter out pyenv shims. They are not actual python binaries, they are used to launch
                 // the binaries specified in .python-version file in the cwd. We should not be reporting
@@ -50,7 +52,9 @@ export class PosixKnownPathsLocator extends Locator<BasicEnvInfo> {
             } catch (ex) {
                 traceError('Failed to process posix paths', ex);
             }
-            traceVerbose('Finished searching for interpreters in posix paths locator');
+            traceInfo(
+                `Finished searching for interpreters in posix paths locator: ${stopWatch.elapsedTime} milliseconds`,
+            );
         };
         return iterator(this.kind);
     }

diff --git a/src/client/pythonEnvironments/base/locators/lowLevel/pyenvLocator.ts b/src/client/pythonEnvironments/base/locators/lowLevel/pyenvLocator.ts
@@ -7,7 +7,8 @@ import { FSWatchingLocator } from './fsWatchingLocator';
 import { getInterpreterPathFromDir } from '../../../common/commonUtils';
 import { getSubDirs } from '../../../common/externalDependencies';
 import { getPyenvVersionsDir } from '../../../common/environmentManagers/pyenv';
-import { traceError, traceVerbose } from '../../../../logging';
+import { traceError, traceInfo } from '../../../../logging';
+import { StopWatch } from '../../../../common/utils/stopWatch';
 
 /**
  * Gets all the pyenv environments.
@@ -16,25 +17,31 @@ import { traceError, traceVerbose } from '../../../../logging';
  * all the environments (global or virtual) in that directory.
  */
 async function* getPyenvEnvironments(): AsyncIterableIterator<BasicEnvInfo> {
-    traceVerbose('Searching for pyenv environments');
-    const pyenvVersionDir = getPyenvVersionsDir();
+    const stopWatch = new StopWatch();
+    traceInfo('Searching for pyenv environments');
+    try {
+        const pyenvVersionDir = getPyenvVersionsDir();
 
-    const subDirs = getSubDirs(pyenvVersionDir, { resolveSymlinks: true });
-    for await (const subDirPath of subDirs) {
-        const interpreterPath = await getInterpreterPathFromDir(subDirPath);
+        const subDirs = getSubDirs(pyenvVersionDir, { resolveSymlinks: true });
+        for await (const subDirPath of subDirs) {
+            const interpreterPath = await getInterpreterPathFromDir(subDirPath);
 
-        if (interpreterPath) {
-            try {
-                yield {
-                    kind: PythonEnvKind.Pyenv,
-                    executablePath: interpreterPath,
-                };
-            } catch (ex) {
-                traceError(`Failed to process environment: ${interpreterPath}`, ex);
+            if (interpreterPath) {
+                try {
+                    yield {
+                        kind: PythonEnvKind.Pyenv,
+                        executablePath: interpreterPath,
+                    };
+                } catch (ex) {
+                    traceError(`Failed to process environment: ${interpreterPath}`, ex);
+                }
             }
         }
+    } catch (ex) {
+        // This is expected when pyenv is not installed
+        traceInfo(`pyenv is not installed`);
     }
-    traceVerbose('Finished searching for pyenv environments');
+    traceInfo(`Finished searching for pyenv environments: ${stopWatch.elapsedTime} milliseconds`);
 }
 
 export class PyenvLocator extends FSWatchingLocator {