Move log activation off the critical extension activation path

plemarquand · plemarquand · commit 8fcd96a5f06c · 2025-11-04T10:34:27.000-05:00
Initializing both the file transport and containing folder for the log
files was blocking extension activation, sometimes taking up to
1,500ms.

Move log activation off the critical path of extension activation by
avoiding awaiting promises before continuing activation. Any logs logged
before the file transport is ready are buffered and replayed into the
file transport once file system operations are complete.

This cuts extension activation time down by about 50%.

This patch also adds timing metrics to extension startup, printing them
to the logs, and also adds a new transport to print to the console when
doing extension development.
diff --git a/src/WorkspaceContext.ts b/src/WorkspaceContext.ts
@@ -350,7 +350,12 @@ export class WorkspaceContext implements vscode.Disposable {
         // add workspace folders, already loaded
         if (vscode.workspace.workspaceFolders && vscode.workspace.workspaceFolders.length > 0) {
             for (const folder of vscode.workspace.workspaceFolders) {
+                const singleFolderStartTime = Date.now();
                 await this.addWorkspaceFolder(folder);
+                const singleFolderElapsed = Date.now() - singleFolderStartTime;
+                this.logger.info(
+                    `Added workspace folder ${folder.name} in ${singleFolderElapsed}ms`
+                );
             }
         }
 
@@ -444,20 +449,38 @@ export class WorkspaceContext implements vscode.Disposable {
      * @param folder folder being added
      */
     async addWorkspaceFolder(workspaceFolder: vscode.WorkspaceFolder) {
+        const searchStartTime = Date.now();
         const folders = await searchForPackages(
             workspaceFolder.uri,
             configuration.disableSwiftPMIntegration,
             configuration.folder(workspaceFolder).searchSubfoldersForPackages,
             configuration.folder(workspaceFolder).ignoreSearchingForPackagesInSubfolders,
             this.globalToolchainSwiftVersion
         );
+        const searchElapsed = Date.now() - searchStartTime;
+        this.logger.info(
+            `Package search for ${workspaceFolder.name} completed in ${searchElapsed}ms (found ${folders.length} packages)`
+        );
 
+        const addPackagesStartTime = Date.now();
         for (const folder of folders) {
+            const singlePackageStartTime = Date.now();
             await this.addPackageFolder(folder, workspaceFolder);
+            const singlePackageElapsed = Date.now() - singlePackageStartTime;
+            this.logger.info(`Added package folder ${folder.fsPath} in ${singlePackageElapsed}ms`);
         }
+        const addPackagesElapsed = Date.now() - addPackagesStartTime;
+        this.logger.info(
+            `All package folders for ${workspaceFolder.name} added in ${addPackagesElapsed}ms`
+        );
 
         if (this.getActiveWorkspaceFolder(vscode.window.activeTextEditor) === workspaceFolder) {
+            const focusStartTime = Date.now();
             await this.focusTextEditor(vscode.window.activeTextEditor);
+            const focusElapsed = Date.now() - focusStartTime;
+            this.logger.info(
+                `Focus text editor for ${workspaceFolder.name} completed in ${focusElapsed}ms`
+            );
         }
     }
 
diff --git a/src/extension.ts b/src/extension.ts
@@ -54,22 +54,28 @@ export interface Api {
  * Activate the extension. This is the main entry point.
  */
 export async function activate(context: vscode.ExtensionContext): Promise<Api> {
+    const activationStartTime = Date.now();
     try {
-        await vscode.workspace.fs.createDirectory(context.logUri);
-        const logger = new SwiftLoggerFactory(context.logUri).create(
-            "Swift",
-            "swift-vscode-extension.log"
-        );
-        context.subscriptions.push(logger);
+        const logSetupStartTime = Date.now();
+        const logger = configureLogging(context);
+        const logSetupElapsed = Date.now() - logSetupStartTime;
         logger.info(
             `Activating Swift for Visual Studio Code ${context.extension.packageJSON.version}...`
         );
+        logger.info(`Log setup completed in ${logSetupElapsed}ms`);
 
+        const preToolchainStartTime = Date.now();
         checkAndWarnAboutWindowsSymlinks(logger);
 
         const contextKeys = createContextKeys();
+        const preToolchainElapsed = Date.now() - preToolchainStartTime;
+        const toolchainStartTime = Date.now();
         const toolchain = await createActiveToolchain(context, contextKeys, logger);
+        const toolchainElapsed = Date.now() - toolchainStartTime;
+
+        const swiftlyCheckStartTime = Date.now();
         checkForSwiftlyInstallation(contextKeys, logger);
+        const swiftlyCheckElapsed = Date.now() - swiftlyCheckStartTime;
 
         // If we don't have a toolchain, show an error and stop initializing the extension.
         // This can happen if the user has not installed Swift or if the toolchain is not
@@ -95,9 +101,12 @@ export async function activate(context: vscode.ExtensionContext): Promise<Api> {
             }
         }
 
+        const workspaceContextStartTime = Date.now();
         const workspaceContext = new WorkspaceContext(context, contextKeys, logger, toolchain);
         context.subscriptions.push(workspaceContext);
+        const workspaceContextElapsed = Date.now() - workspaceContextStartTime;
 
+        const subscriptionsStartTime = Date.now();
         context.subscriptions.push(new SwiftEnvironmentVariablesManager(context));
         context.subscriptions.push(SwiftTerminalProfileProvider.register());
         context.subscriptions.push(
@@ -152,12 +161,22 @@ export async function activate(context: vscode.ExtensionContext): Promise<Api> {
         context.subscriptions.push(TestExplorer.observeFolders(workspaceContext));
 
         context.subscriptions.push(registerSourceKitSchemaWatcher(workspaceContext));
+        const subscriptionsElapsed = Date.now() - subscriptionsStartTime;
 
         // setup workspace context with initial workspace folders
-        void workspaceContext.addWorkspaceFolders();
+        const workspaceFoldersStartTime = Date.now();
+        await workspaceContext.addWorkspaceFolders();
+        const workspaceFoldersElapsed = Date.now() - workspaceFoldersStartTime;
 
+        const finalStepsStartTime = Date.now();
         // Mark the extension as activated.
         contextKeys.isActivated = true;
+        const finalStepsElapsed = Date.now() - finalStepsStartTime;
+
+        const totalActivationTime = Date.now() - activationStartTime;
+        logger.info(
+            `Extension activation completed in ${totalActivationTime}ms (log-setup: ${logSetupElapsed}ms, pre-toolchain: ${preToolchainElapsed}ms, toolchain: ${toolchainElapsed}ms, swiftly-check: ${swiftlyCheckElapsed}ms, workspace-context: ${workspaceContextElapsed}ms, subscriptions: ${subscriptionsElapsed}ms, workspace-folders: ${workspaceFoldersElapsed}ms, final-steps: ${finalStepsElapsed}ms)`
+        );
 
         return {
             workspaceContext,
@@ -177,6 +196,26 @@ export async function activate(context: vscode.ExtensionContext): Promise<Api> {
     }
 }
 
+function configureLogging(context: vscode.ExtensionContext) {
+    // Create log directory asynchronously but don't await it to avoid blocking activation
+    const logDirPromise = vscode.workspace.fs.createDirectory(context.logUri);
+
+    const logger = new SwiftLoggerFactory(context.logUri).create(
+        "Swift",
+        "swift-vscode-extension.log"
+    );
+    context.subscriptions.push(logger);
+
+    void Promise.resolve(logDirPromise)
+        .then(() => {
+            // File transport will be added when directory is ready
+        })
+        .catch((error: unknown) => {
+            logger.warn(`Failed to create log directory: ${error}`);
+        });
+    return logger;
+}
+
 function handleFolderEvent(logger: SwiftLogger): (event: FolderEvent) => Promise<void> {
     // function called when a folder is added. I broke this out so we can trigger it
     // without having to await for it.
diff --git a/src/logging/SwiftLogger.ts b/src/logging/SwiftLogger.ts
@@ -11,11 +11,12 @@
 // SPDX-License-Identifier: Apache-2.0
 //
 //===----------------------------------------------------------------------===//
+import * as fs from "fs";
 import * as vscode from "vscode";
 import * as winston from "winston";
 
 import configuration from "../configuration";
-import { IS_RUNNING_UNDER_TEST } from "../utilities/utilities";
+import { IS_RUNNING_IN_DEVELOPMENT_MODE, IS_RUNNING_UNDER_TEST } from "../utilities/utilities";
 import { OutputChannelTransport } from "./OutputChannelTransport";
 import { RollingLog } from "./RollingLog";
 import { RollingLogTransport } from "./RollingLogTransport";
@@ -31,6 +32,8 @@ export class SwiftLogger implements vscode.Disposable {
     private logger: winston.Logger;
     protected rollingLog: RollingLog;
     protected outputChannel: vscode.OutputChannel;
+    private fileTransportReady = false;
+    private pendingLogs: Array<{ level: string; message: string; meta?: LoggerMeta }> = [];
 
     constructor(
         public readonly name: string,
@@ -42,16 +45,19 @@ export class SwiftLogger implements vscode.Disposable {
         const ouptutChannelTransport = new OutputChannelTransport(this.outputChannel);
         ouptutChannelTransport.level = this.outputChannelLevel;
         const rollingLogTransport = new RollingLogTransport(this.rollingLog);
+
+        // Create logger with minimal transports initially for faster startup
+        const initialTransports = [
+            ouptutChannelTransport,
+            // Only want to capture the rolling log in memory when testing
+            ...(IS_RUNNING_UNDER_TEST ? [rollingLogTransport] : []),
+            ...(IS_RUNNING_IN_DEVELOPMENT_MODE
+                ? [new winston.transports.Console({ level: "debug" })]
+                : []),
+        ];
+
         this.logger = winston.createLogger({
-            transports: [
-                new winston.transports.File({
-                    filename: this.logFilePath,
-                    level: "debug", // File logging at the 'debug' level always
-                }),
-                ouptutChannelTransport,
-                // Only want to capture the rolling log in memory when testing
-                ...(IS_RUNNING_UNDER_TEST ? [rollingLogTransport] : []),
-            ],
+            transports: initialTransports,
             format: winston.format.combine(
                 winston.format.errors({ stack: true }),
                 winston.format.timestamp({ format: "YYYY-MM-DD HH:mm:ss.SSS" }), // This is the format of `vscode.LogOutputChannel`
@@ -61,6 +67,43 @@ export class SwiftLogger implements vscode.Disposable {
                 winston.format.colorize()
             ),
         });
+
+        // Add file transport asynchronously to avoid blocking startup
+        setTimeout(() => {
+            try {
+                const fileTransport = new winston.transports.File({
+                    filename: this.logFilePath,
+                    level: "debug", // File logging at the 'debug' level always
+                });
+
+                // Add the file transport to the main logger
+                this.logger.add(fileTransport);
+                this.fileTransportReady = true;
+
+                // Write buffered logs directly to the file using Node.js fs
+                if (this.pendingLogs.length > 0) {
+                    const logEntries =
+                        this.pendingLogs
+                            .map(({ level, message }) => {
+                                const timestamp = new Date()
+                                    .toISOString()
+                                    .replace("T", " ")
+                                    .replace("Z", "");
+                                return `${timestamp} [${level}] ${message}`;
+                            })
+                            .join("\n") + "\n";
+
+                    fs.appendFileSync(this.logFilePath, logEntries);
+                }
+
+                this.pendingLogs = []; // Clear the buffer
+            } catch (error) {
+                // If file transport fails, continue with output channel only
+                this.logger.warn(`Failed to initialize file logging: ${error}`);
+                this.fileTransportReady = true; // Mark as ready even if failed to stop buffering
+                this.pendingLogs = []; // Clear the buffer
+            }
+        }, 0);
         this.disposables.push(
             {
                 dispose: () => {
@@ -78,30 +121,50 @@ export class SwiftLogger implements vscode.Disposable {
                     e.affectsConfiguration("swift.outputChannelLogLevel") ||
                     e.affectsConfiguration("swift.diagnostics")
                 ) {
+                    // Clear cache when configuration changes
+                    this._cachedOutputChannelLevel = undefined;
                     ouptutChannelTransport.level = this.outputChannelLevel;
                 }
             })
         );
     }
 
     debug(message: LoggerMeta, label?: string, options?: LogMessageOptions) {
-        this.logger.debug(this.normalizeMessage(message, label), options);
+        const normalizedMessage = this.normalizeMessage(message, label);
+        this.logWithBuffer("debug", normalizedMessage, options);
     }
 
     info(message: LoggerMeta, label?: string, options?: LogMessageOptions) {
-        this.logger.info(this.normalizeMessage(message, label), options);
+        const normalizedMessage = this.normalizeMessage(message, label);
+        this.logWithBuffer("info", normalizedMessage, options);
     }
 
     warn(message: LoggerMeta, label?: string, options?: LogMessageOptions) {
-        this.logger.warn(this.normalizeMessage(message, label), options);
+        const normalizedMessage = this.normalizeMessage(message, label);
+        this.logWithBuffer("warn", normalizedMessage, options);
     }
 
     error(message: LoggerMeta, label?: string, options?: LogMessageOptions) {
         if (message instanceof Error) {
-            this.logger.error(message);
+            this.logWithBuffer("error", message);
             return;
         }
-        this.logger.error(this.normalizeMessage(message, label), options);
+        const normalizedMessage = this.normalizeMessage(message, label);
+        this.logWithBuffer("error", normalizedMessage, options);
+    }
+
+    private logWithBuffer(level: string, message: string | Error, meta?: LoggerMeta) {
+        // Always log to current transports (output channel, console, etc.)
+        if (message instanceof Error) {
+            this.logger.log(level, message);
+        } else {
+            this.logger.log(level, message, meta);
+        }
+
+        // If file transport isn't ready yet, buffer the log for replay
+        if (!this.fileTransportReady) {
+            this.pendingLogs.push({ level, message: message.toString(), meta });
+        }
     }
 
     get logs(): string[] {
@@ -130,17 +193,25 @@ export class SwiftLogger implements vscode.Disposable {
         return fullMessage;
     }
 
+    private _cachedOutputChannelLevel: string | undefined;
+
     private get outputChannelLevel(): string {
-        const info = vscode.workspace.getConfiguration("swift").inspect("outputChannelLogLevel");
-        // If the user has explicitly set `outputChannelLogLevel` then use it, otherwise
-        // check the deprecated `diagnostics` property
-        if (info?.globalValue || info?.workspaceValue || info?.workspaceFolderValue) {
-            return configuration.outputChannelLogLevel;
-        } else if (configuration.diagnostics) {
-            return "debug";
-        } else {
-            return configuration.outputChannelLogLevel;
+        // Cache the configuration lookup to avoid repeated expensive calls during initialization
+        if (this._cachedOutputChannelLevel === undefined) {
+            const info = vscode.workspace
+                .getConfiguration("swift")
+                .inspect("outputChannelLogLevel");
+            // If the user has explicitly set `outputChannelLogLevel` then use it, otherwise
+            // check the deprecated `diagnostics` property
+            if (info?.globalValue || info?.workspaceValue || info?.workspaceFolderValue) {
+                this._cachedOutputChannelLevel = configuration.outputChannelLogLevel;
+            } else if (configuration.diagnostics) {
+                this._cachedOutputChannelLevel = "debug";
+            } else {
+                this._cachedOutputChannelLevel = configuration.outputChannelLogLevel;
+            }
         }
+        return this._cachedOutputChannelLevel;
     }
 
     dispose() {
diff --git a/src/utilities/utilities.ts b/src/utilities/utilities.ts
@@ -50,6 +50,12 @@ export const IS_RUNNING_UNDER_DOCKER = IS_RUNNING_UNDER_ACT || IS_RUNNING_UNDER_
  */
 export const IS_RUNNING_UNDER_TEST = process.env.RUNNING_UNDER_VSCODE_TEST_CLI === "1";
 
+/**
+ * Determined by the presence of the `VSCODE_DEBUG` environment variable, set by the
+ * launch.json when starting the extension in development.
+ */
+export const IS_RUNNING_IN_DEVELOPMENT_MODE = process.env["VSCODE_DEBUG"] === "1";
+
 /** Determines whether the provided object has any properties set to non-null values. */
 export function isEmptyObject(obj: { [key: string]: unknown }): boolean {
     const properties = Object.getOwnPropertyNames(obj).filter(
