Log spawning of processes (#756)

For https://github.com/microsoft/vscode-python-environments/issues/734

Author: DonJayamanne

src/features/terminal/shells/cmd/cmdStartup.ts

@@ -10,8 +10,14 @@ import { ShellConstants } from '../../../common/shellConstants';
 import { hasStartupCode, insertStartupCode, removeStartupCode } from '../common/editUtils';
 import { ShellScriptEditState, ShellSetupState, ShellStartupScriptProvider } from '../startupProvider';
 import { CMD_ENV_KEY, CMD_SCRIPT_VERSION } from './cmdConstants';
+import { StopWatch } from '../../../../common/stopWatch';
 
-const exec = promisify(cp.exec);
+function execCommand(command: string) {
+    const timer = new StopWatch();
+    return promisify(cp.exec)(command, { windowsHide: true }).finally(() =>
+        traceInfo(`Executed command: ${command} in ${timer.elapsedTime}`),
+    );
+}
 
 async function isCmdInstalled(): Promise<boolean> {
     if (!isWindows()) {
@@ -94,9 +100,7 @@ async function checkRegistryAutoRun(mainBatchFile: string, regMainBatchFile: str
 
     try {
         // Check if AutoRun is set in the registry to call our batch file
-        const { stdout } = await exec('reg query "HKCU\\Software\\Microsoft\\Command Processor" /v AutoRun', {
-            windowsHide: true,
-        });
+        const { stdout } = await execCommand('reg query "HKCU\\Software\\Microsoft\\Command Processor" /v AutoRun');
 
         // Check if the output contains our batch file path
         return stdout.includes(regMainBatchFile) || stdout.includes(mainBatchFile);
@@ -112,9 +116,7 @@ async function getExistingAutoRun(): Promise<string | undefined> {
     }
 
     try {
-        const { stdout } = await exec('reg query "HKCU\\Software\\Microsoft\\Command Processor" /v AutoRun', {
-            windowsHide: true,
-        });
+        const { stdout } = await execCommand('reg query "HKCU\\Software\\Microsoft\\Command Processor" /v AutoRun');
 
         const match = stdout.match(/AutoRun\s+REG_SZ\s+(.*)/);
         if (match && match[1]) {
@@ -135,9 +137,8 @@ async function setupRegistryAutoRun(mainBatchFile: string): Promise<boolean> {
 
     try {
         // Set the registry key to call our main batch file
-        await exec(
+        await execCommand(
             `reg add "HKCU\\Software\\Microsoft\\Command Processor" /v AutoRun /t REG_SZ /d "if exist \\"${mainBatchFile}\\" call \\"${mainBatchFile}\\"" /f`,
-            { windowsHide: true },
         );
 
         traceInfo(

src/features/terminal/shells/utils.ts

@@ -1,13 +1,16 @@
 import * as cp from 'child_process';
-import { traceVerbose } from '../../../common/logging';
+import { traceError, traceInfo } from '../../../common/logging';
+import { StopWatch } from '../../../common/stopWatch';
 
 export async function runCommand(command: string): Promise<string | undefined> {
     return new Promise((resolve) => {
+        const timer = new StopWatch();
         cp.exec(command, (err, stdout) => {
             if (err) {
-                traceVerbose(`Error running command: ${command}`, err);
+                traceError(`Error running command: ${command} (${timer.elapsedTime})`, err);
                 resolve(undefined);
             } else {
+                traceInfo(`Ran ${command} in ${timer.elapsedTime}`);
                 resolve(stdout?.trim());
             }
         });

src/managers/builtin/helpers.ts

@@ -9,7 +9,7 @@ export async function isUvInstalled(log?: LogOutputChannel): Promise<boolean> {
     if (available.completed) {
         return available.promise;
     }
-
+    log?.info(`Running: uv --version`);
     const proc = ch.spawn('uv', ['--version']);
     proc.on('error', () => {
         available.resolve(false);

src/managers/conda/condaUtils.ts

@@ -56,6 +56,7 @@ import { Installable } from '../common/types';
 import { shortVersion, sortEnvironments } from '../common/utils';
 import { CondaEnvManager } from './condaEnvManager';
 import { getCondaHookPs1Path, getLocalActivationScript } from './condaSourcingUtils';
+import { StopWatch } from '../../common/stopWatch';
 
 export const CONDA_PATH_KEY = `${ENVS_EXTENSION_ID}:conda:CONDA_PATH`;
 export const CONDA_PREFIXES_KEY = `${ENVS_EXTENSION_ID}:conda:CONDA_PREFIXES`;
@@ -202,6 +203,8 @@ async function _runConda(
 ): Promise<string> {
     const deferred = createDeferred<string>();
     args = quoteArgs(args);
+    const timer = new StopWatch();
+    deferred.promise.finally(() => traceInfo(`Ran conda in ${timer.elapsedTime}: ${conda} ${args.join(' ')}`));
     const proc = ch.spawn(conda, args, { shell: true });
 
     token?.onCancellationRequested(() => {