perf(logging): add defer log for util inspect

H4ad · Dec 31, 2022 · 2a7389e · 2a7389e
1 parent c4c8dea
commit 2a7389e
Show file tree

Hide file tree

Showing 6 changed files with 65 additions and 26 deletions.
diff --git a/benchmark/README.md b/benchmark/README.md
@@ -12,6 +12,7 @@ npm run build
 npm pack
 cd benchmark
 npm ci
+npm i ../h4ad-serverless-adapter-0.0.0-development.tgz
 npm run bench
 ```
 
@@ -24,11 +25,11 @@ npm run bench
 ╔════════════════════════════╤═════════╤════════════════╤═══════════╗
 ║ Slower tests               │ Samples │         Result │ Tolerance ║
 ╟────────────────────────────┼─────────┼────────────────┼───────────╢
-║ @h4ad/serverless-adapter   │    5500 │ 4424.96 op/sec │  ± 0.98 % ║
-║ @vendia/serverless-express │    6500 │ 4454.06 op/sec │  ± 0.97 % ║
+║ @vendia/serverless-express │    5500 │ 4518.75 op/sec │  ± 0.99 % ║
+║ @h4ad/serverless-adapter   │   10000 │ 7590.44 op/sec │  ± 1.29 % ║
 ╟────────────────────────────┼─────────┼────────────────┼───────────╢
 ║ Fastest test               │ Samples │         Result │ Tolerance ║
 ╟────────────────────────────┼─────────┼────────────────┼───────────╢
-║ serverless-http            │   10000 │ 8046.93 op/sec │  ± 1.48 % ║
+║ serverless-http            │   10000 │ 8298.48 op/sec │  ± 1.53 % ║
 ╚════════════════════════════╧═════════╧════════════════╧═══════════╝
 ```
diff --git a/benchmark/package-lock.json b/benchmark/package-lock.json
diff --git a/src/core/logger.ts b/src/core/logger.ts
@@ -51,6 +51,35 @@ export type ILogger = Record<Exclude<LogLevels, 'none'>, LoggerFN>;
  */
 const InternalLoggerSymbol = Symbol('InternalLogger');
 
+const errorLogLevel = new Map([
+  ['debug', true],
+  ['verbose', true],
+  ['info', true],
+  ['warn', true],
+  ['error', true],
+]);
+const warnLogLevel = new Map([
+  ['debug', true],
+  ['verbose', true],
+  ['info', true],
+  ['warn', true],
+]);
+const infoLogLevel = new Map([
+  ['debug', true],
+  ['verbose', true],
+  ['info', true],
+]);
+const verboseLogLevel = new Map([
+  ['debug', true],
+  ['verbose', true],
+]);
+
+const lazyPrint = value => {
+  if (typeof value === 'function') return value();
+
+  return value;
+};
+
 /**
  * The method used to create a simple logger instance to use in this library.
  *
@@ -72,37 +101,32 @@ const InternalLoggerSymbol = Symbol('InternalLogger');
 export function createDefaultLogger(
   { level }: LoggerOptions = { level: 'error' },
 ): ILogger {
-  const errorLogLevel = ['debug', 'verbose', 'info', 'warn', 'error'];
-  const warnLogLevel = ['debug', 'verbose', 'info', 'warn'];
-  const infoLogLevel = ['debug', 'verbose', 'info'];
-  const verboseLogLevel = ['debug', 'verbose'];
-
   return {
     [InternalLoggerSymbol]: true,
     error: (message, ...additional) => {
-      if (!errorLogLevel.includes(level)) return;
+      if (!errorLogLevel.has(level)) return;
 
-      console.error(message, ...additional);
+      console.error(message, ...additional.map(lazyPrint));
     },
     warn: (message, ...additional) => {
-      if (!warnLogLevel.includes(level)) return;
+      if (!warnLogLevel.has(level)) return;
 
-      console.warn(message, ...additional);
+      console.warn(message, ...additional.map(lazyPrint));
     },
     info: (message, ...additional) => {
-      if (!infoLogLevel.includes(level)) return;
+      if (!infoLogLevel.has(level)) return;
 
-      console.info(message, ...additional);
+      console.info(message, ...additional.map(lazyPrint));
     },
     verbose: (message, ...additional) => {
-      if (!verboseLogLevel.includes(level)) return;
+      if (!verboseLogLevel.has(level)) return;
 
-      console.debug(message, ...additional);
+      console.debug(message, ...additional.map(lazyPrint));
     },
     debug: (message, ...additional) => {
       if (level !== 'debug') return;
 
-      console.debug(message, ...additional);
+      console.debug(message, ...additional.map(lazyPrint));
     },
   } as ILogger;
 }

diff --git a/src/handlers/default/default.handler.ts b/src/handlers/default/default.handler.ts
@@ -117,12 +117,12 @@ export class DefaultHandler<
     binarySettings: BinarySettings,
     respondWithErrors: boolean,
   ): void {
-    log.debug('SERVERLESS_ADAPTER:PROXY', {
+    log.debug('SERVERLESS_ADAPTER:PROXY', () => ({
       event: util.inspect(event, { depth: null }),
       context: util.inspect(context, { depth: null }),
       binarySettings,
       respondWithErrors,
-    });
+    }));
   }
 
   /**
@@ -218,10 +218,13 @@ export class DefaultHandler<
     successResponse: TResponse,
     body: string,
   ) {
-    log.debug('SERVERLESS_ADAPTER:FORWARD_RESPONSE:EVENT_SOURCE_RESPONSE', {
-      successResponse: util.inspect(successResponse, { depth: null }),
-      body,
-    });
+    log.debug(
+      'SERVERLESS_ADAPTER:FORWARD_RESPONSE:EVENT_SOURCE_RESPONSE',
+      () => ({
+        successResponse: util.inspect(successResponse, { depth: null }),
+        body,
+      }),
+    );
   }
 
   //#endregion

diff --git a/test/core/logger.spec.ts b/test/core/logger.spec.ts
@@ -35,6 +35,17 @@ describe('createDefaultLogger', () => {
     expect(createDefaultLogger()).toBeDefined();
   });
 
+  it('should lazy log when we pass a function', () => {
+    const logger = createDefaultLogger({ level: 'debug' });
+
+    logger.debug('debug', () => '=true', ' works');
+
+    expect(global.console.debug).not.toHaveBeenNthCalledWith(
+      1,
+      'debug=true works',
+    );
+  });
+
   it('should log correctly with log level as none', () => {
     const logger = createDefaultLogger({ level: 'none' });
 

diff --git a/test/handlers/default.handler.spec.ts b/test/handlers/default.handler.spec.ts
@@ -50,7 +50,7 @@ describe('DefaultHandler', () => {
       expect(logger.debug).toHaveBeenNthCalledWith(
         1,
         'SERVERLESS_ADAPTER:PROXY',
-        expect.any(Object),
+        expect.any(Function),
       );
 
       expect(logger.debug).toHaveBeenNthCalledWith(
@@ -80,7 +80,7 @@ describe('DefaultHandler', () => {
       expect(logger.debug).toHaveBeenNthCalledWith(
         6,
         'SERVERLESS_ADAPTER:FORWARD_RESPONSE:EVENT_SOURCE_RESPONSE',
-        expect.any(Object),
+        expect.any(Function),
       );
 
       expect(result).toHaveProperty('headers', {