Logs/warns on slow calls

src/git/git.ts

@@ -160,19 +160,24 @@ export async function git(options: GitCommandOptio
 	} finally {
 		pendingCommands.delete(command);
 
-		const duration = `${Strings.getDurationMilliseconds(start)} ms ${waiting ? '(waited) ' : emptyStr}`;
-		if (exception !== undefined) {
-			Logger.warn(
+		const duration = Strings.getDurationMilliseconds(start);
+		const elapsed = `${duration} ms ${waiting ? '(waited) ' : emptyStr}`;
+		if (exception != null) {
+			Logger.error(
+				'',
 				`[${runOpts.cwd}] Git ${(exception.message || exception.toString() || emptyStr)
 					.trim()
 					.replace(/fatal: /g, '')
-					.replace(/\r?\n|\r/g, ` ${GlyphChars.Dot} `)} ${GlyphChars.Dot} ${duration}`,
+					.replace(/\r?\n|\r/g, ` ${GlyphChars.Dot} `)} ${GlyphChars.Dot} ${elapsed}`,
 			);
+		} else if (duration > Logger.slowCallWarningThreshold) {
+			Logger.warn(`${gitCommand} ${GlyphChars.Dot} ${elapsed} (slow)`);
 		} else {
-			Logger.log(`${gitCommand} ${GlyphChars.Dot} ${duration}`);
+			Logger.log(`${gitCommand} ${GlyphChars.Dot} ${elapsed}`);
 		}
 		Logger.logGitCommand(
-			`${gitCommand} ${GlyphChars.Dot} ${exception !== undefined ? 'FAILED ' : emptyStr}${duration}`,
+			`${gitCommand} ${GlyphChars.Dot} ${exception !== undefined ? 'FAILED ' : emptyStr}${elapsed}`,
+			duration,
 			exception,
 		);
 	}

src/logger.ts

@@ -33,6 +33,8 @@ export interface LogCorrelationContext {
 }
 
 export class Logger {
+	static readonly slowCallWarningThreshold = 500;
+
 	private static output: OutputChannel | undefined;
 	private static customLoggableFn: ((o: object) => string | undefined) | undefined;
 
@@ -152,30 +154,6 @@ export class Logger {
 		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 < OrderedLevel.Info && !this.isDebugging) return;
-
-		let message;
-		if (typeof contextOrMessage === 'string') {
-			message = contextOrMessage;
-		} else {
-			message = params.shift();
-
-			if (contextOrMessage != null) {
-				message = `${contextOrMessage.prefix} ${message ?? emptyStr}`;
-			}
-		}
-
-		if (this.isDebugging) {
-			console.log(this.timestamp, consolePrefix, message ?? emptyStr, ...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 {
@@ -267,12 +245,14 @@ export class Logger {
 
 	static gitOutput: OutputChannel | undefined;
 
-	static logGitCommand(command: string, ex?: Error): void {
+	static logGitCommand(command: string, duration: number, ex?: Error): void {
 		if (this.level < OrderedLevel.Debug && !this.isDebugging) return;
 
 		if (this.isDebugging) {
 			if (ex != null) {
 				console.error(this.timestamp, gitConsolePrefix, command ?? emptyStr, ex);
+			} else if (duration > Logger.slowCallWarningThreshold) {
+				console.warn(this.timestamp, gitConsolePrefix, command ?? emptyStr);
 			} else {
 				console.log(this.timestamp, gitConsolePrefix, command ?? emptyStr);
 			}

src/system/decorators/log.ts

@@ -105,6 +105,7 @@ export function log any>(
 	const logFn = (options.debug ? Logger.debug.bind(Logger) : Logger.log.bind(Logger)) as
 		| typeof Logger.debug
 		| typeof Logger.log;
+	const warnFn = Logger.warn.bind(Logger);
 
 	return (target: any, key: string, descriptor: PropertyDescriptor & Record<string, any>) => {
 		let fn: Function | undefined;
@@ -200,11 +201,12 @@ export function log any>(
 				}).join(', ');
 
 				if (!options.singleLine) {
-					if (!options.debug) {
-						Logger.logWithDebugParams(`${prefix}${enter}`, loggableParams);
-					} else {
-						logFn(`${prefix}${enter}`, loggableParams);
-					}
+					logFn(
+						`${prefix}${enter}`,
+						!options.debug && !Logger.enabled(LogLevel.Debug) && !Logger.isDebugging
+							? emptyStr
+							: loggableParams,
+					);
 				}
 			}
 
@@ -246,7 +248,22 @@ export function log any>(
 				}
 
 				const logResult = (r: any) => {
-					const timing = start !== undefined ? ` \u2022 ${getDurationMilliseconds(start)} ms` : emptyStr;
+					let exitLogFn;
+					let timing;
+					if (start != null) {
+						const duration = getDurationMilliseconds(start);
+						if (duration > Logger.slowCallWarningThreshold) {
+							exitLogFn = warnFn;
+							timing = ` \u2022 ${duration} ms (slow)`;
+						} else {
+							exitLogFn = logFn;
+							timing = ` \u2022 ${duration} ms`;
+						}
+					} else {
+						timing = emptyStr;
+						exitLogFn = logFn;
+					}
+
 					let exit;
 					if (options.exit != null) {
 						try {
@@ -259,23 +276,16 @@ export function log any>(
 					}
 
 					if (options.singleLine) {
-						if (!options.debug) {
-							Logger.logWithDebugParams(
-								`${prefix}${enter} ${exit}${
-									correlationContext?.exitDetails ? correlationContext.exitDetails : emptyStr
-								}${timing}`,
-								loggableParams,
-							);
-						} else {
-							logFn(
-								`${prefix}${enter} ${exit}${
-									correlationContext?.exitDetails ? correlationContext.exitDetails : emptyStr
-								}${timing}`,
-								loggableParams,
-							);
-						}
+						exitLogFn(
+							`${prefix}${enter} ${exit}${
+								correlationContext?.exitDetails ? correlationContext.exitDetails : emptyStr
+							}${timing}`,
+							!options.debug && !Logger.enabled(LogLevel.Debug) && !Logger.isDebugging
+								? emptyStr
+								: loggableParams,
+						);
 					} else {
-						logFn(
+						exitLogFn(
 							`${prefix} ${exit}${
 								correlationContext?.exitDetails ? correlationContext.exitDetails : emptyStr
 							}${timing}`,