Test proposed API to report progress of environment discovery in two phases

[karrtikr]

Refs: #19103

• anyOS: @rchiodo
• anyOS: @DonJayamanne

Complexity: 2

Create Issue

---

Requirements

Tagging the team who previously tested #19103, apologies for the late tag as I was OOF.

1. Use pre release build of the python extension.

Test APIs

• Test the following APIs in IProposedExtensionAPI:
  

  vscode-python/src/client/apiTypes.ts

  Lines 207 to 217 in c46c819

  	/**
  	* Tracks discovery progress for current list of known environments, i.e when it starts, finishes or any other relevant
  	* stage. Note the progress for a particular query is currently not tracked or reported, this only indicates progress of
  	* the entire collection.
  	*/
  	readonly onRefreshProgress: Event<ProgressNotificationEvent>;
  	/**
  	* Returns a promise for the ongoing refresh. Returns `undefined` if there are no active
  	* refreshes going on.
  	*/
  	getRefreshPromise(options?: GetRefreshEnvironmentsOptions): Promise<void> | undefined;

• Copy over contents of https://github.com/microsoft/vscode-python/blob/main/src/client/apiTypes.ts as needed.

• Discovery is considered finished when all paths are discovered and validated. This API provides a way so other extensions need not wait for validation to finish. For eg. to now get all paths (without waiting for discovery to be finished), we can do:
  Example usage:

const extension = extensions.getExtension('ms-python.python');
if (extension) {
    if (!extension.isActive) {
        await extension.activate();
    }
    const api: IExtensionApi & IProposedExtensionAPI = extension.exports as IExtensionApi & IProposedExtensionAPI;
    if (api.environment) {
        proposedApi.environment.refreshEnvironment();
        // Wait until stage `ProgressReportStage.allPathsDiscovered` has been reached.
        await api.environment.getRefreshPromise({ stage: ProgressReportStage.allPathsDiscovered });
        const envPaths = api.environment.getEnvironmentPaths(); // Verify if all paths have discovered.
    }
}

[rchiodo]

Not sure if this is a bug or not, but the progress for allPathsDiscovered isn't any faster than the full refresh. It takes 30 seconds for allPathsDiscovered and almost immediately after that it says finished.

[karrtikr]

It is probably because validation has already been run for the session, in that case validating it again takes no time, are you querying this API at startup?

For example for me it's:

Can you try to trigger a refresh manually just before fetching "refresh promise"? I have updated the example code:

console.time('All paths found');
console.time('Discovery finishes');
proposedApi.environment.refreshEnvironment();
proposedApi.environment.getRefreshPromise({ stage: ProgressReportStage.allPathsDiscovered })?.then(() => {
    console.timeLog('All paths found');
});

proposedApi.environment.getRefreshPromise()?.then(() => {
    console.timeLog('Discovery finishes');
});

[rchiodo]

I was doing that before (well with 'clearCache' : true) but it makes not difference.

30 seconds or so to get all the paths
Validation is immediate after that.

[rchiodo]

How did you get the 'Conda done' message? Is that just internal to the python extension?

[karrtikr]

Yes atm it's internal to the extension, we discovered it's almost the same time as "all paths found" and so wasn't worth exposing.

Validation is immediate after that.

It maybe the case the validation already finished while waiting for all paths to be discovered (within those 30 seconds), which is why it returns immediately.

[karrtikr]

It maybe the case the validation already finished while waiting for all paths to be discovered (within those 30 seconds), which is why it returns immediately.

If Don also sees the same behavior, I can add some verbose logging to confirm this hypothesis.

[amunger]

I'll try to test this for @DonJayamanne since he is out sick

[amunger]

I see something very similar to what Rich described:

info 10:1:42.322: Jupyter Extension: ENVIRONMENT REFRESH - starting discovery
src/platform/logging/consoleLogger.ts:28
info 10:1:51.856: Jupyter Extension: ENVIRONMENT REFRESH - Progress made, stage: allPathsDiscovered
src/platform/logging/consoleLogger.ts:28
info 10:1:52.151: Jupyter Extension: ENVIRONMENT REFRESH - Progress made, stage: discoveryFinished
src/platform/logging/consoleLogger.ts:28
info 10:1:52.159: Jupyter Extension: ENVIRONMENT REFRESH - discovered paths [{"path"...

but the API seems to work

[karrtikr]

I see, can you please provide the logs as mentioned in the issue template. Set python.logging.level to debug in User settings, reload window, then perform the steps to reproduce before providing the logs.

Output for Python in the Output panel (View→Output, change the drop-down the upper-right of the Output panel to Python)

XXX

It contains the timestamps when validation actually completes, so we can verify #19212 (comment).

[rchiodo]

Here's the data:

Console output of my custom extension:

Note: Using the "preview" debug extension
Note: Using the "preview" debug extension
activating extension
starting language server
Congratulations, your extension "test-python-api" is now active!
2022-5-2 16:10:53.49: REFRESH PROGRESS: discoveryStarted
2022-5-2 16:11:17.132: REFRESH PROGRESS: allPathsDiscovered
2022-5-2 16:11:17.266: REFRESH PROGRESS: discoveryFinished

Python log of this happening
pythonlog.txt
:

[karrtikr]

Thanks! So the API seem to be work as expected, but the logs reveals the reason why time taken to discover all paths is so much. It's because of us running conda run to get executables for conda envs without python, which can probably be avoided. #18934 takes care of it.