Adds better Stopwatch & overhauls logging levels

Avoids process.hrtime for web builds

src/annotations/gutterBlameAnnotationProvider.ts

@@ -5,7 +5,7 @@ import { GlyphChars } from '../constants';
 import { Container } from '../container';
 import { CommitFormatOptions, CommitFormatter, GitBlame, GitBlameCommit } from '../git/git';
 import { Logger } from '../logger';
-import { Arrays, Iterables, log, Strings } from '../system';
+import { Arrays, Iterables, log, Stopwatch, Strings } from '../system';
 import { GitDocumentState } from '../trackers/gitDocumentTracker';
 import { TrackedDocument } from '../trackers/trackedDocument';
 import { AnnotationContext } from './annotationProvider';
@@ -37,7 +37,7 @@ export class GutterBlameAnnotationProvider extends BlameAnnotationProviderBase {
 		const blame = await this.getBlame();
 		if (blame == null) return false;
 
-		let start = process.hrtime();
+		const sw = new Stopwatch(cc!);
 
 		const cfg = this.container.config.blame;
 
@@ -157,16 +157,14 @@ export class GutterBlameAnnotationProvider extends BlameAnnotationProviderBase {
 			decorationsMap.set(l.sha, gutter);
 		}
 
-		Logger.log(cc, `${Strings.getDurationMilliseconds(start)} ms to compute gutter blame annotations`);
+		sw.restart({ suffix: ' to compute gutter blame annotations' });
 
 		if (decorationOptions.length) {
-			start = process.hrtime();
-
 			this.setDecorations([
 				{ decorationType: Decorations.gutterBlameAnnotation, rangesOrOptions: decorationOptions },
 			]);
 
-			Logger.log(cc, `${Strings.getDurationMilliseconds(start)} ms to apply all gutter blame annotations`);
+			sw.stop({ suffix: ' to apply all gutter blame annotations' });
 		}
 
 		this.registerHoverProviders(this.container.config.hovers.annotations);

src/annotations/gutterChangesAnnotationProvider.ts

@@ -18,7 +18,7 @@ import { Container } from '../container';
 import { GitDiff, GitLogCommit } from '../git/git';
 import { Hovers } from '../hovers/hovers';
 import { Logger } from '../logger';
-import { log, Strings } from '../system';
+import { log, Stopwatch } from '../system';
 import { GitDocumentState, TrackedDocument } from '../trackers/gitDocumentTracker';
 import { AnnotationContext, AnnotationProviderBase } from './annotationProvider';
 import { Decorations } from './fileAnnotationController';
@@ -155,7 +155,7 @@ export class GutterChangesAnnotationProvider extends AnnotationProviderBase
 		).filter(<T>(d?: T): d is T => Boolean(d));
 		if (!diffs?.length) return false;
 
-		let start = process.hrtime();
+		const sw = new Stopwatch(cc!);
 
 		const decorationsMap = new Map<
 			string,
@@ -262,14 +262,12 @@ export class GutterChangesAnnotationProvider extends AnnotationProviderBase
 			}
 		}
 
-		Logger.log(cc, `${Strings.getDurationMilliseconds(start)} ms to compute recent changes annotations`);
+		sw.restart({ suffix: ' to compute recent changes annotations' });
 
 		if (decorationsMap.size) {
-			start = process.hrtime();
-
 			this.setDecorations([...decorationsMap.values()]);
 
-			Logger.log(cc, `${Strings.getDurationMilliseconds(start)} ms to apply recent changes annotations`);
+			sw.stop({ suffix: ' to apply all recent changes annotations' });
 
 			if (selection != null && context?.selection !== false) {
 				this.editor.selection = selection;

src/annotations/gutterHeatmapBlameAnnotationProvider.ts

@@ -4,7 +4,7 @@ import { FileAnnotationType } from '../configuration';
 import { Container } from '../container';
 import { GitBlameCommit } from '../git/git';
 import { Logger } from '../logger';
-import { log, Strings } from '../system';
+import { log, Stopwatch } from '../system';
 import { GitDocumentState } from '../trackers/gitDocumentTracker';
 import { TrackedDocument } from '../trackers/trackedDocument';
 import { AnnotationContext } from './annotationProvider';
@@ -25,7 +25,7 @@ export class GutterHeatmapBlameAnnotationProvider extends BlameAnnotationProvide
 		const blame = await this.getBlame();
 		if (blame == null) return false;
 
-		let start = process.hrtime();
+		const sw = new Stopwatch(cc!);
 
 		const decorationsMap = new Map<
 			string,
@@ -49,14 +49,12 @@ export class GutterHeatmapBlameAnnotationProvider extends BlameAnnotationProvide
 			);
 		}
 
-		Logger.log(cc, `${Strings.getDurationMilliseconds(start)} ms to compute heatmap annotations`);
+		sw.restart({ suffix: ' to compute heatmap annotations' });
 
 		if (decorationsMap.size) {
-			start = process.hrtime();
-
 			this.setDecorations([...decorationsMap.values()]);
 
-			Logger.log(cc, `${Strings.getDurationMilliseconds(start)} ms to apply recent changes annotations`);
+			sw.stop({ suffix: ' to apply all heatmap annotations' });
 		}
 
 		// this.registerHoverProviders(this.container.config.hovers.annotations);

src/avatars.ts

@@ -4,8 +4,7 @@ import { GravatarDefaultStyle } from './config';
 import { GlobalState } from './constants';
 import { Container } from './container';
 import { GitRevisionReference } from './git/git';
-import { Functions, Iterables, Strings } from './system';
-import { MillisecondsPerDay, MillisecondsPerHour, MillisecondsPerMinute } from './system/date';
+import { Dates, Functions, Iterables, Strings } from './system';
 import { ContactPresenceStatus } from './vsls/vsls';
 
 const _onDidFetchAvatar = new EventEmitter<{ email: string }>();
@@ -57,13 +56,13 @@ const presenceCache = new Map();
 const gitHubNoReplyAddressRegex = /^(?:(?<userId>\d+)\+)?(?<userName>[a-zA-Z\d-]{1,39})@users\.noreply\.github\.com$/;
 
 const retryDecay = [
-	MillisecondsPerDay * 7, // First item is cache expiration (since retries will be 0)
-	MillisecondsPerMinute,
-	MillisecondsPerMinute * 5,
-	MillisecondsPerMinute * 10,
-	MillisecondsPerHour,
-	MillisecondsPerDay,
-	MillisecondsPerDay * 7,
+	Dates.MillisecondsPerDay * 7, // First item is cache expiration (since retries will be 0)
+	Dates.MillisecondsPerMinute,
+	Dates.MillisecondsPerMinute * 5,
+	Dates.MillisecondsPerMinute * 10,
+	Dates.MillisecondsPerHour,
+	Dates.MillisecondsPerDay,
+	Dates.MillisecondsPerDay * 7,
 ];
 
 export function getAvatarUri(

src/commands/logging.ts

@@ -1,5 +1,5 @@
 'use strict';
-import { configuration, TraceLevel } from '../configuration';
+import { configuration, OutputLevel } from '../configuration';
 import { command, Command, Commands } from './common';
 
 @command()
@@ -9,7 +9,7 @@ export class EnableDebugLoggingCommand extends Command {
 	}
 
 	async execute() {
-		await configuration.updateEffective('outputLevel', TraceLevel.Debug);
+		await configuration.updateEffective('outputLevel', OutputLevel.Debug);
 	}
 }
 
@@ -20,6 +20,6 @@ export class DisableDebugLoggingCommand extends Command {
 	}
 
 	async execute() {
-		await configuration.updateEffective('outputLevel', TraceLevel.Errors);
+		await configuration.updateEffective('outputLevel', OutputLevel.Errors);
 	}
 }

src/config.ts

@@ -1,6 +1,6 @@
 'use strict';
 
-export const enum TraceLevel {
+export const enum OutputLevel {
 	Silent = 'silent',
 	Errors = 'errors',
 	Verbose = 'verbose',
@@ -110,7 +110,7 @@ export interface Config {
 		};
 	};
 	modes: Record<string, ModeConfig> | null;
-	outputLevel: TraceLevel;
+	outputLevel: OutputLevel;
 	partners: Record<
 		string,
 		{

src/container.ts

@@ -30,7 +30,7 @@ import { LineHoverController } from './hovers/lineHoverController';
 import { Keyboard } from './keyboard';
 import { Logger } from './logger';
 import { StatusBarController } from './statusbar/statusBarController';
-import { memoize } from './system/decorators/memoize';
+import { log, memoize } from './system';
 import { GitTerminalLinkProvider } from './terminal/linkProvider';
 import { GitDocumentTracker } from './trackers/gitDocumentTracker';
 import { GitLineTracker } from './trackers/gitLineTracker';
@@ -142,16 +142,18 @@ export class Container {
 	}
 
 	private _ready: boolean = false;
+
 	ready() {
 		if (this._ready) throw new Error('Container is already ready');
 
 		this._ready = true;
+		this.registerGitProviders();
 		queueMicrotask(() => {
-			this.registerGitProviders();
 			this._onReady.fire();
 		});
 	}
 
+	@log()
 	private registerGitProviders() {
 		if (env.uiKind !== UIKind.Web) {
 			this._context.subscriptions.push(this._git.register(GitProviderId.Git, new LocalGitProvider(this)));
@@ -164,7 +166,7 @@ export class Container {
 		this._config = undefined;
 
 		if (configuration.changed(e.change, 'outputLevel')) {
-			Logger.level = configuration.get('outputLevel');
+			Logger.logLevel = configuration.get('outputLevel');
 		}
 
 		if (configuration.changed(e.change, 'defaultGravatarsStyle')) {

src/extension.ts

@@ -1,28 +1,49 @@
 'use strict';
-import { commands, ExtensionContext, extensions, window, workspace } from 'vscode';
+import { version as codeVersion, commands, env, ExtensionContext, extensions, window, workspace } from 'vscode';
 import type { CreatePullRequestActionContext, GitLensApi, OpenPullRequestActionContext } from '../src/api/gitlens';
 import { Api } from './api/api';
 import { Commands, executeCommand, OpenPullRequestOnRemoteCommandArgs, registerCommands } from './commands';
 import { CreatePullRequestOnRemoteCommandArgs } from './commands/createPullRequestOnRemote';
-import { configuration, Configuration, TraceLevel } from './configuration';
-import { ContextKeys, GlobalState, GlyphChars, setContext, SyncedState } from './constants';
+import { configuration, Configuration, OutputLevel } from './configuration';
+import { ContextKeys, GlobalState, setContext, SyncedState } from './constants';
 import { Container } from './container';
 import { GitBranch, GitCommit } from './git/git';
 import { GitUri } from './git/gitUri';
-import { Logger } from './logger';
+import { Logger, LogLevel } from './logger';
 import { Messages } from './messages';
 import { registerPartnerActionRunners } from './partners';
-import { Strings, Versions } from './system';
+import { Stopwatch, Versions } from './system';
 import { ViewNode } from './views/nodes';
 
 export function activate(context: ExtensionContext): Promise<GitLensApi | undefined> | undefined {
-	const start = process.hrtime();
+	const insiders = context.extension.id === 'eamodio.gitlens-insiders';
+	const gitlensVersion = context.extension.packageJSON.version;
+
+	Logger.configure(context, configuration.get('outputLevel'), o => {
+		if (GitUri.is(o)) {
+			return `GitUri(${o.toString(true)}${o.repoPath ? ` repoPath=${o.repoPath}` : ''}${
+				o.sha ? ` sha=${o.sha}` : ''
+			})`;
+		}
+
+		if (GitCommit.is(o)) {
+			return `GitCommit(${o.sha ? ` sha=${o.sha}` : ''}${o.repoPath ? ` repoPath=${o.repoPath}` : ''})`;
+		}
+
+		if (ViewNode.is(o)) return o.toString();
+
+		return undefined;
+	});
+
+	const sw = new Stopwatch(`GitLens${insiders ? ' (Insiders)' : ''} v${gitlensVersion}`, {
+		log: { message: ' activating...' },
+	});
 
-	if (context.extension.id === 'eamodio.gitlens-insiders') {
+	if (insiders) {
 		// Ensure that stable isn't also installed
 		const stable = extensions.getExtension('eamodio.gitlens');
 		if (stable != null) {
-			Logger.log('GitLens (Insiders) was NOT activated because GitLens is also enabled');
+			sw.stop({ message: ' was NOT activated because GitLens is also enabled' });
 
 			// If we don't use a setTimeout here this notification will get lost for some reason
 			setTimeout(() => void Messages.showInsidersErrorMessage(), 0);
@@ -40,26 +61,6 @@ export function activate(context: ExtensionContext): Promise
 
 	setKeysForSync(context);
 
-	Logger.configure(context, configuration.get('outputLevel'), o => {
-		if (GitUri.is(o)) {
-			return `GitUri(${o.toString(true)}${o.repoPath ? ` repoPath=${o.repoPath}` : ''}${
-				o.sha ? ` sha=${o.sha}` : ''
-			})`;
-		}
-
-		if (GitCommit.is(o)) {
-			return `GitCommit(${o.sha ? ` sha=${o.sha}` : ''}${o.repoPath ? ` repoPath=${o.repoPath}` : ''})`;
-		}
-
-		if (ViewNode.is(o)) {
-			return o.toString();
-		}
-
-		return undefined;
-	});
-
-	const gitlensVersion = context.extension.packageJSON.version;
-
 	const syncedVersion = context.globalState.get<string>(SyncedState.Version);
 	const localVersion =
 		context.globalState.get<string>(GlobalState.Version) ??
@@ -74,12 +75,11 @@ export function activate(context: ExtensionContext): Promise
 		previousVersion = localVersion;
 	}
 
-	if (Logger.willLog('debug')) {
-		Logger.debug(
-			`GitLens (v${gitlensVersion}): syncedVersion=${syncedVersion}, localVersion=${localVersion}, previousVersion=${previousVersion}, ${
-				SyncedState.WelcomeViewVisible
-			}=${context.globalState.get<boolean>(SyncedState.WelcomeViewVisible)}`,
-		);
+	let exitMessage;
+	if (Logger.enabled(LogLevel.Debug)) {
+		exitMessage = `syncedVersion=${syncedVersion}, localVersion=${localVersion}, previousVersion=${previousVersion}, welcome=${context.globalState.get<boolean>(
+			SyncedState.WelcomeViewVisible,
+		)}`;
 	}
 
 	if (previousVersion == null) {
@@ -111,9 +111,9 @@ export function activate(context: ExtensionContext): Promise
 			void context.globalState.update(SyncedState.Version, gitlensVersion);
 		}
 
-		if (cfg.outputLevel === TraceLevel.Debug) {
+		if (cfg.outputLevel === OutputLevel.Debug) {
 			setTimeout(async () => {
-				if (cfg.outputLevel !== TraceLevel.Debug) return;
+				if (cfg.outputLevel !== OutputLevel.Debug) return;
 
 				if (await Messages.showDebugLoggingWarningMessage()) {
 					void commands.executeCommand(Commands.DisableDebugLogging);
@@ -125,11 +125,11 @@ export function activate(context: ExtensionContext): Promise
 	// Signal that the container is now ready
 	container.ready();
 
-	Logger.log(
-		`GitLens (v${gitlensVersion}${cfg.mode.active ? `, mode: ${cfg.mode.active}` : ''}) activated ${
-			GlyphChars.Dot
-		} ${Strings.getDurationMilliseconds(start)} ms`,
-	);
+	sw.stop({
+		message: ` activated; app=${env.appName}(${codeVersion})${cfg.mode.active ? `, mode: ${cfg.mode.active}` : ''}${
+			exitMessage != null ? `, ${exitMessage}` : ''
+		}`,
+	});
 
 	const api = new Api(container);
 	return Promise.resolve(api);

src/git/git.ts

@@ -2,6 +2,7 @@
 'use strict';
 import * as paths from 'path';
 import { Uri, window, workspace } from 'vscode';
+import { hrtime } from '@env/hrtime';
 import { GlyphChars } from '../constants';
 import { Container } from '../container';
 import { Logger } from '../logger';
@@ -85,7 +86,7 @@ export async function git(options: GitCommandOptio
 		}
 	}
 
-	const start = process.hrtime();
+	const start = hrtime();
 
 	const { configs, correlationKey, errors: errorHandling, encoding, ...opts } = options;
 

src/git/gitProviderService.ts

@@ -268,6 +268,7 @@ export class GitProviderService implements Disposable {
 	 * @param provider A provider for handling git operations
 	 * @returns A disposable to unregister the {@link GitProvider}
 	 */
+	@log({ args: { 1: () => false }, singleLine: true })
 	register(id: GitProviderId, provider: GitProvider): Disposable {
 		if (this._providers.has(id)) throw new Error(`Provider '${id}' has already been registered`);
 
@@ -339,6 +340,8 @@ export class GitProviderService implements Disposable {
 	}
 
 	private _initializing: boolean = true;
+
+	@log({ singleLine: true })
 	registrationComplete() {
 		this._initializing = false;
 
@@ -361,6 +364,7 @@ export class GitProviderService implements Disposable {
 
 	private _discoveredWorkspaceFolders = new Map<WorkspaceFolder, Promise<Repository[]>>();
 
+	@log<GitProviderService['discoverRepositories']>({ args: { 0: folders => `${folders.length}` } })
 	async discoverRepositories(folders: readonly WorkspaceFolder[], options?: { force?: boolean }): Promise<void> {
 		const promises = [];
 

src/git/locator.ts

@@ -1,5 +1,8 @@
 'use strict';
 import * as paths from 'path';
+import { GlyphChars } from '../constants';
+import { LogLevel } from '../logger';
+import { Stopwatch } from '../system';
 import { findExecutable, run } from './shell';
 
 export class UnableToFindGitError extends Error {
@@ -28,10 +31,14 @@ function parseVersion(raw: string): string {
 }
 
 async function findSpecificGit(path: string): Promise<GitLocation> {
+	const sw = new Stopwatch(`findSpecificGit(${path})`, { logLevel: LogLevel.Debug });
+
 	let version;
 	try {
 		version = await run<string>(path, ['--version'], 'utf8');
 	} catch (ex) {
+		sw.stop({ message: ` ${GlyphChars.Dot} Unable to find git` });
+
 		if (/bad config/i.test(ex.message)) throw new InvalidGitConfigError(ex);
 		throw ex;
 	}
@@ -44,6 +51,8 @@ async function findSpecificGit(path: string): Promise {
 		try {
 			version = await run<string>(foundPath, ['--version'], 'utf8');
 		} catch (ex) {
+			sw.stop({ message: ` ${GlyphChars.Dot} Unable to find git` });
+
 			if (/bad config/i.test(ex.message)) throw new InvalidGitConfigError(ex);
 			throw ex;
 		}
@@ -51,6 +60,8 @@ async function findSpecificGit(path: string): Promise {
 		path = foundPath;
 	}
 
+	sw.stop({ message: ` ${GlyphChars.Dot} Found git @ ${path}` });
+
 	return {
 		path: path,
 		version: parseVersion(version.trim()),

src/git/models/repository.ts

@@ -18,7 +18,7 @@ import { executeActionCommand } from '../../commands';
 import { configuration } from '../../configuration';
 import { BuiltInGitCommands, BuiltInGitConfiguration, Starred, WorkspaceState } from '../../constants';
 import { Container } from '../../container';
-import { Logger } from '../../logger';
+import { Logger, LogLevel } from '../../logger';
 import { Messages } from '../../messages';
 import { Arrays, Dates, debug, Functions, gate, Iterables, log, logName } from '../../system';
 import { runGitCommandInTerminal } from '../../terminal';
@@ -273,7 +273,7 @@ export class Repository implements Disposable {
 		if (!this.supportsChangeEvents) {
 			void this.tryWatchingForChangesViaBuiltInApi();
 
-			if (Logger.willLog('debug')) {
+			if (Logger.enabled(LogLevel.Debug)) {
 				Logger.debug(
 					`Repository(${
 						this.id
@@ -1105,7 +1105,7 @@ export class Repository implements Disposable {
 					);
 					this._supportsChangeEvents = true;
 
-					if (Logger.willLog('debug')) {
+					if (Logger.enabled(LogLevel.Debug)) {
 						Logger.debug(`Repository(${this.id}) is now using fallback file watching`);
 					}
 				} catch {}

src/git/providers/localGitProvider.ts

@@ -15,6 +15,7 @@ import {
 	workspace,
 	WorkspaceFolder,
 } from 'vscode';
+import { hrtime } from '@env/hrtime';
 import type { API as BuiltInGitApi, Repository as BuiltInGitRepository, GitExtension } from '../../@types/vscode.git';
 import { configuration } from '../../configuration';
 import { BuiltInGitConfiguration, DocumentSchemes, GlyphChars } from '../../constants';
@@ -225,7 +226,7 @@ export class LocalGitProvider implements GitProvider, Disposable {
 		}
 		void subscribeToScmOpenCloseRepository(this.container, scmPromise);
 
-		const start = process.hrtime();
+		const start = hrtime();
 		const location = await findGitPath(gitPath ?? configuration.getAny<string | string[]>('git.path'));
 
 		if (cc != null) {

src/hovers/hovers.ts

@@ -3,6 +3,7 @@ import { MarkdownString } from 'vscode';
 import { DiffWithCommand, ShowQuickCommitCommand } from '../commands';
 import { GlyphChars } from '../constants';
 import { Container } from '../container';
+import { hrtime } from '../env/node/hrtime';
 import {
 	CommitFormatter,
 	GitBlameCommit,
@@ -15,7 +16,7 @@ import {
 	PullRequest,
 } from '../git/git';
 import { GitUri } from '../git/gitUri';
-import { Logger } from '../logger';
+import { Logger, LogLevel } from '../logger';
 import { Iterables, Promises, Strings } from '../system';
 
 export namespace Hovers {
@@ -263,7 +264,7 @@ export namespace Hovers {
 		const cc = Logger.getNewCorrelationContext('Hovers.getAutoLinkedIssues');
 		Logger.debug(cc, `${GlyphChars.Dash} message=<message>`);
 
-		const start = process.hrtime();
+		const start = hrtime();
 
 		if (
 			!Container.instance.config.hovers.autolinks.enabled ||
@@ -290,7 +291,7 @@ export namespace Hovers {
 				timeout: timeout,
 			});
 
-			if (autolinks != null && Logger.willLog('debug')) {
+			if (autolinks != null && Logger.enabled(LogLevel.Debug)) {
 				// If there are any issues/PRs that timed out, log it
 				const count = Iterables.count(autolinks.values(), pr => pr instanceof Promises.CancellationError);
 				if (count !== 0) {
@@ -342,7 +343,7 @@ export namespace Hovers {
 		const cc = Logger.getNewCorrelationContext('Hovers.getPullRequestForCommit');
 		Logger.debug(cc, `${GlyphChars.Dash} ref=${ref}`);
 
-		const start = process.hrtime();
+		const start = hrtime();
 
 		if (!options?.pullRequests) {
 			Logger.debug(cc, `completed ${GlyphChars.Dot} ${Strings.getDurationMilliseconds(start)} ms`);

src/logger.ts

@@ -1,16 +1,30 @@
 'use strict';
 import { ExtensionContext, ExtensionMode, OutputChannel, Uri, window } from 'vscode';
-import { TraceLevel } from './configuration';
+import { OutputLevel } from './configuration';
 import { getCorrelationContext, getNextCorrelationId } from './system';
 
 const emptyStr = '';
-const extensionOutputChannelName = 'GitLens';
-const ConsolePrefix = '[GitLens]';
-
-const extensionGitOutputChannelName = 'GitLens (Git)';
-const GitConsolePrefix = '[GitLens (Git)]';
+const outputChannelName = 'GitLens';
+const consolePrefix = '[GitLens]';
+
+const gitOutputChannelName = 'GitLens (Git)';
+const gitConsolePrefix = '[GitLens (Git)]';
+
+export const enum LogLevel {
+	Off = 'off',
+	Error = 'error',
+	Warn = 'warn',
+	Info = 'info',
+	Debug = 'debug',
+}
 
-export { TraceLevel } from './configuration';
+const enum OrderedLevel {
+	Off = 0,
+	Error = 1,
+	Warn = 2,
+	Info = 3,
+	Debug = 4,
+}
 
 export interface LogCorrelationContext {
 	readonly correlationId?: number;
@@ -19,14 +33,17 @@ export interface LogCorrelationContext {
 }
 
 export class Logger {
-	static output: OutputChannel | undefined;
-	static customLoggableFn: ((o: object) => string | undefined) | undefined;
+	private static output: OutputChannel | undefined;
+	private static customLoggableFn: ((o: object) => string | undefined) | undefined;
 
-	static configure(context: ExtensionContext, level: TraceLevel, loggableFn?: (o: any) => string | undefined) {
+	static configure(context: ExtensionContext, outputLevel: OutputLevel, loggableFn?: (o: any) => string | undefined) {
+		this._isDebugging = context.extensionMode === ExtensionMode.Development;
+		this.logLevel = outputLevel;
 		this.customLoggableFn = loggableFn;
+	}
 
-		this._isDebugging = context.extensionMode === ExtensionMode.Development;
-		this.level = level;
+	static enabled(level: LogLevel): boolean {
+		return this.level >= toOrderedLevel(level);
 	}
 
 	private static _isDebugging: boolean;
@@ -34,26 +51,27 @@ export class Logger {
 		return this._isDebugging;
 	}
 
-	private static _level: TraceLevel = TraceLevel.Silent;
-	static get level() {
-		return this._level;
+	private static level: OrderedLevel = OrderedLevel.Off;
+	private static _logLevel: LogLevel = LogLevel.Off;
+	static get logLevel(): LogLevel {
+		return this._logLevel;
 	}
-	static set level(value: TraceLevel) {
-		this._level = value;
-		if (value === TraceLevel.Silent) {
-			if (this.output != null) {
-				this.output.dispose();
-				this.output = undefined;
-			}
+	static set logLevel(value: LogLevel | OutputLevel) {
+		this._logLevel = fromOutputLevel(value);
+		this.level = toOrderedLevel(this._logLevel);
+
+		if (value === LogLevel.Off) {
+			this.output?.dispose();
+			this.output = undefined;
 		} else {
-			this.output = this.output ?? window.createOutputChannel(extensionOutputChannelName);
+			this.output = this.output ?? window.createOutputChannel(outputChannelName);
 		}
 	}
 
 	static debug(message: string, ...params: any[]): void;
 	static debug(context: LogCorrelationContext | undefined, message: string, ...params: any[]): void;
 	static debug(contextOrMessage: LogCorrelationContext | string | undefined, ...params: any[]): void {
-		if (this.level !== TraceLevel.Debug && !Logger.isDebugging) return;
+		if (this.level < OrderedLevel.Debug && !this.isDebugging) return;
 
 		let message;
 		if (typeof contextOrMessage === 'string') {
@@ -66,19 +84,22 @@ export class Logger {
 			}
 		}
 
-		if (Logger.isDebugging) {
-			console.log(this.timestamp, ConsolePrefix, message ?? emptyStr, ...params);
+		if (this.isDebugging) {
+			console.log(this.timestamp, consolePrefix, message ?? emptyStr, ...params);
 		}
 
-		if (this.output != null && this.level === TraceLevel.Debug) {
-			this.output.appendLine(`${this.timestamp} ${message ?? emptyStr}${this.toLoggableParams(true, params)}`);
-		}
+		if (this.output == null || this.level < OrderedLevel.Debug) return;
+		this.output.appendLine(`${this.timestamp} ${message ?? emptyStr}${this.toLoggableParams(true, params)}`);
 	}
 
-	static error(ex: Error, message?: string, ...params: any[]): void;
-	static error(ex: Error, context?: LogCorrelationContext, message?: string, ...params: any[]): void;
-	static error(ex: Error, contextOrMessage: LogCorrelationContext | string | undefined, ...params: any[]): void {
-		if (this.level === TraceLevel.Silent && !Logger.isDebugging) return;
+	static error(ex: Error | unknown, message?: string, ...params: any[]): void;
+	static error(ex: Error | unknown, context?: LogCorrelationContext, message?: string, ...params: any[]): void;
+	static error(
+		ex: Error | unknown,
+		contextOrMessage: LogCorrelationContext | string | undefined,
+		...params: any[]
+	): void {
+		if (this.level < OrderedLevel.Error && !this.isDebugging) return;
 
 		let message;
 		if (contextOrMessage == null || typeof contextOrMessage === 'string') {
@@ -88,7 +109,7 @@ export class Logger {
 		}
 
 		if (message == null) {
-			const stack = ex.stack;
+			const stack = ex instanceof Error ? ex.stack : undefined;
 			if (stack) {
 				const match = /.*\s*?at\s(.+?)\s/.exec(stack);
 				if (match != null) {
@@ -97,35 +118,20 @@ export class Logger {
 			}
 		}
 
-		if (Logger.isDebugging) {
-			console.error(this.timestamp, ConsolePrefix, message ?? emptyStr, ...params, ex);
-		}
-
-		if (this.output != null && this.level !== TraceLevel.Silent) {
-			this.output.appendLine(
-				`${this.timestamp} ${message ?? emptyStr}${this.toLoggableParams(false, params)}\n${ex?.toString()}`,
-			);
+		if (this.isDebugging) {
+			console.error(this.timestamp, consolePrefix, message ?? emptyStr, ...params, ex);
 		}
-	}
 
-	static getCorrelationContext() {
-		return getCorrelationContext();
-	}
-
-	static getNewCorrelationContext(prefix: string): LogCorrelationContext {
-		const correlationId = getNextCorrelationId();
-		return {
-			correlationId: correlationId,
-			prefix: `[${correlationId}] ${prefix}`,
-		};
+		if (this.output == null || this.level < OrderedLevel.Error) return;
+		this.output.appendLine(
+			`${this.timestamp} ${message ?? emptyStr}${this.toLoggableParams(false, params)}\n${String(ex)}`,
+		);
 	}
 
 	static log(message: string, ...params: any[]): void;
 	static log(context: LogCorrelationContext | undefined, message: string, ...params: any[]): void;
 	static log(contextOrMessage: LogCorrelationContext | string | undefined, ...params: any[]): void {
-		if (this.level !== TraceLevel.Verbose && this.level !== TraceLevel.Debug && !Logger.isDebugging) {
-			return;
-		}
+		if (this.level < OrderedLevel.Info && !this.isDebugging) return;
 
 		let message;
 		if (typeof contextOrMessage === 'string') {
@@ -138,21 +144,18 @@ export class Logger {
 			}
 		}
 
-		if (Logger.isDebugging) {
-			console.log(this.timestamp, ConsolePrefix, message ?? emptyStr, ...params);
+		if (this.isDebugging) {
+			console.log(this.timestamp, consolePrefix, message ?? emptyStr, ...params);
 		}
 
-		if (this.output != null && (this.level === TraceLevel.Verbose || this.level === TraceLevel.Debug)) {
-			this.output.appendLine(`${this.timestamp} ${message ?? emptyStr}${this.toLoggableParams(false, params)}`);
-		}
+		if (this.output == null || this.level < OrderedLevel.Info) return;
+		this.output.appendLine(`${this.timestamp} ${message ?? emptyStr}${this.toLoggableParams(false, params)}`);
 	}
 
 	static logWithDebugParams(message: string, ...params: any[]): void;
 	static logWithDebugParams(context: LogCorrelationContext | undefined, message: string, ...params: any[]): void;
 	static logWithDebugParams(contextOrMessage: LogCorrelationContext | string | undefined, ...params: any[]): void {
-		if (this.level !== TraceLevel.Verbose && this.level !== TraceLevel.Debug && !Logger.isDebugging) {
-			return;
-		}
+		if (this.level < OrderedLevel.Info && !this.isDebugging) return;
 
 		let message;
 		if (typeof contextOrMessage === 'string') {
@@ -165,19 +168,18 @@ export class Logger {
 			}
 		}
 
-		if (Logger.isDebugging) {
-			console.log(this.timestamp, ConsolePrefix, message ?? emptyStr, ...params);
+		if (this.isDebugging) {
+			console.log(this.timestamp, consolePrefix, message ?? emptyStr, ...params);
 		}
 
-		if (this.output != null && (this.level === TraceLevel.Verbose || this.level === TraceLevel.Debug)) {
-			this.output.appendLine(`${this.timestamp} ${message ?? emptyStr}${this.toLoggableParams(true, params)}`);
-		}
+		if (this.output == null || this.level < OrderedLevel.Info) return;
+		this.output.appendLine(`${this.timestamp} ${message ?? emptyStr}${this.toLoggableParams(true, params)}`);
 	}
 
 	static warn(message: string, ...params: any[]): void;
 	static warn(context: LogCorrelationContext | undefined, message: string, ...params: any[]): void;
 	static warn(contextOrMessage: LogCorrelationContext | string | undefined, ...params: any[]): void {
-		if (this.level === TraceLevel.Silent && !Logger.isDebugging) return;
+		if (this.level < OrderedLevel.Warn && !this.isDebugging) return;
 
 		let message;
 		if (typeof contextOrMessage === 'string') {
@@ -190,33 +192,28 @@ export class Logger {
 			}
 		}
 
-		if (Logger.isDebugging) {
-			console.warn(this.timestamp, ConsolePrefix, message ?? emptyStr, ...params);
+		if (this.isDebugging) {
+			console.warn(this.timestamp, consolePrefix, message ?? emptyStr, ...params);
 		}
 
-		if (this.output != null && this.level !== TraceLevel.Silent) {
-			this.output.appendLine(`${this.timestamp} ${message ?? emptyStr}${this.toLoggableParams(false, params)}`);
-		}
+		if (this.output == null || this.level < OrderedLevel.Warn) return;
+		this.output.appendLine(`${this.timestamp} ${message ?? emptyStr}${this.toLoggableParams(false, params)}`);
 	}
 
-	static willLog(type: 'debug' | 'error' | 'log' | 'warn'): boolean {
-		switch (type) {
-			case 'debug':
-				return this.level === TraceLevel.Debug || Logger.isDebugging;
-			case 'error':
-			case 'warn':
-				return this.level !== TraceLevel.Silent || Logger.isDebugging;
-			case 'log':
-				return this.level === TraceLevel.Verbose || this.level === TraceLevel.Debug || Logger.isDebugging;
-			default:
-				return false;
-		}
+	static getCorrelationContext() {
+		return getCorrelationContext();
 	}
 
-	static showOutputChannel() {
-		if (this.output == null) return;
+	static getNewCorrelationContext(prefix: string): LogCorrelationContext {
+		const correlationId = getNextCorrelationId();
+		return {
+			correlationId: correlationId,
+			prefix: `[${String(correlationId).padStart(5)}] ${prefix}`,
+		};
+	}
 
-		this.output.show();
+	static showOutputChannel() {
+		this.output?.show();
 	}
 
 	static toLoggable(p: any, sanitize?: ((key: string, value: any) => any) | undefined) {
@@ -260,7 +257,7 @@ export class Logger {
 	}
 
 	private static toLoggableParams(debugOnly: boolean, params: any[]) {
-		if (params.length === 0 || (debugOnly && this.level !== TraceLevel.Debug && !Logger.isDebugging)) {
+		if (params.length === 0 || (debugOnly && this.level < OrderedLevel.Debug && !this.isDebugging)) {
 			return emptyStr;
 		}
 
@@ -271,19 +268,51 @@ export class Logger {
 	static gitOutput: OutputChannel | undefined;
 
 	static logGitCommand(command: string, ex?: Error): void {
-		if (this.level !== TraceLevel.Debug) return;
+		if (this.level < OrderedLevel.Debug && !this.isDebugging) return;
 
-		if (Logger.isDebugging) {
+		if (this.isDebugging) {
 			if (ex != null) {
-				console.error(this.timestamp, GitConsolePrefix, command ?? emptyStr, ex);
+				console.error(this.timestamp, gitConsolePrefix, command ?? emptyStr, ex);
 			} else {
-				console.log(this.timestamp, GitConsolePrefix, command ?? emptyStr);
+				console.log(this.timestamp, gitConsolePrefix, command ?? emptyStr);
 			}
 		}
 
 		if (this.gitOutput == null) {
-			this.gitOutput = window.createOutputChannel(extensionGitOutputChannelName);
+			this.gitOutput = window.createOutputChannel(gitOutputChannelName);
 		}
 		this.gitOutput.appendLine(`${this.timestamp} ${command}${ex != null ? `\n\n${ex.toString()}` : emptyStr}`);
 	}
 }
+
+function fromOutputLevel(level: LogLevel | OutputLevel): LogLevel {
+	switch (level) {
+		case OutputLevel.Silent:
+			return LogLevel.Off;
+		case OutputLevel.Errors:
+			return LogLevel.Error;
+		case OutputLevel.Verbose:
+			return LogLevel.Info;
+		case OutputLevel.Debug:
+			return LogLevel.Debug;
+		default:
+			return level;
+	}
+}
+
+function toOrderedLevel(logLevel: LogLevel): OrderedLevel {
+	switch (logLevel) {
+		case LogLevel.Off:
+			return OrderedLevel.Off;
+		case LogLevel.Error:
+			return OrderedLevel.Error;
+		case LogLevel.Warn:
+			return OrderedLevel.Warn;
+		case LogLevel.Info:
+			return OrderedLevel.Info;
+		case LogLevel.Debug:
+			return OrderedLevel.Debug;
+		default:
+			return OrderedLevel.Off;
+	}
+}

src/system/decorators/log.ts

@@ -1,5 +1,6 @@
 'use strict';
-import { LogCorrelationContext, Logger, TraceLevel } from '../../logger';
+import { hrtime } from '@env/hrtime';
+import { LogCorrelationContext, Logger, LogLevel } from '../../logger';
 import { filterMap } from '../array';
 import { getParameters } from '../function';
 import { is as isPromise } from '../promise';
@@ -106,8 +107,8 @@ export function log any>(
 
 			if (
 				(!Logger.isDebugging &&
-					Logger.level !== TraceLevel.Debug &&
-					!(Logger.level === TraceLevel.Verbose && !options.debug)) ||
+					!Logger.enabled(LogLevel.Debug) &&
+					!(Logger.enabled(LogLevel.Info) && !options.debug)) ||
 				(typeof options.condition === 'function' && !options.condition(...args))
 			) {
 				return fn!.apply(this, args);
@@ -129,7 +130,7 @@ export function log any>(
 				correlate = true;
 			}
 
-			let prefix = `${correlate ? `[${correlationId.toString(16)}] ` : emptyStr}${
+			let prefix = `${correlate ? `[${correlationId.toString(16).padStart(5)}] ` : emptyStr}${
 				instanceName ? `${instanceName}.` : emptyStr
 			}${key}`;
 
@@ -189,7 +190,7 @@ export function log any>(
 			}
 
 			if (options.singleLine || options.timed || options.exit != null) {
-				const start = options.timed ? process.hrtime() : undefined;
+				const start = options.timed ? hrtime() : undefined;
 
 				const logError = (ex: Error) => {
 					const timing = start !== undefined ? ` \u2022 ${getDurationMilliseconds(start)} ms` : emptyStr;

src/system/stopwatch.ts

@@ -1,27 +1,132 @@
 'use strict';
+import { hrtime } from '@env/hrtime';
+import { GlyphChars } from '../constants';
+import { LogCorrelationContext, Logger, LogLevel } from '../logger';
+import { getNextCorrelationId } from '../system';
+
+type StopwatchLogOptions = { message?: string; suffix?: string };
+type StopwatchOptions = {
+	log?: boolean | StopwatchLogOptions;
+	logLevel?: StopwatchLogLevel;
+};
+type StopwatchLogLevel = Exclude<LogLevel, LogLevel.Off>;
 
 export class Stopwatch {
-	private static readonly timers = new Map<string, [number, number]>();
+	private readonly instance = `[${String(getNextCorrelationId()).padStart(5)}] `;
+	private readonly logLevel: StopwatchLogLevel;
+	private time: [number, number];
+
+	constructor(public readonly context: string | LogCorrelationContext, options?: StopwatchOptions, ...params: any[]) {
+		let cc;
+		if (typeof context !== 'string') {
+			cc = context;
+			context = '';
+			this.instance = '';
+		}
 
-	static start(id: string) {
-		if (Stopwatch.timers.has(id)) {
-			this.log(id);
+		let logOptions: StopwatchLogOptions | undefined;
+		if (typeof options?.log === 'boolean') {
+			logOptions = options.log ? {} : undefined;
+		} else {
+			logOptions = options?.log ?? {};
 		}
 
-		Stopwatch.timers.set(id, process.hrtime());
+		this.logLevel = options?.logLevel ?? LogLevel.Info;
+		this.time = hrtime();
+
+		if (logOptions != null) {
+			if (!Logger.enabled(this.logLevel)) return;
+
+			if (params.length) {
+				log(
+					this.logLevel,
+					cc,
+					`${this.instance}${context}${logOptions.message ?? ''}${logOptions.suffix ?? ''}`,
+					...params,
+				);
+			} else {
+				log(
+					this.logLevel,
+					cc,
+					`${this.instance}${context}${logOptions.message ?? ''}${logOptions.suffix ?? ''}`,
+				);
+			}
+		}
 	}
 
-	static log(id: string, message?: string) {
-		const [secs, nanosecs] = process.hrtime(Stopwatch.timers.get(id));
+	log(options?: StopwatchLogOptions): void {
+		this.logCore(this.context, options, false);
+	}
+
+	restart(options?: StopwatchLogOptions): void {
+		this.logCore(this.context, options, true);
+		this.time = hrtime();
+	}
+
+	stop(options?: StopwatchLogOptions): void {
+		this.restart(options);
+	}
+
+	private logCore(
+		context: string | LogCorrelationContext,
+		options: StopwatchLogOptions | undefined,
+		logTotalElapsed: boolean,
+	): void {
+		if (!Logger.enabled(this.logLevel)) return;
+
+		let cc;
+		if (typeof context !== 'string') {
+			cc = context;
+			context = '';
+		}
+
+		if (!logTotalElapsed) {
+			log(this.logLevel, cc, `${this.instance}${context}${options?.message ?? ''}${options?.suffix ?? ''}`);
+
+			return;
+		}
+
+		const [secs, nanosecs] = hrtime(this.time);
 		const ms = secs * 1000 + Math.floor(nanosecs / 1000000);
 
-		console.log(`${id}${message ? `(${message})` : ''} took ${ms} ms`);
+		const prefix = `${this.instance}${context}${options?.message ?? ''}`;
+		log(
+			ms > 250 ? LogLevel.Warn : this.logLevel,
+			cc,
+			`${prefix ? `${prefix} ${GlyphChars.Dot} ` : ''}${ms} ms${options?.suffix ?? ''}`,
+		);
+	}
+
+	private static readonly watches = new Map<string, Stopwatch>();
+
+	static start(key: string, options?: StopwatchOptions, ...params: any[]): void {
+		Stopwatch.watches.get(key)?.log();
+		Stopwatch.watches.set(key, new Stopwatch(key, options, ...params));
+	}
+
+	static log(key: string, options?: StopwatchLogOptions): void {
+		Stopwatch.watches.get(key)?.log(options);
 	}
 
-	static stop(id: string, message?: string) {
-		if (!Stopwatch.timers.has(id)) return;
+	static stop(key: string, options?: StopwatchLogOptions): void {
+		Stopwatch.watches.get(key)?.stop(options);
+		Stopwatch.watches.delete(key);
+	}
+}
 
-		this.log(id, message);
-		Stopwatch.timers.delete(id);
+function log(logLevel: StopwatchLogLevel, cc: LogCorrelationContext | undefined, message: string, ...params: any[]) {
+	switch (logLevel) {
+		case LogLevel.Error:
+			Logger.error('', cc, message, ...params);
+			break;
+		case LogLevel.Warn:
+			Logger.warn(cc, message, ...params);
+			break;
+		case LogLevel.Info:
+			Logger.log(cc, message, ...params);
+			break;
+		default:
+			Logger.debug(cc, message, ...params);
+			break;
 	}
 }

webpack.config.js

@@ -208,6 +208,7 @@ function getExtensionConfig(target, mode, env) {
 							fs: false,
 							os: false,
 							path: require.resolve('path-browserify'),
+							process: false,
 							stream: false,
 							url: false,
 					  }