From 0b54c9a5d6be7b20af4bcfe6425fc68deb55a232 Mon Sep 17 00:00:00 2001 From: Daniel Imms <2193314+Tyriar@users.noreply.github.com> Date: Fri, 18 Aug 2023 10:55:30 -0700 Subject: [PATCH] Add trace log level, traceCall decorator and use in webgl - New 'trace' log level in the API, you should expect very spammy logs when trace is on and filter them down. As opposed to 'debug' which should be more readable. - traceCall decorator logs the args and return value of the decorated method. Wecan use this on key functions in various parts of the code to assist debugging issues that are hard to reproduce such as #4665. - Decorated a few webgl render methods for #4665. - There's an early exit in traceCall when not on the trace log level so the runtime impact when not in trace is negligable. Part of #4665 --- addons/xterm-addon-webgl/src/GlyphRenderer.ts | 3 ++ addons/xterm-addon-webgl/src/WebglAddon.ts | 8 +++- addons/xterm-addon-webgl/src/WebglRenderer.ts | 4 +- addons/xterm-addon-webgl/src/tsconfig.json | 1 + demo/client.ts | 6 +-- src/browser/renderer/shared/TextureAtlas.ts | 2 + src/common/TestUtils.test.ts | 1 + src/common/services/LogService.ts | 37 +++++++++++++++++++ src/common/services/Services.ts | 14 ++++--- typings/xterm-headless.d.ts | 20 ++++++---- typings/xterm.d.ts | 20 ++++++---- 11 files changed, 91 insertions(+), 25 deletions(-) diff --git a/addons/xterm-addon-webgl/src/GlyphRenderer.ts b/addons/xterm-addon-webgl/src/GlyphRenderer.ts index 1c75b3b9..269d9374 100644 --- a/addons/xterm-addon-webgl/src/GlyphRenderer.ts +++ b/addons/xterm-addon-webgl/src/GlyphRenderer.ts @@ -11,6 +11,8 @@ import { IRasterizedGlyph, IRenderDimensions, ITextureAtlas } from 'browser/rend import { Disposable, toDisposable } from 'common/Lifecycle'; import { throwIfFalsy } from 'browser/renderer/shared/RendererUtils'; import { TextureAtlas } from 'browser/renderer/shared/TextureAtlas'; +import { ILogService } from 'common/services/Services'; +import { traceCall } from 'common/services/LogService'; interface IVertices { attributes: Float32Array; @@ -212,6 +214,7 @@ export class GlyphRenderer extends Disposable { return this._atlas ? this._atlas.beginFrame() : true; } + @traceCall public updateCell(x: number, y: number, code: number, bg: number, fg: number, ext: number, chars: string, lastBg: number): void { // Since this function is called for every cell (`rows*cols`), it must be very optimized. It // should not instantiate any variables unless a new glyph is drawn to the cache where the diff --git a/addons/xterm-addon-webgl/src/WebglAddon.ts b/addons/xterm-addon-webgl/src/WebglAddon.ts index 97e2ce0c..3e091f0b 100644 --- a/addons/xterm-addon-webgl/src/WebglAddon.ts +++ b/addons/xterm-addon-webgl/src/WebglAddon.ts @@ -8,9 +8,10 @@ import { ITerminal } from 'browser/Types'; import { EventEmitter, forwardEvent } from 'common/EventEmitter'; import { Disposable, toDisposable } from 'common/Lifecycle'; import { getSafariVersion, isSafari } from 'common/Platform'; -import { ICoreService, IDecorationService, IOptionsService } from 'common/services/Services'; +import { ICoreService, IDecorationService, ILogService, IOptionsService } from 'common/services/Services'; import { ITerminalAddon, Terminal } from 'xterm'; import { WebglRenderer } from './WebglRenderer'; +import { setTraceLogger } from 'common/services/LogService'; export class WebglAddon extends Disposable implements ITerminalAddon { private _terminal?: Terminal; @@ -51,8 +52,13 @@ export class WebglAddon extends Disposable implements ITerminalAddon { const charSizeService: ICharSizeService = unsafeCore._charSizeService; const coreBrowserService: ICoreBrowserService = unsafeCore._coreBrowserService; const decorationService: IDecorationService = unsafeCore._decorationService; + const logService: ILogService = unsafeCore._logService; const themeService: IThemeService = unsafeCore._themeService; + // Set trace logger just in case it hasn't been yet which could happen when the addon is + // bundled separately to the core module + setTraceLogger(logService); + this._renderer = this.register(new WebglRenderer( terminal, characterJoinerService, diff --git a/addons/xterm-addon-webgl/src/WebglRenderer.ts b/addons/xterm-addon-webgl/src/WebglRenderer.ts index c21086e2..f533e0ee 100644 --- a/addons/xterm-addon-webgl/src/WebglRenderer.ts +++ b/addons/xterm-addon-webgl/src/WebglRenderer.ts @@ -17,7 +17,7 @@ import { CellData } from 'common/buffer/CellData'; import { Attributes, Content, NULL_CELL_CHAR, NULL_CELL_CODE } from 'common/buffer/Constants'; import { EventEmitter, forwardEvent } from 'common/EventEmitter'; import { Disposable, getDisposeArrayDisposable, toDisposable } from 'common/Lifecycle'; -import { ICoreService, IDecorationService, IOptionsService } from 'common/services/Services'; +import { ICoreService, IDecorationService, ILogService, IOptionsService } from 'common/services/Services'; import { CharData, IBufferLine, ICellData } from 'common/Types'; import { IDisposable, Terminal } from 'xterm'; import { GlyphRenderer } from './GlyphRenderer'; @@ -27,6 +27,7 @@ import { LinkRenderLayer } from './renderLayer/LinkRenderLayer'; import { IRenderLayer } from './renderLayer/Types'; import { COMBINED_CHAR_BIT_MASK, RenderModel, RENDER_MODEL_BG_OFFSET, RENDER_MODEL_EXT_OFFSET, RENDER_MODEL_FG_OFFSET, RENDER_MODEL_INDICIES_PER_CELL } from './RenderModel'; import { IWebGL2RenderingContext } from './Types'; +import { traceCall } from 'common/services/LogService'; export class WebglRenderer extends Disposable implements IRenderer { private _renderLayers: IRenderLayer[]; @@ -323,6 +324,7 @@ export class WebglRenderer extends Disposable implements IRenderer { return false; } + @traceCall public renderRows(start: number, end: number): void { if (!this._isAttached) { if (this._coreBrowserService.window.document.body.contains(this._core.screenElement!) && this._charSizeService.width && this._charSizeService.height) { diff --git a/addons/xterm-addon-webgl/src/tsconfig.json b/addons/xterm-addon-webgl/src/tsconfig.json index f752dc5b..74989973 100644 --- a/addons/xterm-addon-webgl/src/tsconfig.json +++ b/addons/xterm-addon-webgl/src/tsconfig.json @@ -21,6 +21,7 @@ }, "strict": true, "downlevelIteration": true, + "experimentalDecorators": true, "types": [ "../../../node_modules/@types/mocha" ] diff --git a/demo/client.ts b/demo/client.ts index c9111fec..9e0cdeff 100644 --- a/demo/client.ts +++ b/demo/client.ts @@ -424,7 +424,7 @@ function initOptions(term: TerminalType): void { fontFamily: null, fontWeight: ['normal', 'bold', '100', '200', '300', '400', '500', '600', '700', '800', '900'], fontWeightBold: ['normal', 'bold', '100', '200', '300', '400', '500', '600', '700', '800', '900'], - logLevel: ['debug', 'info', 'warn', 'error', 'off'], + logLevel: ['trace', 'debug', 'info', 'warn', 'error', 'off'], theme: ['default', 'xtermjs', 'sapphire', 'light'], wordSeparator: null }; @@ -1227,7 +1227,7 @@ Test BG-colored Erase (BCE): for all cells to the right. def 41 42 43 44 45 46 47\x1b[47m -\x1b[m \x1b[41m \x1b[42m \x1b[43m \x1b[44m \x1b[45m \x1b[46m \x1b[47m +\x1b[m \x1b[41m \x1b[42m \x1b[43m \x1b[44m \x1b[45m \x1b[46m \x1b[47m \x1b[m\x1b[5X\x1b[41m\x1b[5C\x1b[5X\x1b[42m\x1b[5C\x1b[5X\x1b[43m\x1b[5C\x1b[5X\x1b[44m\x1b[5C\x1b[5X\x1b[45m\x1b[5C\x1b[5X\x1b[46m\x1b[5C\x1b[5X\x1b[47m\x1b[5C\x1b[5X\x1b[m `; term.write(data.split('\n').join('\r\n')); @@ -1263,7 +1263,7 @@ function initImageAddonExposed(): void { term.write('\r\n'); term.write(new Uint8Array(buffer)); }); - + const iip_demo = (url: string) => () => fetch(url) .then(resp => resp.arrayBuffer()) .then(buffer => { diff --git a/src/browser/renderer/shared/TextureAtlas.ts b/src/browser/renderer/shared/TextureAtlas.ts index eec560e0..3ee21519 100644 --- a/src/browser/renderer/shared/TextureAtlas.ts +++ b/src/browser/renderer/shared/TextureAtlas.ts @@ -16,6 +16,7 @@ import { IdleTaskQueue } from 'common/TaskQueue'; import { IBoundingBox, ICharAtlasConfig, IRasterizedGlyph, IRequestRedrawEvent, ITextureAtlas } from 'browser/renderer/shared/Types'; import { EventEmitter } from 'common/EventEmitter'; import { IColorContrastCache } from 'browser/Types'; +import { traceCall } from 'common/services/LogService'; /** * A shared object which is used to draw nothing for a particular cell. @@ -425,6 +426,7 @@ export class TextureAtlas implements ITextureAtlas { return this._config.colors.contrastCache; } + @traceCall private _drawToCache(codeOrChars: number | string, bg: number, fg: number, ext: number, restrictToCellHeight: boolean = false): IRasterizedGlyph { const chars = typeof codeOrChars === 'number' ? String.fromCharCode(codeOrChars) : codeOrChars; diff --git a/src/common/TestUtils.test.ts b/src/common/TestUtils.test.ts index cae90ec8..3e554d10 100644 --- a/src/common/TestUtils.test.ts +++ b/src/common/TestUtils.test.ts @@ -104,6 +104,7 @@ export class MockCoreService implements ICoreService { export class MockLogService implements ILogService { public serviceBrand: any; public logLevel = LogLevelEnum.DEBUG; + public trace(message: any, ...optionalParams: any[]): void { } public debug(message: any, ...optionalParams: any[]): void { } public info(message: any, ...optionalParams: any[]): void { } public warn(message: any, ...optionalParams: any[]): void { } diff --git a/src/common/services/LogService.ts b/src/common/services/LogService.ts index b297049e..b3a7450c 100644 --- a/src/common/services/LogService.ts +++ b/src/common/services/LogService.ts @@ -21,6 +21,7 @@ interface IConsole { declare const console: IConsole; const optionsKeyToLogLevel: { [key: string]: LogLevelEnum } = { + trace: LogLevelEnum.TRACE, debug: LogLevelEnum.DEBUG, info: LogLevelEnum.INFO, warn: LogLevelEnum.WARN, @@ -42,6 +43,9 @@ export class LogService extends Disposable implements ILogService { super(); this._updateLogLevel(); this.register(this._optionsService.onSpecificOptionChange('logLevel', () => this._updateLogLevel())); + + // For trace logging, assume the latest created log service is valid + traceLogger = this; } private _updateLogLevel(): void { @@ -61,6 +65,12 @@ export class LogService extends Disposable implements ILogService { type.call(console, (this._optionsService.options.logger ? '' : LOG_PREFIX) + message, ...optionalParams); } + public trace(message: string, ...optionalParams: any[]): void { + if (this._logLevel <= LogLevelEnum.TRACE) { + this._log(this._optionsService.options.logger?.trace.bind(this._optionsService.options.logger) ?? console.log, message, optionalParams); + } + } + public debug(message: string, ...optionalParams: any[]): void { if (this._logLevel <= LogLevelEnum.DEBUG) { this._log(this._optionsService.options.logger?.debug.bind(this._optionsService.options.logger) ?? console.log, message, optionalParams); @@ -85,3 +95,30 @@ export class LogService extends Disposable implements ILogService { } } } + +let traceLogger: ILogService; +export function setTraceLogger(logger: ILogService): void { + traceLogger = logger; +} + +/** + * A decorator that can be used to automatically log trace calls to the decorated function. + */ +export function traceCall(_target: any, key: string, descriptor: any): any { + if (typeof descriptor.value !== 'function') { + throw new Error('not supported'); + } + const fnKey = 'value'; + const fn = descriptor.value; + descriptor[fnKey] = function (...args: any[]) { + // Early exit + if (traceLogger.logLevel !== LogLevelEnum.TRACE) { + return fn.apply(this, args); + } + + traceLogger.trace(`GlyphRenderer#${fn.name}(${args.map(e => JSON.stringify(e)).join(', ')})`); + const result = fn.apply(this, args); + traceLogger.trace(`GlyphRenderer#${fn.name} return`, result); + return result; + }; +} diff --git a/src/common/services/Services.ts b/src/common/services/Services.ts index f31b6be0..b4ee5a76 100644 --- a/src/common/services/Services.ts +++ b/src/common/services/Services.ts @@ -142,11 +142,12 @@ export interface IInstantiationService { } export enum LogLevelEnum { - DEBUG = 0, - INFO = 1, - WARN = 2, - ERROR = 3, - OFF = 4 + TRACE = 0, + DEBUG = 1, + INFO = 2, + WARN = 3, + ERROR = 4, + OFF = 5 } export const ILogService = createDecorator('LogService'); @@ -155,6 +156,7 @@ export interface ILogService { readonly logLevel: LogLevelEnum; + trace(message: any, ...optionalParams: any[]): void; debug(message: any, ...optionalParams: any[]): void; info(message: any, ...optionalParams: any[]): void; warn(message: any, ...optionalParams: any[]): void; @@ -201,7 +203,7 @@ export interface IOptionsService { } export type FontWeight = 'normal' | 'bold' | '100' | '200' | '300' | '400' | '500' | '600' | '700' | '800' | '900' | number; -export type LogLevel = 'debug' | 'info' | 'warn' | 'error' | 'off'; +export type LogLevel = 'trace' | 'debug' | 'info' | 'warn' | 'error' | 'off'; export interface ITerminalOptions { allowProposedApi?: boolean; diff --git a/typings/xterm-headless.d.ts b/typings/xterm-headless.d.ts index 835cc553..688e2eda 100644 --- a/typings/xterm-headless.d.ts +++ b/typings/xterm-headless.d.ts @@ -11,7 +11,7 @@ declare module 'xterm-headless' { /** * A string representing log level. */ - export type LogLevel = 'debug' | 'info' | 'warn' | 'error' | 'off'; + export type LogLevel = 'trace' | 'debug' | 'info' | 'warn' | 'error' | 'off'; /** * An object containing options for the terminal. @@ -100,11 +100,12 @@ declare module 'xterm-headless' { * What log level to use, this will log for all levels below and including * what is set: * - * 1. debug - * 2. info (default) - * 3. warn - * 4. error - * 5. off + * 1. trace + * 2. debug + * 3. info (default) + * 4. warn + * 5. error + * 6. off */ logLevel?: LogLevel; @@ -314,9 +315,14 @@ declare module 'xterm-headless' { * A replacement logger for `console`. */ export interface ILogger { + /** + * Log a trace message, this will only be called if + * {@link ITerminalOptions.logLevel} is set to trace. + */ + trace(message: string, ...args: any[]): void; /** * Log a debug message, this will only be called if - * {@link ITerminalOptions.logLevel} is set to debug. + * {@link ITerminalOptions.logLevel} is set to debug or below. */ debug(message: string, ...args: any[]): void; /** diff --git a/typings/xterm.d.ts b/typings/xterm.d.ts index dccc18f6..44402b84 100644 --- a/typings/xterm.d.ts +++ b/typings/xterm.d.ts @@ -18,7 +18,7 @@ declare module 'xterm' { /** * A string representing log level. */ - export type LogLevel = 'debug' | 'info' | 'warn' | 'error' | 'off'; + export type LogLevel = 'trace' | 'debug' | 'info' | 'warn' | 'error' | 'off'; /** * An object containing options for the terminal. @@ -158,11 +158,12 @@ declare module 'xterm' { * What log level to use, this will log for all levels below and including * what is set: * - * 1. debug - * 2. info (default) - * 3. warn - * 4. error - * 5. off + * 1. trace + * 2. debug + * 3. info (default) + * 4. warn + * 5. error + * 6. off */ logLevel?: LogLevel; @@ -391,9 +392,14 @@ declare module 'xterm' { * A replacement logger for `console`. */ export interface ILogger { + /** + * Log a trace message, this will only be called if + * {@link ITerminalOptions.logLevel} is set to trace. + */ + trace(message: string, ...args: any[]): void; /** * Log a debug message, this will only be called if - * {@link ITerminalOptions.logLevel} is set to debug. + * {@link ITerminalOptions.logLevel} is set to debug or below. */ debug(message: string, ...args: any[]): void; /**