chore: track startup times (#22)

Adds profiling traces to the output channel for the startup times of the
extension and its plugins.

Author: skyrpex

package-lock.json

@@ -126,6 +126,7 @@
 		"@eslint/js": "^9.34.0",
 		"@types/fs-extra": "^11.0.4",
 		"@types/mocha": "^10.0.10",
+		"@types/ms": "^2.1.0",
 		"@types/node": "20.x",
 		"@types/vscode": "^1.83.0",
 		"@vscode/test-cli": "^0.0.11",
@@ -135,6 +136,7 @@
 		"eslint": "^9.34.0",
 		"eslint-plugin-import": "^2.32.0",
 		"fs-extra": "^11.3.1",
+		"ms": "^2.1.3",
 		"npm-run-all": "^4.1.5",
 		"p-min-delay": "^4.1.0",
 		"typescript": "^5.9.2",

package.json

@@ -1,3 +1,4 @@
+import ms from "ms";
 import { StatusBarAlignment, window } from "vscode";
 import type { ExtensionContext } from "vscode";
 
@@ -13,6 +14,7 @@ import { createLocalStackStatusTracker } from "./utils/localstack-status.ts";
 import { getOrCreateExtensionSessionId } from "./utils/manage.ts";
 import { createSetupStatusTracker } from "./utils/setup-status.ts";
 import { createTelemetry } from "./utils/telemetry.ts";
+import { createTimeTracker } from "./utils/time-tracker.ts";
 
 const plugins = new PluginManager([
 	setup,
@@ -29,36 +31,83 @@ export async function activate(context: ExtensionContext) {
 	});
 	context.subscriptions.push(outputChannel);
 
-	const statusBarItem = window.createStatusBarItem(StatusBarAlignment.Left, -1);
-	context.subscriptions.push(statusBarItem);
-	statusBarItem.text = "$(loading~spin) LocalStack";
-	statusBarItem.show();
+	const timeTracker = createTimeTracker({ outputChannel });
 
-	const containerStatusTracker = await createContainerStatusTracker(
-		"localstack-main",
-		outputChannel,
-	);
-	context.subscriptions.push(containerStatusTracker);
-
-	const localStackStatusTracker = await createLocalStackStatusTracker(
-		containerStatusTracker,
-		outputChannel,
-	);
-	context.subscriptions.push(localStackStatusTracker);
-
-	const setupStatusTracker = await createSetupStatusTracker(outputChannel);
-
-	const sessionId = await getOrCreateExtensionSessionId(context);
-	const telemetry = createTelemetry(outputChannel, sessionId);
-
-	await plugins.activate({
-		context,
-		outputChannel,
-		statusBarItem,
+	const {
 		containerStatusTracker,
 		localStackStatusTracker,
 		setupStatusTracker,
+		statusBarItem,
 		telemetry,
+	} = await timeTracker.run("extension.dependencies", async () => {
+		const statusBarItem = window.createStatusBarItem(
+			StatusBarAlignment.Left,
+			-1,
+		);
+		context.subscriptions.push(statusBarItem);
+		statusBarItem.text = "$(loading~spin) LocalStack";
+		statusBarItem.show();
+
+		const containerStatusTracker = await createContainerStatusTracker(
+			"localstack-main",
+			outputChannel,
+			timeTracker,
+		);
+		context.subscriptions.push(containerStatusTracker);
+
+		const localStackStatusTracker = await createLocalStackStatusTracker(
+			containerStatusTracker,
+			outputChannel,
+			timeTracker,
+		);
+		context.subscriptions.push(localStackStatusTracker);
+
+		outputChannel.trace(`[setup-status]: Starting...`);
+		const startStatusTracker = Date.now();
+		const setupStatusTracker = await createSetupStatusTracker(
+			outputChannel,
+			timeTracker,
+		);
+		context.subscriptions.push(setupStatusTracker);
+		const endStatusTracker = Date.now();
+		outputChannel.trace(
+			`[setup-status]: Completed in ${ms(
+				endStatusTracker - startStatusTracker,
+				{ long: true },
+			)}`,
+		);
+
+		const startTelemetry = Date.now();
+		outputChannel.trace(`[telemetry]: Starting...`);
+		const sessionId = await getOrCreateExtensionSessionId(context);
+		const telemetry = createTelemetry(outputChannel, sessionId);
+		const endTelemetry = Date.now();
+		outputChannel.trace(
+			`[telemetry]: Completed in ${ms(endTelemetry - startTelemetry, {
+				long: true,
+			})}`,
+		);
+
+		return {
+			statusBarItem,
+			containerStatusTracker,
+			localStackStatusTracker,
+			setupStatusTracker,
+			telemetry,
+		};
+	});
+
+	await timeTracker.run("extension.activatePlugins", async () => {
+		await plugins.activate({
+			context,
+			outputChannel,
+			statusBarItem,
+			containerStatusTracker,
+			localStackStatusTracker,
+			setupStatusTracker,
+			telemetry,
+			timeTracker,
+		});
 	});
 }
 

src/extension.ts

@@ -1,9 +1,11 @@
+import ms from "ms";
 import type { ExtensionContext, LogOutputChannel, StatusBarItem } from "vscode";
 
 import type { ContainerStatusTracker } from "./utils/container-status.ts";
 import type { LocalStackStatusTracker } from "./utils/localstack-status.ts";
 import type { SetupStatusTracker } from "./utils/setup-status.ts";
 import type { Telemetry } from "./utils/telemetry.ts";
+import type { TimeTracker } from "./utils/time-tracker.ts";
 
 export type Deactivate = () => Promise<void> | void;
 
@@ -15,40 +17,59 @@ export interface PluginOptions {
 	localStackStatusTracker: LocalStackStatusTracker;
 	setupStatusTracker: SetupStatusTracker;
 	telemetry: Telemetry;
+	timeTracker: TimeTracker;
 }
 
 export interface Plugin {
 	deactivate: Deactivate;
 }
 
-export type PluginFactory = (options: PluginOptions) => Promise<Plugin>;
+export type PluginDefinition = {
+	name: string;
+	factory: (options: PluginOptions) => Promise<Plugin>;
+};
 
 export const createPlugin = (
+	name: string,
 	// biome-ignore lint/suspicious/noConfusingVoidType: required
 	handler: (options: PluginOptions) => Promise<Deactivate | void> | void,
-): PluginFactory => {
-	return async (options) => {
-		const deactivate = (await handler(options)) ?? (() => {});
-		return {
-			deactivate,
-		};
+): PluginDefinition => {
+	return {
+		name,
+		async factory(options: PluginOptions): Promise<Plugin> {
+			const deactivate = (await handler(options)) ?? (() => {});
+			return {
+				deactivate,
+			};
+		},
 	};
 };
 
 export class PluginManager {
-	private plugins: PluginFactory[];
+	private plugins: PluginDefinition[];
 
 	private deactivatables: Plugin[];
 
-	constructor(plugins: PluginFactory[]) {
+	constructor(plugins: PluginDefinition[]) {
 		this.plugins = plugins;
 		this.deactivatables = [];
 	}
 
 	async activate(options: PluginOptions) {
 		for (const activate of this.plugins) {
-			const deactivatable = await activate(options);
+			const startPlugin = Date.now();
+			options.outputChannel.trace(
+				`[extension.plugins]: Activating plugin "${activate.name}"...`,
+			);
+			const deactivatable = await activate.factory(options);
 			this.deactivatables.push(deactivatable);
+			const endPlugin = Date.now();
+			options.outputChannel.trace(
+				`[extension.plugins]: Activated plugin "${activate.name}" in ${ms(
+					endPlugin - startPlugin,
+					{ long: true },
+				)}`,
+			);
 		}
 	}