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

@@ -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

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,

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) {

addons/xterm-addon-webgl/src/tsconfig.json

@@ -21,6 +21,7 @@
     },
     "strict": true,
     "downlevelIteration": true,
+    "experimentalDecorators": true,
     "types": [
       "../../../node_modules/@types/mocha"
     ]

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 => {

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;
 

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 { }

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;
+  };
+}

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<ILogService>('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;

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;
     /**

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;
     /**