Few Perf Improvements for kernel startup & more logging

src/client/common/installer/productInstaller.ts

@@ -6,11 +6,12 @@ import { IPythonInstaller } from '../../api/types';
 import '../../common/extensions';
 import { InterpreterPackages } from '../../datascience/telemetry/interpreterPackages';
 import { IServiceContainer } from '../../ioc/types';
+import { logValue } from '../../logging/trace';
 import { PythonEnvironment } from '../../pythonEnvironments/info';
 import { getInterpreterHash } from '../../pythonEnvironments/info/interpreter';
 import { IApplicationShell } from '../application/types';
 import { STANDARD_OUTPUT_CHANNEL } from '../constants';
-import { traceError, traceInfo } from '../logger';
+import { traceDecorators, traceError, traceInfo } from '../logger';
 import { IProcessServiceFactory, IPythonExecutionFactory } from '../process/types';
 import {
     IConfigurationService,
@@ -94,8 +95,11 @@ export abstract class BaseInstaller {
             .get<IPythonInstaller>(IPythonInstaller)
             .install(product, resource, cancel, reInstallAndUpdate, installPipIfRequired);
     }
-
-    public async isInstalled(product: Product, resource?: InterpreterUri): Promise<boolean | undefined> {
+    @traceDecorators.verbose('Checking if product is installed')
+    public async isInstalled(
+        product: Product,
+        @logValue('path') resource?: InterpreterUri
+    ): Promise<boolean | undefined> {
         // User may have customized the module name or provided the fully qualified path.
         const interpreter = isResource(resource) ? undefined : resource;
         const uri = isResource(resource) ? resource : undefined;

src/client/common/process/processFactory.ts

@@ -6,6 +6,7 @@
 import { inject, injectable } from 'inversify';
 import { Uri } from 'vscode';
 import { IWorkspaceService } from '../application/types';
+import { traceDecorators } from '../logger';
 import { IDisposableRegistry } from '../types';
 import { IEnvironmentVariablesProvider } from '../variables/types';
 import { ProcessService } from './proc';
@@ -20,6 +21,7 @@ export class ProcessServiceFactory implements IProcessServiceFactory {
         @inject(IDisposableRegistry) private readonly disposableRegistry: IDisposableRegistry,
         @inject(IWorkspaceService) private readonly workspace: IWorkspaceService
     ) {}
+    @traceDecorators.verbose('Create ProcessService')
     public async create(resource?: Uri): Promise<IProcessService> {
         // This should never happen, but if it does ensure we never run code accidentally in untrusted workspaces.
         if (!this.workspace.isTrusted) {

src/client/common/process/pythonExecutionFactory.ts

@@ -57,6 +57,7 @@ export class PythonExecutionFactory implements IPythonExecutionFactory {
         this.logger = this.serviceContainer.get<IProcessLogger>(IProcessLogger);
         this.fileSystem = this.serviceContainer.get<IFileSystem>(IFileSystem);
     }
+    @traceDecorators.verbose('Creating execution process')
     public async create(options: ExecutionFactoryCreationOptions): Promise<IPythonExecutionService> {
         const pythonPath = options.pythonPath ? options.pythonPath : await this.getPythonPath(options.resource);
         const processService: IProcessService = await this.processServiceFactory.create(options.resource);
@@ -70,7 +71,7 @@ export class PythonExecutionFactory implements IPythonExecutionFactory {
         );
     }
 
-    @traceDecorators.verbose('Create daemon', TraceOptions.BeforeCall)
+    @traceDecorators.verbose('Create daemon')
     public async createDaemon<T extends IPythonDaemonExecutionService | IDisposable>(
         options: DaemonExecutionFactoryCreationOptions
     ): Promise<T | IPythonExecutionService> {

src/client/common/utils/misc.ts

@@ -70,14 +70,14 @@ export type TraceInfo =
 export function tracing<T>(log: (t: TraceInfo) => void, run: () => T, logBeforeCall?: boolean): T {
     const timer = new StopWatch();
     try {
+        if (logBeforeCall) {
+            log(undefined);
+        }
         // eslint-disable-next-line no-invalid-this, @typescript-eslint/no-use-before-define,
         const result = run();
 
         // If method being wrapped returns a promise then wait for it.
         if (isPromise(result)) {
-            if (logBeforeCall) {
-                log(undefined);
-            }
             // eslint-disable-next-line
             (result as Promise<void>)
                 .then((data) => {

src/client/datascience/jupyter/kernels/helpers.ts

@@ -439,6 +439,21 @@ export function isLocalLaunch(configuration: IConfigurationService) {
     return false;
 }
 
+export function getInterpreterHashInMetdata(
+    notebookMetadata: nbformat.INotebookMetadata | undefined
+): string | undefined {
+    // If the user has kernelspec in metadata & the interpreter hash is stored in metadata, then its a perfect match.
+    // This is the preferred approach https://github.com/microsoft/vscode-jupyter/issues/5612
+    if (
+        typeof notebookMetadata === 'object' &&
+        'interpreter' in notebookMetadata &&
+        (notebookMetadata as any).interpreter &&
+        typeof (notebookMetadata as any).interpreter === 'object' &&
+        'hash' in (notebookMetadata as any).interpreter
+    ) {
+        return (notebookMetadata as any).interpreter.hash;
+    }
+}
 export function findPreferredKernel(
     kernels: KernelConnectionMetadata[],
     resource: Resource,
@@ -604,15 +619,11 @@ export function findPreferredKernel(
 
                 // If the user has kernelspec in metadata & the interpreter hash is stored in metadata, then its a perfect match.
                 // This is the preferred approach https://github.com/microsoft/vscode-jupyter/issues/5612
+                const interpreterHashInMetadata = getInterpreterHashInMetdata(notebookMetadata);
                 if (
-                    typeof notebookMetadata === 'object' &&
-                    'interpreter' in notebookMetadata &&
-                    (notebookMetadata as any).interpreter &&
-                    typeof (notebookMetadata as any).interpreter === 'object' &&
-                    'hash' in (notebookMetadata as any).interpreter &&
                     (metadata.kind === 'startUsingKernelSpec' || metadata.kind === 'startUsingPythonInterpreter') &&
                     metadata.interpreter &&
-                    getInterpreterHash(metadata.interpreter) === (notebookMetadata as any).interpreter.hash
+                    getInterpreterHash(metadata.interpreter) === interpreterHashInMetadata
                 ) {
                     // This is a perfect match.
                     traceInfoIfCI('Increased score by +100 for matching interpreter in notbeook metadata');

src/client/datascience/kernel-launcher/jupyterPaths.ts

@@ -2,11 +2,11 @@
 // Licensed under the MIT License.
 'use strict';
 
-import { inject, injectable } from 'inversify';
+import { inject, injectable, named } from 'inversify';
 import * as path from 'path';
-import { CancellationToken } from 'vscode';
+import { CancellationToken, Memento } from 'vscode';
 import { IPlatformService } from '../../common/platform/types';
-import { IPathUtils } from '../../common/types';
+import { GLOBAL_MEMENTO, IDisposableRegistry, IMemento, IPathUtils } from '../../common/types';
 import { IEnvironmentVariablesProvider } from '../../common/variables/types';
 import { traceDecorators } from '../../logging';
 import { tryGetRealPath } from '../common';
@@ -15,29 +15,57 @@ const winJupyterPath = path.join('AppData', 'Roaming', 'jupyter', 'kernels');
 const linuxJupyterPath = path.join('.local', 'share', 'jupyter', 'kernels');
 const macJupyterPath = path.join('Library', 'Jupyter', 'kernels');
 export const baseKernelPath = path.join('share', 'jupyter', 'kernels');
+const CACHE_KEY_FOR_JUPYTER_KERNELSPEC_ROOT_PATH = 'CACHE_KEY_FOR_JUPYTER_KERNELSPEC_ROOT_PATH';
+const CACHE_KEY_FOR_JUPYTER_PATHS = 'CACHE_KEY_FOR_JUPYTER_PATHS';
 
 @injectable()
 export class JupyterPaths {
+    private cachedKernelSpecRootPath?: Promise<string | undefined>;
+    private cachedJupyterPaths?: Promise<string[]>;
     constructor(
         @inject(IPlatformService) private platformService: IPlatformService,
         @inject(IPathUtils) private readonly pathUtils: IPathUtils,
-        @inject(IEnvironmentVariablesProvider) private readonly envVarsProvider: IEnvironmentVariablesProvider
-    ) {}
+        @inject(IEnvironmentVariablesProvider) private readonly envVarsProvider: IEnvironmentVariablesProvider,
+        @inject(IDisposableRegistry) disposables: IDisposableRegistry,
+        @inject(IMemento) @named(GLOBAL_MEMENTO) private readonly globalState: Memento
+    ) {
+        this.envVarsProvider.onDidEnvironmentVariablesChange(
+            () => {
+                this.cachedJupyterPaths = undefined;
+            },
+            this,
+            disposables
+        );
+    }
 
     /**
      * This should return a WRITABLE place that jupyter will look for a kernel as documented
      * here: https://jupyter-client.readthedocs.io/en/stable/kernels.html#kernel-specs
      */
+    @traceDecorators.verbose('Getting Jupyter KernelSpec Root Path')
     public async getKernelSpecRootPath(): Promise<string | undefined> {
-        if (this.platformService.isWindows) {
-            // On windows the path is not correct if we combine those variables.
-            // It won't point to a path that you can actually read from.
-            return tryGetRealPath(path.join(this.pathUtils.home, winJupyterPath));
-        } else if (this.platformService.isMac) {
-            return path.join(this.pathUtils.home, macJupyterPath);
-        } else {
-            return path.join(this.pathUtils.home, linuxJupyterPath);
+        this.cachedKernelSpecRootPath =
+            this.cachedKernelSpecRootPath ||
+            (async () => {
+                if (this.platformService.isWindows) {
+                    // On windows the path is not correct if we combine those variables.
+                    // It won't point to a path that you can actually read from.
+                    return tryGetRealPath(path.join(this.pathUtils.home, winJupyterPath));
+                } else if (this.platformService.isMac) {
+                    return path.join(this.pathUtils.home, macJupyterPath);
+                } else {
+                    return path.join(this.pathUtils.home, linuxJupyterPath);
+                }
+            })();
+        void this.cachedKernelSpecRootPath.then((value) => {
+            if (value) {
+                void this.globalState.update(CACHE_KEY_FOR_JUPYTER_KERNELSPEC_ROOT_PATH, value);
+            }
+        });
+        if (this.globalState.get(CACHE_KEY_FOR_JUPYTER_KERNELSPEC_ROOT_PATH)) {
+            return this.globalState.get(CACHE_KEY_FOR_JUPYTER_KERNELSPEC_ROOT_PATH);
         }
+        return this.cachedKernelSpecRootPath;
     }
     /**
      * This list comes from the docs here:
@@ -76,27 +104,41 @@ export class JupyterPaths {
      * We need to look at the 'kernels' sub-directory and these paths are supposed to come first in the searching
      * https://jupyter.readthedocs.io/en/latest/projects/jupyter-directories.html#envvar-JUPYTER_PATH
      */
+    @traceDecorators.verbose('Get Jupyter Paths')
     private async getJupyterPathPaths(cancelToken?: CancellationToken): Promise<string[]> {
-        const paths: string[] = [];
-        const vars = await this.envVarsProvider.getEnvironmentVariables();
-        if (cancelToken?.isCancellationRequested) {
-            return [];
-        }
-        const jupyterPathVars = vars.JUPYTER_PATH
-            ? vars.JUPYTER_PATH.split(path.delimiter).map((jupyterPath) => {
-                  return path.join(jupyterPath, 'kernels');
-              })
-            : [];
+        this.cachedJupyterPaths =
+            this.cachedJupyterPaths ||
+            (async () => {
+                const paths: string[] = [];
+                const vars = await this.envVarsProvider.getEnvironmentVariables();
+                if (cancelToken?.isCancellationRequested) {
+                    return [];
+                }
+                const jupyterPathVars = vars.JUPYTER_PATH
+                    ? vars.JUPYTER_PATH.split(path.delimiter).map((jupyterPath) => {
+                          return path.join(jupyterPath, 'kernels');
+                      })
+                    : [];
 
-        if (jupyterPathVars.length > 0) {
-            jupyterPathVars.forEach(async (jupyterPath) => {
-                const realPath = await tryGetRealPath(jupyterPath);
-                if (realPath) {
-                    paths.push(realPath);
+                if (jupyterPathVars.length > 0) {
+                    jupyterPathVars.forEach(async (jupyterPath) => {
+                        const realPath = await tryGetRealPath(jupyterPath);
+                        if (realPath) {
+                            paths.push(realPath);
+                        }
+                    });
                 }
-            });
-        }
 
-        return paths;
+                return paths;
+            })();
+        void this.cachedJupyterPaths.then((value) => {
+            if (value.length > 0) {
+                void this.globalState.update(CACHE_KEY_FOR_JUPYTER_PATHS, value);
+            }
+        });
+        if (this.globalState.get<string[]>(CACHE_KEY_FOR_JUPYTER_PATHS, []).length > 0) {
+            return this.globalState.get<string[]>(CACHE_KEY_FOR_JUPYTER_PATHS, []);
+        }
+        return this.cachedJupyterPaths;
     }
 }

src/client/datascience/kernel-launcher/kernelDaemonPool.ts

@@ -14,7 +14,7 @@ import { IDisposable, Resource } from '../../common/types';
 import { noop } from '../../common/utils/misc';
 import { IEnvironmentVariablesProvider } from '../../common/variables/types';
 import { IInterpreterService } from '../../interpreter/contracts';
-import { TraceOptions } from '../../logging/trace';
+import { logValue, TraceOptions } from '../../logging/trace';
 import { PythonEnvironment } from '../../pythonEnvironments/info';
 import { KernelLauncherDaemonModule } from '../constants';
 import { IJupyterKernelSpec, IKernelDependencyService } from '../types';
@@ -72,11 +72,11 @@ export class KernelDaemonPool implements IDisposable {
     public dispose() {
         this.disposables.forEach((item) => item.dispose());
     }
-    @traceDecorators.verbose('Get kernel daemon', TraceOptions.BeforeCall)
+    @traceDecorators.verbose('Get kernel daemon', TraceOptions.BeforeCall | TraceOptions.Arguments)
     public async get(
         resource: Resource,
-        kernelSpec: IJupyterKernelSpec,
-        interpreter?: PythonEnvironment
+        @logValue<IJupyterKernelSpec>('id') kernelSpec: IJupyterKernelSpec,
+        @logValue<PythonEnvironment>('path') interpreter?: PythonEnvironment
     ): Promise<IPythonKernelDaemon | IPythonExecutionService> {
         const pythonPath = interpreter?.path || kernelSpec.argv[0];
         // If we have environment variables in the kernel.json, then its not we support.

src/client/datascience/kernel-launcher/kernelLauncherDaemon.ts

@@ -12,7 +12,6 @@ import { IPythonExecutionFactory, ObservableExecutionResult } from '../../common
 import { IDisposable, Resource } from '../../common/types';
 import { noop } from '../../common/utils/misc';
 import { traceDecorators } from '../../logging';
-import { TraceOptions } from '../../logging/trace';
 import { logValue } from '../../logging/trace';
 import { PythonEnvironment } from '../../pythonEnvironments/info';
 import { IJupyterKernelSpec } from '../types';
@@ -34,7 +33,7 @@ export class PythonKernelLauncherDaemon implements IDisposable {
         @inject(KernelEnvironmentVariablesService)
         private readonly kernelEnvVarsService: KernelEnvironmentVariablesService
     ) {}
-    @traceDecorators.verbose('Launching kernel daemon', TraceOptions.BeforeCall)
+    @traceDecorators.verbose('Launching kernel daemon')
     public async launch(
         resource: Resource,
         workingDirectory: string,

src/client/datascience/kernel-launcher/kernelProcess.ts

@@ -43,7 +43,7 @@ import { KernelProcessExitedError } from '../errors/kernelProcessExitedError';
 import { PythonKernelDiedError } from '../errors/pythonKernelDiedError';
 import { KernelDiedError } from '../errors/kernelDiedError';
 import { KernelPortNotUsedTimeoutError } from '../errors/kernelPortNotUsedTimeoutError';
-import { ignoreLogging, TraceOptions } from '../../logging/trace';
+import { ignoreLogging } from '../../logging/trace';
 
 // Launches and disposes a kernel process given a kernelspec and a resource or python interpreter.
 // Exposes connection information and the process itself.
@@ -387,7 +387,7 @@ export class KernelProcess implements IKernelProcess {
         return newConnectionArgs;
     }
 
-    @traceDecorators.verbose('Launching kernel in kernelProcess.ts', TraceOptions.BeforeCall)
+    @traceDecorators.verbose('Launching kernel in kernelProcess.ts')
     private async launchAsObservable(workingDirectory: string, @ignoreLogging() cancelToken: CancellationToken) {
         let exeObs: ObservableExecutionResult<string> | undefined;
 

src/client/datascience/notebook/notebookControllerManager.ts

@@ -391,7 +391,7 @@ export class NotebookControllerManager implements INotebookControllerManager, IE
 
         // Prep so that we can track the selected controller for this document
         traceInfoIfCI(`Clear controller mapping for ${getDisplayPath(document.uri)}`);
-        const loadControllersPromise = this.loadNotebookControllers();
+        void this.loadNotebookControllers();
 
         if (
             isPythonNotebook(getNotebookMetadata(document)) &&
@@ -454,9 +454,6 @@ export class NotebookControllerManager implements INotebookControllerManager, IE
                     )}`
                 );
             }
-            // Wait for our controllers to be loaded before we try to set a preferred on
-            // can happen if a document is opened quick and we have not yet loaded our controllers
-            await loadControllersPromise;
             const targetController = Array.from(this.registeredControllers.values()).find(
                 (value) => preferredConnection?.id === value.connection.id
             );
@@ -470,11 +467,15 @@ export class NotebookControllerManager implements INotebookControllerManager, IE
                 // Save in our map so we can find it in test code.
                 this.preferredControllers.set(document, targetController);
             } else {
-                traceInfoIfCI(
-                    `TargetController not found ID: ${preferredConnection?.id} for document ${getDisplayPath(
-                        document.uri
-                    )}`
-                );
+                // Possible the kernel discovery hasn't completed yet.
+                if (preferredConnection) {
+                    this.createNotebookControllers([preferredConnection]);
+                    traceInfoIfCI(
+                        `TargetController not found ID: ${preferredConnection?.id} for document ${getDisplayPath(
+                            document.uri
+                        )}`
+                    );
+                }
             }
         } catch (ex) {
             traceError('Failed to find & set preferred controllers', ex);