Move log activation off the critical extension activation path (#1913)

plemarquand · web-flow · commit b0734af2f5e7 · 2025-11-04T16:28:50.000-05:00
* Move log activation off the critical extension activation path

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,17 +449,30 @@ 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) {
             await this.focusTextEditor(vscode.window.activeTextEditor);
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/FileTransport.ts b/src/logging/FileTransport.ts
@@ -0,0 +1,92 @@
+//===----------------------------------------------------------------------===//
+//
+// This source file is part of the VS Code Swift open source project
+//
+// Copyright (c) 2025 the VS Code Swift project authors
+// Licensed under Apache License v2.0
+//
+// See LICENSE.txt for license information
+// See CONTRIBUTORS.txt for the list of VS Code Swift project authors
+//
+// SPDX-License-Identifier: Apache-2.0
+//
+//===----------------------------------------------------------------------===//
+import * as fs from "fs";
+import * as path from "path";
+import * as TransportType from "winston-transport";
+
+// Compile error if don't use "require": https://github.com/swiftlang/vscode-swift/actions/runs/16529946578/job/46752753379?pr=1746
+// eslint-disable-next-line @typescript-eslint/no-require-imports
+const Transport: typeof TransportType = require("winston-transport");
+
+export class FileTransport extends Transport {
+    private fileHandle: fs.WriteStream | null = null;
+    private pendingLogs: string[] = [];
+    private isReady = false;
+
+    constructor(private readonly filePath: string) {
+        super();
+        this.initializeFile();
+    }
+
+    private initializeFile(): void {
+        try {
+            // Ensure the directory exists
+            const dir = path.dirname(this.filePath);
+            if (!fs.existsSync(dir)) {
+                fs.mkdirSync(dir, { recursive: true });
+            }
+
+            // Create write stream
+            this.fileHandle = fs.createWriteStream(this.filePath, { flags: "a" });
+
+            this.fileHandle.on("ready", () => {
+                this.isReady = true;
+                this.flushPendingLogs();
+            });
+
+            this.fileHandle.on("error", error => {
+                // eslint-disable-next-line no-console
+                console.error(`FileTransport error: ${error}`);
+                this.isReady = false;
+            });
+        } catch (error) {
+            // eslint-disable-next-line no-console
+            console.error(`Failed to initialize FileTransport: ${error}`);
+            this.isReady = false;
+        }
+    }
+
+    private flushPendingLogs(): void {
+        if (this.fileHandle && this.pendingLogs.length > 0) {
+            for (const log of this.pendingLogs) {
+                this.fileHandle.write(log + "\n");
+            }
+            this.pendingLogs = [];
+        }
+    }
+
+    // eslint-disable-next-line @typescript-eslint/no-explicit-any
+    public log(info: any, next: () => void): void {
+        // Get the formatted message from winston
+        const logMessage = info[Symbol.for("message")];
+
+        if (this.isReady && this.fileHandle) {
+            this.fileHandle.write(logMessage + "\n");
+        } else {
+            // Buffer logs if file isn't ready yet
+            this.pendingLogs.push(logMessage);
+        }
+
+        next();
+    }
+
+    public close(): void {
+        if (this.fileHandle) {
+            this.fileHandle.end();
+            this.fileHandle = null;
+        }
+        this.isReady = false;
+        this.pendingLogs = [];
+    }
+}
diff --git a/src/logging/SwiftLogger.ts b/src/logging/SwiftLogger.ts
@@ -15,7 +15,8 @@ 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 { FileTransport } from "./FileTransport";
 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 fileTransport: FileTransport;
+    private cachedOutputChannelLevel: string | undefined;
 
     constructor(
         public readonly name: string,
@@ -42,16 +45,24 @@ export class SwiftLogger implements vscode.Disposable {
         const ouptutChannelTransport = new OutputChannelTransport(this.outputChannel);
         ouptutChannelTransport.level = this.outputChannelLevel;
         const rollingLogTransport = new RollingLogTransport(this.rollingLog);
+
+        // Create file transport
+        this.fileTransport = new FileTransport(this.logFilePath);
+        this.fileTransport.level = "debug"; // File logging at the 'debug' level always
+
+        // Create logger with all transports
+        const transports = [
+            ouptutChannelTransport,
+            this.fileTransport,
+            // 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: transports,
             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`
@@ -71,37 +82,53 @@ export class SwiftLogger implements vscode.Disposable {
                     if (rollingLogTransport.close) {
                         rollingLogTransport.close();
                     }
+                    this.fileTransport.close();
                 },
             },
             vscode.workspace.onDidChangeConfiguration(e => {
                 if (
                     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) {
+        // Log to all transports (output channel, file, console, etc.)
+        if (message instanceof Error) {
+            this.logger.log(level, message);
+        } else {
+            this.logger.log(level, message, meta);
+        }
     }
 
     get logs(): string[] {
@@ -131,16 +158,22 @@ export class SwiftLogger implements vscode.Disposable {
     }
 
     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(
