Skip to content

Comments

chore: track startup times#22

Merged
skyrpex merged 12 commits intomainfrom
track-extension-startup-times
Sep 4, 2025
Merged

chore: track startup times#22
skyrpex merged 12 commits intomainfrom
track-extension-startup-times

Conversation

@skyrpex
Copy link
Collaborator

@skyrpex skyrpex commented Sep 4, 2025

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

@skyrpex
Copy link
Collaborator Author

skyrpex commented Sep 4, 2025

Example:

2025-09-04 12:32:29.979 [trace] [extension.dependencies]: Starting...
2025-09-04 12:32:29.979 [debug] [container-status.listenToContainerStatus] Spawning 'docker events'...
2025-09-04 12:32:29.979 [trace] [container-status.getContainerStatus]: Starting...
2025-09-04 12:32:29.980 [trace] [container-status.getContainerStatus]: Completed in 232 ms
2025-09-04 12:32:29.980 [trace] [localstack-status.healthCheck]: Starting...
2025-09-04 12:32:29.984 [trace] [localstack-status.healthCheck]: Completed in 14 ms
2025-09-04 12:32:29.984 [trace] [setup-status-tracker]: Starting...
2025-09-04 12:32:29.984 [trace] [setup-status-tracker]: Initialized dependencies in 0 ms
2025-09-04 12:32:29.984 [trace] [setup-status-tracker.checkIsSetupRequired]: Starting...
2025-09-04 12:32:30.417 [trace] [setup-status-tracker.checkIsSetupRequired]: Completed in 433 ms
2025-09-04 12:32:30.418 [trace] [setup-status-tracker]: Completed in 434 ms
2025-09-04 12:32:30.418 [trace] [telemetry]: Starting...
2025-09-04 12:32:30.418 [trace] [telemetry]: Completed in 0 ms
2025-09-04 12:32:30.418 [trace] [extension.dependencies]: Completed in 682 ms
2025-09-04 12:32:30.418 [trace] [extension.activatePlugins]: Starting...
2025-09-04 12:32:30.418 [trace] [extension.plugins]: Activating plugin "setup"...
2025-09-04 12:32:30.419 [trace] [extension.plugins]: Activated plugin "setup" in 0 ms
2025-09-04 12:32:30.419 [trace] [extension.plugins]: Activating plugin "authenticate"...
2025-09-04 12:32:30.419 [trace] [extension.plugins]: Activated plugin "authenticate" in 1 ms
2025-09-04 12:32:30.419 [trace] [extension.plugins]: Activating plugin "configure-aws"...
2025-09-04 12:32:30.419 [trace] [extension.plugins]: Activated plugin "configure-aws" in 0 ms
2025-09-04 12:32:30.419 [trace] [extension.plugins]: Activating plugin "manage"...
2025-09-04 12:32:30.419 [trace] [extension.plugins]: Activated plugin "manage" in 0 ms
2025-09-04 12:32:30.419 [trace] [extension.plugins]: Activating plugin "status-bar"...
2025-09-04 12:32:30.419 [trace] [extension.plugins]: Activated plugin "status-bar" in 0 ms
2025-09-04 12:32:30.419 [trace] [extension.plugins]: Activating plugin "logs"...
2025-09-04 12:32:30.419 [trace] [extension.plugins]: Activated plugin "logs" in 0 ms
2025-09-04 12:32:30.419 [trace] [extension.activatePlugins]: Completed in 1 ms

@skyrpex skyrpex force-pushed the track-extension-startup-times branch from 4c17dfa to 93932f9 Compare September 4, 2025 10:18
@skyrpex skyrpex disabled auto-merge September 4, 2025 10:21
@skyrpex skyrpex enabled auto-merge (squash) September 4, 2025 10:37
options.outputChannel.error(
`[${name}]: Failed after ${timeDiff(start, end)}`,
);
throw error;
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What happens when the error is thrown? I'm trying to understand this specific behaviour

Copy link
Collaborator Author

@skyrpex skyrpex Sep 4, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In the case of an error being thrown, we log the error to the output channel, and re-throw the error. This means that using the time tracker doesn't have any impact on the logic of the tracked callback -- it just logs the time it took either to complete or fail.

Comment on lines +91 to +98
return {
statusBarItem,
containerStatusTracker,
localStackStatusTracker,
setupStatusTracker,
telemetry,
};
});
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

what is the reason of returning these now? 👀

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

statusBarItem, telemetry, etc. are now created inside of a timeTracker.run(...) callback, so they aren't available outside of the callback. To solve this, we take advantage of timeTracker.run(...) returning back the stuff from the callback.

	const {
		statusBarItem,
	} = await timeTracker.run("extension.dependencies", async () => {
		// Not available outside of this callback.
		const statusBarItem = window.createStatusBarItem(
			StatusBarAlignment.Left,
			-1,
		);
		// ...
		// Return them so they can be grabbed outside.
		return {
			statusBarItem,
		};
	});

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

got it, thanks for clarifying that!

skyrpex and others added 4 commits September 4, 2025 13:02
Co-authored-by: Anisa Oshafi <anisaoshafi@gmail.com>
Co-authored-by: Anisa Oshafi <anisaoshafi@gmail.com>
Co-authored-by: Anisa Oshafi <anisaoshafi@gmail.com>
Co-authored-by: Anisa Oshafi <anisaoshafi@gmail.com>
Copy link
Collaborator

@anisaoshafi anisaoshafi left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM 🚀 impressed by how quickly you put this code together!

@skyrpex skyrpex merged commit f62e0cf into main Sep 4, 2025
2 checks passed
@skyrpex skyrpex deleted the track-extension-startup-times branch September 4, 2025 11:21
@joe4dev joe4dev mentioned this pull request Sep 4, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants