NestJS Logger Benchmarks

benchmark.ts

// to run this file, copy this file inside an NestJS API
// then install: npm i --save benchmark
// then copy `better-logger.service.ts` and `better-console-logger.service.ts`.
// and then just run with: npx ts-node src/benchmark.ts  

const Benchmark = require('benchmark');

import { Logger } from '@nestjs/common';
import { BetterLogger } from './better-logger.service';

const suite = new Benchmark.Suite();

const logger = new Logger();
const betterLogger = new BetterLogger();

suite.add('Logger', function () {
  logger.log('Hello World');
});

suite.add('BetterLogger', function () {
  betterLogger.log('Hello World');
});

suite.add('Console', function () {
  console.log('Hello World');
});

const results = [];

suite
  // add listeners
  .on('cycle', function (event) {
    results.push(String(event.target));
  })
  .on('complete', function () {
    results.forEach(console.log);

    console.log('Fastest is ' + this.filter('fastest').map('name'));
  })
  .run({
    async: true,
  });

better-console-logger.service.ts

import { Injectable, Optional } from '@nestjs/common/decorators/core';
import { clc, yellow } from '@nestjs/common/utils/cli-colors.util';
import { isPlainObject, isString } from '@nestjs/common/utils/shared.utils';
import { LoggerService, LogLevel } from '@nestjs/common/services/logger.service';
import { isLogLevelEnabled } from '@nestjs/common/services/utils';

export interface ConsoleLoggerOptions {
  /**
   * Enabled log levels.
   */
  logLevels?: LogLevel[];
  /**
   * If enabled, will print timestamp (time difference) between current and previous log message.
   */
  timestamp?: boolean;
}

const DEFAULT_LOG_LEVELS: LogLevel[] = [
  'log',
  'error',
  'warn',
  'debug',
  'verbose',
];

const dateTimeFormatter  = Intl.DateTimeFormat(undefined, {
  year: 'numeric',
  hour: 'numeric',
  minute: 'numeric',
  second: 'numeric',
  day: '2-digit',
  month: '2-digit',
});

@Injectable()
export class BetterConsoleLogger implements LoggerService {
  private static lastTimestampAt?: number;
  private originalContext?: string;

  constructor();
  constructor(context: string);
  constructor(context: string, options: ConsoleLoggerOptions);
  constructor(
    @Optional()
    protected context?: string,
    @Optional()
    protected options: ConsoleLoggerOptions = {},
  ) {
    if (!options.logLevels) {
      options.logLevels = DEFAULT_LOG_LEVELS;
    }
    if (context) {
      this.originalContext = context;
    }
  }

  /**
   * Write a 'log' level log, if the configured level allows for it.
   * Prints to `stdout` with newline.
   */
  log(message: any, context?: string): void;
  log(message: any, ...optionalParams: [...any, string?]): void;
  log(message: any, ...optionalParams: any[]) {
    if (!this.isLevelEnabled('log')) {
      return;
    }
    const { messages, context } = this.getContextAndMessagesToPrint([
      message,
      ...optionalParams,
    ]);
    this.printMessages(messages, context, 'log');
  }

  /**
   * Write an 'error' level log, if the configured level allows for it.
   * Prints to `stderr` with newline.
   */
  error(message: any, stack?: string, context?: string): void;
  error(message: any, ...optionalParams: [...any, string?, string?]): void;
  error(message: any, ...optionalParams: any[]) {
    if (!this.isLevelEnabled('error')) {
      return;
    }
    const { messages, context, stack } =
      this.getContextAndStackAndMessagesToPrint([message, ...optionalParams]);

    this.printMessages(messages, context, 'error', 'stderr');
    this.printStackTrace(stack);
  }

  /**
   * Write a 'warn' level log, if the configured level allows for it.
   * Prints to `stdout` with newline.
   */
  warn(message: any, context?: string): void;
  warn(message: any, ...optionalParams: [...any, string?]): void;
  warn(message: any, ...optionalParams: any[]) {
    if (!this.isLevelEnabled('warn')) {
      return;
    }
    const { messages, context } = this.getContextAndMessagesToPrint([
      message,
      ...optionalParams,
    ]);
    this.printMessages(messages, context, 'warn');
  }

  /**
   * Write a 'debug' level log, if the configured level allows for it.
   * Prints to `stdout` with newline.
   */
  debug(message: any, context?: string): void;
  debug(message: any, ...optionalParams: [...any, string?]): void;
  debug(message: any, ...optionalParams: any[]) {
    if (!this.isLevelEnabled('debug')) {
      return;
    }
    const { messages, context } = this.getContextAndMessagesToPrint([
      message,
      ...optionalParams,
    ]);
    this.printMessages(messages, context, 'debug');
  }

  /**
   * Write a 'verbose' level log, if the configured level allows for it.
   * Prints to `stdout` with newline.
   */
  verbose(message: any, context?: string): void;
  verbose(message: any, ...optionalParams: [...any, string?]): void;
  verbose(message: any, ...optionalParams: any[]) {
    if (!this.isLevelEnabled('verbose')) {
      return;
    }
    const { messages, context } = this.getContextAndMessagesToPrint([
      message,
      ...optionalParams,
    ]);
    this.printMessages(messages, context, 'verbose');
  }

  /**
   * Set log levels
   * @param levels log levels
   */
  setLogLevels(levels: LogLevel[]) {
    if (!this.options) {
      this.options = {};
    }
    this.options.logLevels = levels;
  }

  /**
   * Set logger context
   * @param context context
   */
  setContext(context: string) {
    this.context = context;
  }

  /**
   * Resets the logger context to the value that was passed in the constructor.
   */
  resetContext() {
    this.context = this.originalContext;
  }

  isLevelEnabled(level: LogLevel): boolean {
    const logLevels = this.options?.logLevels;
    return isLogLevelEnabled(level, logLevels);
  }

  protected getTimestamp(): string {
    // let timestamp = '';
    // return new Date().toISOString();
    return dateTimeFormatter.format(Date.now());
    // return 'Now';
    // const localeStringOptions = {
    //   year: 'numeric',
    //   hour: 'numeric',
    //   minute: 'numeric',
    //   second: 'numeric',
    //   day: '2-digit',
    //   month: '2-digit',
    // };
    // return new Date(Date.now()).toLocaleString(
    //   undefined,
    //   localeStringOptions as Intl.DateTimeFormatOptions,
    // );
  }

  protected printMessages(
    messages: unknown[],
    context = '',
    logLevel: LogLevel = 'log',
    writeStreamType?: 'stdout' | 'stderr',
  ) {
    messages.forEach(message => {
      const pidMessage = this.formatPid(process.pid);
      const contextMessage = this.formatContext(context);
      const timestampDiff = this.updateAndGetTimestampDiff();
      const formattedLogLevel = logLevel.toUpperCase().padStart(7, ' ');
      const formattedMessage = this.formatMessage(
        logLevel,
        message,
        pidMessage,
        formattedLogLevel,
        contextMessage,
        timestampDiff,
      );

      process[writeStreamType ?? 'stdout'].write(formattedMessage);
    });
  }

  protected formatPid(pid: number) {
    return `[Nest] ${pid}  - `;
  }

  protected formatContext(context: string): string {
    return context ? yellow(`[${context}] `) : '';
  }

  protected formatMessage(
    logLevel: LogLevel,
    message: unknown,
    pidMessage: string,
    formattedLogLevel: string,
    contextMessage: string,
    timestampDiff: string,
  ) {
    const output = this.stringifyMessage(message, logLevel);
    pidMessage = this.colorize(pidMessage, logLevel);
    formattedLogLevel = this.colorize(formattedLogLevel, logLevel);
    return `${pidMessage}${this.getTimestamp()} ${formattedLogLevel} ${contextMessage}${output}${timestampDiff}\n`;
  }

  protected stringifyMessage(message: unknown, logLevel: LogLevel) {
    return isPlainObject(message) || Array.isArray(message)
      ? `${this.colorize('Object:', logLevel)}\n${JSON.stringify(
          message,
          (key, value) =>
            typeof value === 'bigint' ? value.toString() : value,
          2,
        )}\n`
      : this.colorize(message as string, logLevel);
  }

  protected colorize(message: string, logLevel: LogLevel) {
    const color = this.getColorByLogLevel(logLevel);
    return color(message);
  }

  protected printStackTrace(stack: string) {
    if (!stack) {
      return;
    }
    process.stderr.write(`${stack}\n`);
  }

  private updateAndGetTimestampDiff(): string {
    const includeTimestamp =
    BetterConsoleLogger.lastTimestampAt && this.options?.timestamp;
    const result = includeTimestamp
      ? this.formatTimestampDiff(Date.now() - BetterConsoleLogger.lastTimestampAt)
      : '';
      BetterConsoleLogger.lastTimestampAt = Date.now();
    return result;
  }

  protected formatTimestampDiff(timestampDiff: number) {
    return yellow(` +${timestampDiff}ms`);
  }

  private getContextAndMessagesToPrint(args: unknown[]) {
    if (args?.length <= 1) {
      return { messages: args, context: this.context };
    }
    const lastElement = args[args.length - 1];
    const isContext = isString(lastElement);
    if (!isContext) {
      return { messages: args, context: this.context };
    }
    return {
      context: lastElement as string,
      messages: args.slice(0, args.length - 1),
    };
  }

  private getContextAndStackAndMessagesToPrint(args: unknown[]) {
    const { messages, context } = this.getContextAndMessagesToPrint(args);
    if (messages?.length <= 1) {
      return { messages, context };
    }
    const lastElement = messages[messages.length - 1];
    const isStack = isString(lastElement);
    if (!isStack) {
      return { messages, context };
    }
    return {
      stack: lastElement as string,
      messages: messages.slice(0, messages.length - 1),
      context,
    };
  }

  private getColorByLogLevel(level: LogLevel) {
    switch (level) {
      case 'debug':
        return clc.magentaBright;
      case 'warn':
        return clc.yellow;
      case 'error':
        return clc.red;
      case 'verbose':
        return clc.cyanBright;
      default:
        return clc.green;
    }
  }
}

better-logger.service.ts

import { Injectable, Logger, LoggerService, LogLevel, Optional } from '@nestjs/common';
import { isObject } from '@nestjs/common/utils/shared.utils';
import { isLogLevelEnabled } from '@nestjs/common/services/utils/is-log-level-enabled.util';
import { BetterConsoleLogger } from './better-console-logger.service';

const DEFAULT_LOGGER = new BetterConsoleLogger();

@Injectable()
export class BetterLogger implements LoggerService {
  protected static logBuffer = new Array<Function>();
  protected static staticInstanceRef?: LoggerService = DEFAULT_LOGGER;
  protected static logLevels?: LogLevel[];
  private static isBufferAttached: boolean;

  protected localInstanceRef?: LoggerService;

  constructor();
  constructor(context: string);
  constructor(context: string, options?: { timestamp?: boolean });
  constructor(
    @Optional() protected context?: string,
    @Optional() protected options: { timestamp?: boolean } = {},
  ) {}

  get localInstance(): LoggerService {
    if (BetterLogger.staticInstanceRef === DEFAULT_LOGGER) {
      return this.registerLocalInstanceRef();
    } else if (BetterLogger.staticInstanceRef instanceof BetterLogger) {
      const prototype = Object.getPrototypeOf(BetterLogger.staticInstanceRef);
      if (prototype.constructor === BetterLogger) {
        return this.registerLocalInstanceRef();
      }
    }

    return BetterLogger.staticInstanceRef;
  }

  private static wrapBuffer(logMethod: Function): void {
    if (!BetterLogger.isBufferAttached)
      return logMethod();

    BetterLogger.logBuffer.push(logMethod);
  }

  /**
   * Write an 'error' level log.
   */
  error(message: any, stack?: string, context?: string): void;
  error(message: any, ...optionalParams: [...any, string?, string?]): void;
  // @BetterLogger.WrapBuffer
  error(message: any, ...optionalParams: any[]) {
    BetterLogger.wrapBuffer(() => {
      optionalParams = this.context
        ? optionalParams.concat(this.context)
        : optionalParams;

      this.localInstance?.error(message, ...optionalParams);
    });
  }

  /**
   * Write a 'log' level log.
   */
  log(message: any, context?: string): void;
  log(message: any, ...optionalParams: [...any, string?]): void;
  // @BetterLogger.WrapBuffer
  log(message: any, ...optionalParams: any[]) {
    BetterLogger.wrapBuffer(() => {
      optionalParams = this.context
        ? optionalParams.concat(this.context)
        : optionalParams;

      this.localInstance?.log(message, ...optionalParams);
    });
  }

  /**
   * Write a 'warn' level log.
   */
  warn(message: any, context?: string): void;
  warn(message: any, ...optionalParams: [...any, string?]): void;
  // @BetterLogger.WrapBuffer
  warn(message: any, ...optionalParams: any[]) {
    BetterLogger.wrapBuffer(() => {
      optionalParams = this.context
        ? optionalParams.concat(this.context)
        : optionalParams;

      this.localInstance?.warn(message, ...optionalParams);
    });
  }

  /**
   * Write a 'debug' level log.
   */
  debug(message: any, context?: string): void;
  debug(message: any, ...optionalParams: [...any, string?]): void;
  // @BetterLogger.WrapBuffer
  debug(message: any, ...optionalParams: any[]) {
    BetterLogger.wrapBuffer(() => {
      optionalParams = this.context
        ? optionalParams.concat(this.context)
        : optionalParams;

      this.localInstance?.debug(message, ...optionalParams);
    });
  }

  /**
   * Write a 'verbose' level log.
   */
  verbose(message: any, context?: string): void;
  verbose(message: any, ...optionalParams: [...any, string?]): void;
  // @BetterLogger.WrapBuffer
  verbose(message: any, ...optionalParams: any[]) {
    BetterLogger.wrapBuffer(() => {
      optionalParams = this.context
        ? optionalParams.concat(this.context)
        : optionalParams;

      this.localInstance?.verbose?.(message, ...optionalParams);
    });
  }

  /**
   * Write an 'error' level log.
   */
  static error(message: any, context?: string): void;
  static error(message: any, stack?: string, context?: string): void;
  static error(
    message: any,
    ...optionalParams: [...any, string?, string?]
  ): void;
  // @BetterLogger.WrapBuffer
  static error(message: any, ...optionalParams: any[]) {
    BetterLogger.wrapBuffer(() => {
      this.staticInstanceRef?.error(message, ...optionalParams);
    });
  }

  /**
   * Write a 'log' level log.
   */
  static log(message: any, context?: string): void;
  static log(message: any, ...optionalParams: [...any, string?]): void;
  // @BetterLogger.WrapBuffer
  static log(message: any, ...optionalParams: any[]) {
    BetterLogger.wrapBuffer(() => {
      this.staticInstanceRef?.log(message, ...optionalParams);
    });
  }

  /**
   * Write a 'warn' level log.
   */
  static warn(message: any, context?: string): void;
  static warn(message: any, ...optionalParams: [...any, string?]): void;
  // @BetterLogger.WrapBuffer
  static warn(message: any, ...optionalParams: any[]) {
    BetterLogger.wrapBuffer(() => {
      this.staticInstanceRef?.warn(message, ...optionalParams);
    });
  }

  /**
   * Write a 'debug' level log, if the configured level allows for it.
   * Prints to `stdout` with newline.
   */
  static debug(message: any, context?: string): void;
  static debug(message: any, ...optionalParams: [...any, string?]): void;
  // @BetterLogger.WrapBuffer
  static debug(message: any, ...optionalParams: any[]) {
    BetterLogger.wrapBuffer(() => {
      this.staticInstanceRef?.debug(message, ...optionalParams);
    });
  }

  /**
   * Write a 'verbose' level log.
   */
  static verbose(message: any, context?: string): void;
  static verbose(message: any, ...optionalParams: [...any, string?]): void;
  // @BetterLogger.WrapBuffer
  static verbose(message: any, ...optionalParams: any[]) {
    BetterLogger.wrapBuffer(() => {
      this.staticInstanceRef?.verbose(message, ...optionalParams);
    });
  }

  /**
   * Print buffered logs and detach buffer.
   */
  static flush() {
    this.isBufferAttached = false;
    this.logBuffer.forEach(methodRef => methodRef());
    this.logBuffer = [];
  }

  /**
   * Attach buffer.
   * Turns on initialization logs buffering.
   */
  static attachBuffer() {
    this.isBufferAttached = true;
  }

  /**
   * Detach buffer.
   * Turns off initialization logs buffering.
   */
  static detachBuffer() {
    this.isBufferAttached = false;
  }

  static getTimestamp() {
    const localeStringOptions = {
      year: 'numeric',
      hour: 'numeric',
      minute: 'numeric',
      second: 'numeric',
      day: '2-digit',
      month: '2-digit',
    };
    return new Date(Date.now()).toLocaleString(
      undefined,
      localeStringOptions as Intl.DateTimeFormatOptions,
    );
  }

  static overrideLogger(logger: LoggerService | LogLevel[] | boolean) {
    if (Array.isArray(logger)) {
      BetterLogger.logLevels = logger;
      return this.staticInstanceRef?.setLogLevels(logger);
    }
    if (isObject(logger)) {
      if (logger instanceof Logger && logger.constructor !== Logger) {
        const errorMessage = `Using the "extends Logger" instruction is not allowed in Nest v9. Please, use "extends ConsoleLogger" instead.`;
        this.staticInstanceRef.error(errorMessage);
        throw new Error(errorMessage);
      }
      this.staticInstanceRef = logger as LoggerService;
    } else {
      this.staticInstanceRef = undefined;
    }
  }

  static isLevelEnabled(level: LogLevel): boolean {
    const logLevels = BetterLogger.logLevels;
    return isLogLevelEnabled(level, logLevels);
  }

  private registerLocalInstanceRef() {
    if (this.localInstanceRef) {
      return this.localInstanceRef;
    }
    this.localInstanceRef = new BetterConsoleLogger(this.context, {
      timestamp: this.options?.timestamp,
      logLevels: BetterLogger.logLevels,
    });
    return this.localInstanceRef;
  }
}

perf-better-logger.ts

// this file I use to get the profiler information
// to run this file, compile to JavaScript first,
// then you run: node --prof dist/perf-better-logger.js
// this will generate a file called: isolate-0xnnnnnnnnnnnn-v8.log
// to be able to read the information inside this file, run:
// node --prof-process isolate-0xnnnnnnnnnnnn-v8.log > processed.txt

import { BetterLogger } from './better-logger.service';

const betterLogger = new BetterLogger();

// to get CPU information, comment this loop
// and run with: node --cpu-prof dist/perf-better-logger.js
for (let i = 0; i < 1e4; i++) 
  betterLogger.log('Hello World');

perf-normal-logger.ts

// this file I use to get the profiler information
// to run this file, compile to JavaScript first,
// then you run: node --prof dist/perf-normal-logger.js
// this will generate a file called: isolate-0xnnnnnnnnnnnn-v8.log
// to be able to read the information inside this file, run:
// node --prof-process isolate-0xnnnnnnnnnnnn-v8.log > processed.txt

import { Logger } from '@nestjs/common';

const logger = new Logger();

// to get CPU information, comment this loop
// and run with: node --cpu-prof dist/perf-normal-logger.js
for (let i = 0; i < 1e4; i++) 
  logger.log('Hello World');