Skip to content

Commit 79e1423

Browse files
karthiknadigDonJayamanne
karthiknadig
authored and
DonJayamanne
committed
Add more logging and some tweaks (#23425)
1 parent 22496cc commit 79e1423

14 files changed

+118
-44
lines changed

‎native_locator/Cargo.toml

+2-1
Original file line numberDiff line numberDiff line change
@@ -12,7 +12,8 @@ serde_json = "1.0.93"
1212
serde_repr = "0.1.10"
1313
regex = "1.10.4"
1414
log = "0.4.21"
15-
env_logger = "0.11.3"
15+
env_logger = "0.10.2"
16+
1617

1718
[lib]
1819
doctest = false

‎src/client/common/utils/async.ts

+1
Original file line numberDiff line numberDiff line change
@@ -155,6 +155,7 @@ export async function* chain<T>(
155155
): IAsyncIterableIterator<T> {
156156
const promises = iterators.map(getNext);
157157
let numRunning = iterators.length;
158+
158159
while (numRunning > 0) {
159160
// Promise.race will not fail, because each promise calls getNext,
160161
// Which handles failures by wrapping each iterator in a try/catch block.

‎src/client/pythonEnvironments/base/info/environmentInfoService.ts

+23
Original file line numberDiff line numberDiff line change
@@ -106,6 +106,13 @@ class EnvironmentInfoService implements IEnvironmentInfoService {
106106
}
107107

108108
const deferred = createDeferred<InterpreterInformation>();
109+
const info = EnvironmentInfoService.getInterpreterInfo(env);
110+
if (info !== undefined) {
111+
this.cache.set(normCasePath(interpreterPath), deferred);
112+
deferred.resolve(info);
113+
return info;
114+
}
115+
109116
this.cache.set(normCasePath(interpreterPath), deferred);
110117
this._getEnvironmentInfo(env, priority)
111118
.then((r) => {
@@ -205,6 +212,22 @@ class EnvironmentInfoService implements IEnvironmentInfoService {
205212
}
206213
});
207214
}
215+
216+
private static getInterpreterInfo(env: PythonEnvInfo): InterpreterInformation | undefined {
217+
if (env.version.major > -1 && env.version.minor > -1 && env.version.micro > -1 && env.location) {
218+
return {
219+
arch: env.arch,
220+
executable: {
221+
filename: env.executable.filename,
222+
ctime: -1,
223+
mtime: -1,
224+
sysPrefix: env.location,
225+
},
226+
version: env.version,
227+
};
228+
}
229+
return undefined;
230+
}
208231
}
209232

210233
function addToQueue(

‎src/client/pythonEnvironments/base/locators/composite/envsCollectionService.ts

+13-4
Original file line numberDiff line numberDiff line change
@@ -5,7 +5,7 @@ import { Event, EventEmitter } from 'vscode';
55
import '../../../../common/extensions';
66
import { createDeferred, Deferred } from '../../../../common/utils/async';
77
import { StopWatch } from '../../../../common/utils/stopWatch';
8-
import { traceError, traceVerbose } from '../../../../logging';
8+
import { traceError, traceInfo, traceVerbose } from '../../../../logging';
99
import { sendTelemetryEvent } from '../../../../telemetry';
1010
import { EventName } from '../../../../telemetry/constants';
1111
import { normalizePath } from '../../../common/externalDependencies';
@@ -107,14 +107,18 @@ export class EnvsCollectionService extends PythonEnvsWatcher<PythonEnvCollection
107107
}
108108

109109
public triggerRefresh(query?: PythonLocatorQuery, options?: TriggerRefreshOptions): Promise<void> {
110-
const stopWatch = new StopWatch();
111110
let refreshPromise = this.getRefreshPromiseForQuery(query);
112111
if (!refreshPromise) {
113112
if (options?.ifNotTriggerredAlready && this.hasRefreshFinished(query)) {
114113
// Do not trigger another refresh if a refresh has previously finished.
115114
return Promise.resolve();
116115
}
117-
refreshPromise = this.startRefresh(query).then(() => this.sendTelemetry(query, stopWatch));
116+
const stopWatch = new StopWatch();
117+
traceInfo(`Starting Environment refresh`);
118+
refreshPromise = this.startRefresh(query).then(() => {
119+
this.sendTelemetry(query, stopWatch);
120+
traceInfo(`Environment refresh took ${stopWatch.elapsedTime} milliseconds`);
121+
});
118122
}
119123
return refreshPromise;
120124
}
@@ -139,17 +143,21 @@ export class EnvsCollectionService extends PythonEnvsWatcher<PythonEnvCollection
139143
pending: 0,
140144
};
141145
const updatesDone = createDeferred<void>();
142-
146+
const stopWatch = new StopWatch();
143147
if (iterator.onUpdated !== undefined) {
144148
const listener = iterator.onUpdated(async (event) => {
145149
if (isProgressEvent(event)) {
146150
switch (event.stage) {
147151
case ProgressReportStage.discoveryFinished:
148152
state.done = true;
149153
listener.dispose();
154+
traceInfo(`Environments refresh finished (event): ${stopWatch.elapsedTime} milliseconds`);
150155
break;
151156
case ProgressReportStage.allPathsDiscovered:
152157
if (!query) {
158+
traceInfo(
159+
`Environments refresh paths discovered (event): ${stopWatch.elapsedTime} milliseconds`,
160+
);
153161
// Only mark as all paths discovered when querying for all envs.
154162
this.progress.fire(event);
155163
}
@@ -178,6 +186,7 @@ export class EnvsCollectionService extends PythonEnvsWatcher<PythonEnvCollection
178186
seen.push(env);
179187
this.cache.addEnv(env);
180188
}
189+
traceInfo(`Environments refresh paths discovered: ${stopWatch.elapsedTime} milliseconds`);
181190
await updatesDone.promise;
182191
// If query for all envs is done, `seen` should contain the list of all envs.
183192
await this.cache.validateCache(seen, query === undefined);

‎src/client/pythonEnvironments/base/locators/lowLevel/activeStateLocator.ts

+5-3
Original file line numberDiff line numberDiff line change
@@ -6,21 +6,23 @@
66
import { ActiveState } from '../../../common/environmentManagers/activestate';
77
import { PythonEnvKind } from '../../info';
88
import { BasicEnvInfo, IPythonEnvsIterator } from '../../locator';
9-
import { traceError, traceVerbose } from '../../../../logging';
9+
import { traceError, traceInfo, traceVerbose } from '../../../../logging';
1010
import { LazyResourceBasedLocator } from '../common/resourceBasedLocator';
1111
import { findInterpretersInDir } from '../../../common/commonUtils';
12+
import { StopWatch } from '../../../../common/utils/stopWatch';
1213

1314
export class ActiveStateLocator extends LazyResourceBasedLocator {
1415
public readonly providerId: string = 'activestate';
1516

1617
// eslint-disable-next-line class-methods-use-this
1718
public async *doIterEnvs(): IPythonEnvsIterator<BasicEnvInfo> {
19+
const stopWatch = new StopWatch();
1820
const state = await ActiveState.getState();
1921
if (state === undefined) {
2022
traceVerbose(`Couldn't locate the state binary.`);
2123
return;
2224
}
23-
traceVerbose(`Searching for active state environments`);
25+
traceInfo(`Searching for active state environments`);
2426
const projects = await state.getProjects();
2527
if (projects === undefined) {
2628
traceVerbose(`Couldn't fetch State Tool projects.`);
@@ -41,6 +43,6 @@ export class ActiveStateLocator extends LazyResourceBasedLocator {
4143
}
4244
}
4345
}
44-
traceVerbose(`Finished searching for active state environments`);
46+
traceInfo(`Finished searching for active state environments: ${stopWatch.elapsedTime} milliseconds`);
4547
}
4648
}

‎src/client/pythonEnvironments/base/locators/lowLevel/condaLocator.ts

+5-2
Original file line numberDiff line numberDiff line change
@@ -4,8 +4,9 @@ import '../../../../common/extensions';
44
import { PythonEnvKind } from '../../info';
55
import { BasicEnvInfo, IPythonEnvsIterator } from '../../locator';
66
import { Conda, getCondaEnvironmentsTxt } from '../../../common/environmentManagers/conda';
7-
import { traceError, traceVerbose } from '../../../../logging';
7+
import { traceError, traceInfo, traceVerbose } from '../../../../logging';
88
import { FSWatchingLocator } from './fsWatchingLocator';
9+
import { StopWatch } from '../../../../common/utils/stopWatch';
910

1011
export class CondaEnvironmentLocator extends FSWatchingLocator {
1112
public readonly providerId: string = 'conda-envs';
@@ -20,6 +21,8 @@ export class CondaEnvironmentLocator extends FSWatchingLocator {
2021

2122
// eslint-disable-next-line class-methods-use-this
2223
public async *doIterEnvs(_: unknown): IPythonEnvsIterator<BasicEnvInfo> {
24+
const stopWatch = new StopWatch();
25+
traceInfo('Searching for conda environments');
2326
const conda = await Conda.getConda();
2427
if (conda === undefined) {
2528
traceVerbose(`Couldn't locate the conda binary.`);
@@ -38,6 +41,6 @@ export class CondaEnvironmentLocator extends FSWatchingLocator {
3841
traceError(`Failed to process conda env: ${JSON.stringify(env)}`, ex);
3942
}
4043
}
41-
traceVerbose(`Finished searching for conda environments`);
44+
traceInfo(`Finished searching for conda environments: ${stopWatch.elapsedTime} milliseconds`);
4245
}
4346
}

‎src/client/pythonEnvironments/base/locators/lowLevel/customVirtualEnvLocator.ts

+5-2
Original file line numberDiff line numberDiff line change
@@ -23,7 +23,8 @@ import {
2323
} from '../../../common/environmentManagers/simplevirtualenvs';
2424
import '../../../../common/extensions';
2525
import { asyncFilter } from '../../../../common/utils/arrayUtils';
26-
import { traceError, traceVerbose } from '../../../../logging';
26+
import { traceError, traceInfo, traceVerbose } from '../../../../logging';
27+
import { StopWatch } from '../../../../common/utils/stopWatch';
2728
/**
2829
* Default number of levels of sub-directories to recurse when looking for interpreters.
2930
*/
@@ -99,6 +100,8 @@ export class CustomVirtualEnvironmentLocator extends FSWatchingLocator {
99100
// eslint-disable-next-line class-methods-use-this
100101
protected doIterEnvs(): IPythonEnvsIterator<BasicEnvInfo> {
101102
async function* iterator() {
103+
const stopWatch = new StopWatch();
104+
traceInfo('Searching for custom virtual environments');
102105
const envRootDirs = await getCustomVirtualEnvDirs();
103106
const envGenerators = envRootDirs.map((envRootDir) => {
104107
async function* generator() {
@@ -132,7 +135,7 @@ export class CustomVirtualEnvironmentLocator extends FSWatchingLocator {
132135
});
133136

134137
yield* iterable(chain(envGenerators));
135-
traceVerbose(`Finished searching for custom virtual envs`);
138+
traceInfo(`Finished searching for custom virtual envs: ${stopWatch.elapsedTime} milliseconds`);
136139
}
137140

138141
return iterator();

‎src/client/pythonEnvironments/base/locators/lowLevel/globalVirtualEnvronmentLocator.ts

+5-2
Original file line numberDiff line numberDiff line change
@@ -19,7 +19,8 @@ import {
1919
} from '../../../common/environmentManagers/simplevirtualenvs';
2020
import '../../../../common/extensions';
2121
import { asyncFilter } from '../../../../common/utils/arrayUtils';
22-
import { traceError, traceVerbose } from '../../../../logging';
22+
import { traceError, traceInfo, traceVerbose } from '../../../../logging';
23+
import { StopWatch } from '../../../../common/utils/stopWatch';
2324

2425
const DEFAULT_SEARCH_DEPTH = 2;
2526
/**
@@ -118,6 +119,8 @@ export class GlobalVirtualEnvironmentLocator extends FSWatchingLocator {
118119
const searchDepth = this.searchDepth ?? DEFAULT_SEARCH_DEPTH;
119120

120121
async function* iterator() {
122+
const stopWatch = new StopWatch();
123+
traceInfo('Searching for global virtual environments');
121124
const envRootDirs = await getGlobalVirtualEnvDirs();
122125
const envGenerators = envRootDirs.map((envRootDir) => {
123126
async function* generator() {
@@ -152,7 +155,7 @@ export class GlobalVirtualEnvironmentLocator extends FSWatchingLocator {
152155
});
153156

154157
yield* iterable(chain(envGenerators));
155-
traceVerbose(`Finished searching for global virtual envs`);
158+
traceInfo(`Finished searching for global virtual envs: ${stopWatch.elapsedTime} milliseconds`);
156159
}
157160

158161
return iterator();

‎src/client/pythonEnvironments/base/locators/lowLevel/microsoftStoreLocator.ts

+5-3
Original file line numberDiff line numberDiff line change
@@ -12,7 +12,8 @@ import {
1212
isStorePythonInstalled,
1313
getMicrosoftStoreAppsRoot,
1414
} from '../../../common/environmentManagers/microsoftStoreEnv';
15-
import { traceVerbose } from '../../../../logging';
15+
import { traceInfo } from '../../../../logging';
16+
import { StopWatch } from '../../../../common/utils/stopWatch';
1617

1718
/**
1819
* This is a glob pattern which matches following file names:
@@ -87,13 +88,14 @@ export class MicrosoftStoreLocator extends FSWatchingLocator {
8788

8889
protected doIterEnvs(): IPythonEnvsIterator<BasicEnvInfo> {
8990
const iterator = async function* (kind: PythonEnvKind) {
90-
traceVerbose('Searching for windows store envs');
91+
const stopWatch = new StopWatch();
92+
traceInfo('Searching for windows store envs');
9193
const exes = await getMicrosoftStorePythonExes();
9294
yield* exes.map(async (executablePath: string) => ({
9395
kind,
9496
executablePath,
9597
}));
96-
traceVerbose(`Finished searching for windows store envs`);
98+
traceInfo(`Finished searching for windows store envs: ${stopWatch.elapsedTime} milliseconds`);
9799
};
98100
return iterator(this.kind);
99101
}

‎src/client/pythonEnvironments/base/locators/lowLevel/nativeLocator.ts

+12-1
Original file line numberDiff line numberDiff line change
@@ -7,7 +7,7 @@ import { ILocator, BasicEnvInfo, IPythonEnvsIterator } from '../../locator';
77
import { PythonEnvsChangedEvent } from '../../watcher';
88
import { PythonEnvKind, PythonVersion } from '../../info';
99
import { Conda } from '../../../common/environmentManagers/conda';
10-
import { traceError } from '../../../../logging';
10+
import { traceError, traceInfo } from '../../../../logging';
1111
import type { KnownEnvironmentTools } from '../../../../api/types';
1212
import { setPyEnvBinary } from '../../../common/environmentManagers/pyenv';
1313
import {
@@ -17,6 +17,7 @@ import {
1717
createNativeGlobalPythonFinder,
1818
} from '../common/nativePythonFinder';
1919
import { disposeAll } from '../../../../common/utils/resourceLifecycle';
20+
import { StopWatch } from '../../../../common/utils/stopWatch';
2021

2122
function categoryToKind(category: string): PythonEnvKind {
2223
switch (category.toLowerCase()) {
@@ -96,6 +97,8 @@ export class NativeLocator implements ILocator<BasicEnvInfo>, IDisposable {
9697
}
9798

9899
public iterEnvs(): IPythonEnvsIterator<BasicEnvInfo> {
100+
const stopWatch = new StopWatch();
101+
traceInfo('Searching for Python environments using Native Locator');
99102
const promise = this.finder.startSearch();
100103
const envs: BasicEnvInfo[] = [];
101104
const disposables: IDisposable[] = [];
@@ -133,9 +136,17 @@ export class NativeLocator implements ILocator<BasicEnvInfo>, IDisposable {
133136
);
134137

135138
const iterator = async function* (): IPythonEnvsIterator<BasicEnvInfo> {
139+
// When this promise is complete, we know that the search is complete.
136140
await promise;
141+
traceInfo(
142+
`Finished searching for Python environments using Native Locator: ${stopWatch.elapsedTime} milliseconds`,
143+
);
137144
yield* envs;
145+
traceInfo(
146+
`Finished yielding Python environments using Native Locator: ${stopWatch.elapsedTime} milliseconds`,
147+
);
138148
};
149+
139150
return iterator();
140151
}
141152
}

‎src/client/pythonEnvironments/base/locators/lowLevel/posixKnownPathsLocator.ts

+7-3
Original file line numberDiff line numberDiff line change
@@ -9,7 +9,8 @@ import { commonPosixBinPaths, getPythonBinFromPosixPaths } from '../../../common
99
import { isPyenvShimDir } from '../../../common/environmentManagers/pyenv';
1010
import { getOSType, OSType } from '../../../../common/utils/platform';
1111
import { isMacDefaultPythonPath } from '../../../common/environmentManagers/macDefault';
12-
import { traceError, traceVerbose } from '../../../../logging';
12+
import { traceError, traceInfo, traceVerbose } from '../../../../logging';
13+
import { StopWatch } from '../../../../common/utils/stopWatch';
1314

1415
export class PosixKnownPathsLocator extends Locator<BasicEnvInfo> {
1516
public readonly providerId = 'posixKnownPaths';
@@ -26,7 +27,8 @@ export class PosixKnownPathsLocator extends Locator<BasicEnvInfo> {
2627
}
2728

2829
const iterator = async function* (kind: PythonEnvKind) {
29-
traceVerbose('Searching for interpreters in posix paths locator');
30+
const stopWatch = new StopWatch();
31+
traceInfo('Searching for interpreters in posix paths locator');
3032
try {
3133
// Filter out pyenv shims. They are not actual python binaries, they are used to launch
3234
// 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> {
5052
} catch (ex) {
5153
traceError('Failed to process posix paths', ex);
5254
}
53-
traceVerbose('Finished searching for interpreters in posix paths locator');
55+
traceInfo(
56+
`Finished searching for interpreters in posix paths locator: ${stopWatch.elapsedTime} milliseconds`,
57+
);
5458
};
5559
return iterator(this.kind);
5660
}

‎src/client/pythonEnvironments/base/locators/lowLevel/pyenvLocator.ts

+22-15
Original file line numberDiff line numberDiff line change
@@ -7,7 +7,8 @@ import { FSWatchingLocator } from './fsWatchingLocator';
77
import { getInterpreterPathFromDir } from '../../../common/commonUtils';
88
import { getSubDirs } from '../../../common/externalDependencies';
99
import { getPyenvVersionsDir } from '../../../common/environmentManagers/pyenv';
10-
import { traceError, traceVerbose } from '../../../../logging';
10+
import { traceError, traceInfo } from '../../../../logging';
11+
import { StopWatch } from '../../../../common/utils/stopWatch';
1112

1213
/**
1314
* Gets all the pyenv environments.
@@ -16,25 +17,31 @@ import { traceError, traceVerbose } from '../../../../logging';
1617
* all the environments (global or virtual) in that directory.
1718
*/
1819
async function* getPyenvEnvironments(): AsyncIterableIterator<BasicEnvInfo> {
19-
traceVerbose('Searching for pyenv environments');
20-
const pyenvVersionDir = getPyenvVersionsDir();
20+
const stopWatch = new StopWatch();
21+
traceInfo('Searching for pyenv environments');
22+
try {
23+
const pyenvVersionDir = getPyenvVersionsDir();
2124

22-
const subDirs = getSubDirs(pyenvVersionDir, { resolveSymlinks: true });
23-
for await (const subDirPath of subDirs) {
24-
const interpreterPath = await getInterpreterPathFromDir(subDirPath);
25+
const subDirs = getSubDirs(pyenvVersionDir, { resolveSymlinks: true });
26+
for await (const subDirPath of subDirs) {
27+
const interpreterPath = await getInterpreterPathFromDir(subDirPath);
2528

26-
if (interpreterPath) {
27-
try {
28-
yield {
29-
kind: PythonEnvKind.Pyenv,
30-
executablePath: interpreterPath,
31-
};
32-
} catch (ex) {
33-
traceError(`Failed to process environment: ${interpreterPath}`, ex);
29+
if (interpreterPath) {
30+
try {
31+
yield {
32+
kind: PythonEnvKind.Pyenv,
33+
executablePath: interpreterPath,
34+
};
35+
} catch (ex) {
36+
traceError(`Failed to process environment: ${interpreterPath}`, ex);
37+
}
3438
}
3539
}
40+
} catch (ex) {
41+
// This is expected when pyenv is not installed
42+
traceInfo(`pyenv is not installed`);
3643
}
37-
traceVerbose('Finished searching for pyenv environments');
44+
traceInfo(`Finished searching for pyenv environments: ${stopWatch.elapsedTime} milliseconds`);
3845
}
3946

4047
export class PyenvLocator extends FSWatchingLocator {

0 commit comments

Comments
 (0)