From 4554c48d9d90d1283c55b1ffc170b6ed1d7fbce2 Mon Sep 17 00:00:00 2001 From: Eric Amodio Date: Mon, 6 Dec 2021 03:08:13 -0500 Subject: [PATCH] Adds better Stopwatch & overhauls logging levels Avoids process.hrtime for web builds --- src/annotations/gutterBlameAnnotationProvider.ts | 10 +- src/annotations/gutterChangesAnnotationProvider.ts | 10 +- .../gutterHeatmapBlameAnnotationProvider.ts | 10 +- src/avatars.ts | 17 +- src/commands/logging.ts | 6 +- src/config.ts | 4 +- src/container.ts | 8 +- src/extension.ts | 82 ++++---- src/git/git.ts | 3 +- src/git/gitProviderService.ts | 4 + src/git/locator.ts | 11 + src/git/models/repository.ts | 6 +- src/git/providers/localGitProvider.ts | 3 +- src/hovers/hovers.ts | 9 +- src/logger.ts | 221 ++++++++++++--------- src/system/decorators/log.ts | 11 +- src/system/stopwatch.ts | 129 ++++++++++-- webpack.config.js | 1 + 18 files changed, 347 insertions(+), 198 deletions(-) diff --git a/src/annotations/gutterBlameAnnotationProvider.ts b/src/annotations/gutterBlameAnnotationProvider.ts index 65b4f58..b54b939 100644 --- a/src/annotations/gutterBlameAnnotationProvider.ts +++ b/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); diff --git a/src/annotations/gutterChangesAnnotationProvider.ts b/src/annotations/gutterChangesAnnotationProvider.ts index 048ba90..8d74b3c 100644 --- a/src/annotations/gutterChangesAnnotationProvider.ts +++ b/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(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(); @@ -57,13 +56,13 @@ const presenceCache = new Map(); const gitHubNoReplyAddressRegex = /^(?:(?\d+)\+)?(?[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( diff --git a/src/commands/logging.ts b/src/commands/logging.ts index a57e395..252d149 100644 --- a/src/commands/logging.ts +++ b/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); } } diff --git a/src/config.ts b/src/config.ts index 73267c3..4667644 100644 --- a/src/config.ts +++ b/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 | null; - outputLevel: TraceLevel; + outputLevel: OutputLevel; partners: Record< string, { diff --git a/src/container.ts b/src/container.ts index af5191f..a85a3bf 100644 --- a/src/container.ts +++ b/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')) { diff --git a/src/extension.ts b/src/extension.ts index b097c31..d09db39 100644 --- a/src/extension.ts +++ b/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 | 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 { - 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(SyncedState.Version); const localVersion = context.globalState.get(GlobalState.Version) ?? @@ -74,12 +75,11 @@ export function activate(context: ExtensionContext): Promise(SyncedState.WelcomeViewVisible)}`, - ); + let exitMessage; + if (Logger.enabled(LogLevel.Debug)) { + exitMessage = `syncedVersion=${syncedVersion}, localVersion=${localVersion}, previousVersion=${previousVersion}, welcome=${context.globalState.get( + SyncedState.WelcomeViewVisible, + )}`; } if (previousVersion == null) { @@ -111,9 +111,9 @@ export function activate(context: ExtensionContext): Promise { - 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(options: GitCommandOptio } } - const start = process.hrtime(); + const start = hrtime(); const { configs, correlationKey, errors: errorHandling, encoding, ...opts } = options; diff --git a/src/git/gitProviderService.ts b/src/git/gitProviderService.ts index c4c6cb7..54d2d04 100644 --- a/src/git/gitProviderService.ts +++ b/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>(); + @log({ args: { 0: folders => `${folders.length}` } }) async discoverRepositories(folders: readonly WorkspaceFolder[], options?: { force?: boolean }): Promise { const promises = []; diff --git a/src/git/locator.ts b/src/git/locator.ts index 4e6749e..4b17759 100644 --- a/src/git/locator.ts +++ b/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 { + const sw = new Stopwatch(`findSpecificGit(${path})`, { logLevel: LogLevel.Debug }); + let version; try { version = await run(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(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()), diff --git a/src/git/models/repository.ts b/src/git/models/repository.ts index 1fd4bcf..e9588be 100644 --- a/src/git/models/repository.ts +++ b/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 {} diff --git a/src/git/providers/localGitProvider.ts b/src/git/providers/localGitProvider.ts index d1faf5f..5e2a2a1 100644 --- a/src/git/providers/localGitProvider.ts +++ b/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('git.path')); if (cc != null) { diff --git a/src/hovers/hovers.ts b/src/hovers/hovers.ts index 69bf90d..ca608bc 100644 --- a/src/hovers/hovers.ts +++ b/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=`); - 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`); diff --git a/src/logger.ts b/src/logger.ts index 8768180..d8f19fd 100644 --- a/src/logger.ts +++ b/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; + } +} diff --git a/src/system/decorators/log.ts b/src/system/decorators/log.ts index 81179ba..791edc1 100644 --- a/src/system/decorators/log.ts +++ b/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; diff --git a/src/system/stopwatch.ts b/src/system/stopwatch.ts index 6772ecd..c4470dc 100644 --- a/src/system/stopwatch.ts +++ b/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; export class Stopwatch { - private static readonly timers = new Map(); + 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(); + + 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; } } diff --git a/webpack.config.js b/webpack.config.js index 88b0222..7f08bc6 100644 --- a/webpack.config.js +++ b/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, }