Feat: Simple profiler for BuiltinLogger (#1945)

Maybe not so simple

CHANGELOG.md

@@ -2,6 +2,32 @@
 
 ## Version 20
 
+### v20.5.0
+
+- Featuring a simple profiler for the built-in logger:
+  - Introducing `BuiltinLogger::profile(msg: string)` — measures the duration until you invoke the returned callback;
+  - Using Node Performance Hooks for measuring microtimes (less than 1ms);
+  - The output severity is `debug` (will be customizable later), so logger must have the corresponding `level`;
+  - It prints the duration in log using adaptive units: from picoseconds to minutes.
+
+```typescript
+// usage assuming that logger is an instance of BuiltinLogger
+const done = logger.profile("expensive operation");
+doExpensiveOperation();
+done(); // debug: expensive operation '555 milliseconds'
+```
+
+```typescript
+// to set up config using the built-in logger do this:
+import { createConfig, BuiltinLogger } from "express-zod-api";
+
+const config = createConfig({ logger: { level: "debug", color: true } });
+
+declare module "express-zod-api" {
+  interface LoggerOverrides extends BuiltinLogger {}
+}
+```
+
 ### v20.4.1
 
 - Technical update due to improved builder configuration:

README.md

@@ -37,7 +37,8 @@ Start your API server with I/O schema validation and custom middlewares in minut
    9. [Enabling HTTPS](#enabling-https)
    10. [Customizing logger](#customizing-logger)
    11. [Child logger](#child-logger)
-   12. [Enabling compression](#enabling-compression)
+   12. [Profiling](#profiling)
+   13. [Enabling compression](#enabling-compression)
 5. [Advanced features](#advanced-features)
    1. [Customizing input sources](#customizing-input-sources)
    2. [Route path params](#route-path-params)
@@ -613,10 +614,10 @@ it can also be asynchronous. The child logger returned by that function will rep
 You can use the `.child()` method of the built-in logger or [install a custom logger](#customizing-logger) instead.
 
 ```typescript
-import { createConfig } from "express-zod-api";
+import { createConfig, BuiltinLogger } from "express-zod-api";
 import { randomUUID } from "node:crypto";
 
-// This enables the .child() method on the built-in logger:
+// This enables the .child() method on "logger":
 declare module "express-zod-api" {
   interface LoggerOverrides extends BuiltinLogger {}
 }
@@ -628,6 +629,27 @@ const config = createConfig({
 });
 ```
 
+## Profiling
+
+For debugging and performance testing purposes the library offers a simple `.profile()` method on the built-in logger.
+It starts a timer when you call it and measures the duration in adaptive units (from picoseconds to minutes) until you
+invoke the returned callback. The `level` of the logger must be set to `debug` to make those measurements visible.
+
+```typescript
+import { createConfig, BuiltinLogger } from "express-zod-api";
+
+// This enables the .profile() method on "logger":
+declare module "express-zod-api" {
+  interface LoggerOverrides extends BuiltinLogger {}
+}
+const config = createConfig({ logger: { level: "debug", color: true } });
+
+// Inside a handler of Endpoint, Middleware or ResultHandler:
+const done = logger.profile("expensive operation");
+doExpensiveOperation();
+done(); // debug: expensive operation '555 milliseconds'
+```
+
 ## Enabling compression
 
 According to [Express.js best practices guide](http://expressjs.com/en/advanced/best-practice-performance.html)

example/config.ts

@@ -38,7 +38,7 @@ declare module "express-zod-api" {
 }
 */
 
-// Uncomment these lines for using .child() method of built-in logger:
+// Uncomment these lines for using .child() and .profile() methods of built-in logger:
 /*
 declare module "express-zod-api" {
   interface LoggerOverrides extends BuiltinLogger {}

src/builtin-logger.ts

@@ -1,7 +1,8 @@
 import { Ansis, blue, cyanBright, green, hex, red } from "ansis";
 import { inspect } from "node:util";
+import { performance } from "node:perf_hooks";
 import type { FlatObject } from "./common-helpers";
-import { AbstractLogger, severity } from "./logger-helpers";
+import { AbstractLogger, formatDuration, severity } from "./logger-helpers";
 
 interface Context extends FlatObject {
   requestId?: string;
@@ -106,4 +107,10 @@ export class BuiltinLogger implements AbstractLogger {
   public child(ctx: Context) {
     return new BuiltinLogger({ ...this.config, ctx });
   }
+
+  /** @desc Measures the duration until you invoke the returned callback */
+  public profile(message: string) {
+    const start = performance.now();
+    return () => this.debug(message, formatDuration(performance.now() - start));
+  }
 }

src/logger-helpers.ts

@@ -25,3 +25,33 @@ export const severity: Record<keyof AbstractLogger, number> = {
 export const isLoggerInstance = (subject: unknown): subject is AbstractLogger =>
   isObject(subject) &&
   Object.keys(severity).some((method) => method in subject);
+
+/**
+ * @todo consider Intl units when Node 18 dropped (microsecond unit is missing, picosecond is not in list)
+ * @link https://tc39.es/ecma402/#table-sanctioned-single-unit-identifiers
+ * */
+const makeNumberFormat = (fraction = 0) =>
+  Intl.NumberFormat(undefined, {
+    useGrouping: false,
+    minimumFractionDigits: 0,
+    maximumFractionDigits: fraction,
+  });
+
+// creating them once increases the performance significantly
+const intFormat = makeNumberFormat();
+const floatFormat = makeNumberFormat(2);
+
+// not using R.cond for performance optimization
+const pickTimeUnit = (ms: number): [string, number, Intl.NumberFormat] => {
+  if (ms < 1e-6) return ["picosecond", ms / 1e-9, intFormat];
+  if (ms < 1e-3) return ["nanosecond", ms / 1e-6, intFormat];
+  if (ms < 1) return ["microsecond", ms / 1e-3, intFormat];
+  if (ms < 1e3) return ["millisecond", ms, intFormat];
+  if (ms < 6e4) return ["second", ms / 1e3, floatFormat];
+  return ["minute", ms / 6e4, floatFormat];
+};
+
+export const formatDuration = (durationMs: number) => {
+  const [unit, converted, formatter] = pickTimeUnit(durationMs);
+  return `${formatter.format(converted)} ${unit}${converted > 1 ? "s" : ""}`;
+};

tests/bench/documentation.bench.ts

@@ -3,7 +3,7 @@ import { config } from "../../example/config";
 import { routing } from "../../example/routing";
 import { Documentation } from "../../src";
 
-describe("Documentation", () => {
+describe.skip("Documentation", () => {
   bench(
     "example",
     () => {

tests/bench/endpoint.bench.ts

@@ -2,7 +2,7 @@ import { bench, describe, expect } from "vitest";
 import { retrieveUserEndpoint } from "../../example/endpoints/retrieve-user";
 import { testEndpoint } from "../../src";
 
-describe("Endpoint", () => {
+describe.skip("Endpoint", () => {
   bench(
     "retrieveUserEndpoint",
     async () => {

tests/bench/experiment.bench.ts

@@ -1,15 +1,12 @@
 import { bench, describe } from "vitest";
+import { formatDuration } from "../../src/logger-helpers";
 
-describe.skip("Experiment", () => {
-  const originalFn = () => {};
+describe.each([0.555, 555, 55555555])("Experiment", (ms) => {
+  bench("original", () => {
+    formatDuration(ms);
+  });
 
-  bench(
-    "original",
-    () => {
-      originalFn();
-    },
-    { time: 5000 },
-  );
-
-  bench("featured", () => {}, { time: 5000 });
+  bench("featured", () => {
+    formatDuration(ms);
+  });
 });

tests/bench/integration.bench.ts

@@ -2,7 +2,7 @@ import { bench, describe, expect } from "vitest";
 import { routing } from "../../example/routing";
 import { Integration } from "../../src";
 
-describe("Integration", () => {
+describe.skip("Integration", () => {
   bench(
     "example",
     () => {

tests/unit/__snapshots__/logger-helpers.spec.ts.snap

@@ -0,0 +1,41 @@
+// Vitest Snapshot v1, https://vitest.dev/guide/snapshot.html
+
+exports[`Logger helpers > formatDuration() > 0 should format 1e-9 ms 1`] = `"1 picosecond"`;
+
+exports[`Logger helpers > formatDuration() > 1 should format 1e-8 ms 1`] = `"10 picoseconds"`;
+
+exports[`Logger helpers > formatDuration() > 2 should format 1e-7 ms 1`] = `"100 picoseconds"`;
+
+exports[`Logger helpers > formatDuration() > 3 should format 0.000001 ms 1`] = `"1 nanosecond"`;
+
+exports[`Logger helpers > formatDuration() > 4 should format 0.00001 ms 1`] = `"10 nanoseconds"`;
+
+exports[`Logger helpers > formatDuration() > 5 should format 0.0001 ms 1`] = `"100 nanoseconds"`;
+
+exports[`Logger helpers > formatDuration() > 6 should format 0.001 ms 1`] = `"1 microsecond"`;
+
+exports[`Logger helpers > formatDuration() > 7 should format 0.01 ms 1`] = `"10 microseconds"`;
+
+exports[`Logger helpers > formatDuration() > 8 should format 0.1 ms 1`] = `"100 microseconds"`;
+
+exports[`Logger helpers > formatDuration() > 9 should format 1 ms 1`] = `"1 millisecond"`;
+
+exports[`Logger helpers > formatDuration() > 10 should format 10 ms 1`] = `"10 milliseconds"`;
+
+exports[`Logger helpers > formatDuration() > 11 should format 100 ms 1`] = `"100 milliseconds"`;
+
+exports[`Logger helpers > formatDuration() > 12 should format 1000 ms 1`] = `"1 second"`;
+
+exports[`Logger helpers > formatDuration() > 13 should format 1500 ms 1`] = `"1.5 seconds"`;
+
+exports[`Logger helpers > formatDuration() > 14 should format 10000 ms 1`] = `"10 seconds"`;
+
+exports[`Logger helpers > formatDuration() > 15 should format 100000 ms 1`] = `"1.67 minutes"`;
+
+exports[`Logger helpers > formatDuration() > 16 should format 1000000 ms 1`] = `"16.67 minutes"`;
+
+exports[`Logger helpers > formatDuration() > 17 should format 10000000 ms 1`] = `"166.67 minutes"`;
+
+exports[`Logger helpers > formatDuration() > 18 should format 100000000 ms 1`] = `"1666.67 minutes"`;
+
+exports[`Logger helpers > formatDuration() > 19 should format 1000000000 ms 1`] = `"16666.67 minutes"`;

tests/unit/builtin-logger.spec.ts

@@ -9,6 +9,7 @@ import {
   test,
   vi,
 } from "vitest";
+import { performance } from "node:perf_hooks";
 import { BuiltinLogger, BuiltinLoggerConfig } from "../../src/builtin-logger";
 
 describe("BuiltinLogger", () => {
@@ -114,4 +115,22 @@ describe("BuiltinLogger", () => {
       expect(logSpy.mock.calls).toMatchSnapshot();
     });
   });
+
+  describe("profile()", () => {
+    test.each([1e-3, 1e-2, 1e-1, 1, 1e1, 1e2, 1e3])(
+      "should measure %s ms",
+      async (delay) => {
+        const { logger, logSpy } = makeLogger({ level: "debug", color: false });
+        const stop = logger.profile("test");
+        const start = performance.now();
+        while (performance.now() - start < delay) {} // eslint-disable-line no-empty -- waits
+        stop();
+        expect(logSpy).toHaveBeenCalledWith(
+          expect.stringMatching(
+            /2022-01-01T00:00:00.000Z debug: test '[\d.]+ (pico|micro|milli)?second(s)?'/,
+          ),
+        );
+      },
+    );
+  });
 });

tests/unit/logger-helpers.spec.ts

@@ -1,6 +1,10 @@
 import { BuiltinLogger } from "../../src";
 import { BuiltinLoggerConfig } from "../../src/builtin-logger";
-import { AbstractLogger, isLoggerInstance } from "../../src/logger-helpers";
+import {
+  AbstractLogger,
+  formatDuration,
+  isLoggerInstance,
+} from "../../src/logger-helpers";
 import { describe, expect, test } from "vitest";
 
 describe("Logger helpers", () => {
@@ -31,4 +35,13 @@ describe("Logger helpers", () => {
       expect(isLoggerInstance(sample)).toBeTruthy();
     });
   });
+
+  describe("formatDuration()", () => {
+    test.each([
+      1e-9, 1e-8, 1e-7, 1e-6, 1e-5, 1e-4, 1e-3, 1e-2, 1e-1, 1, 1e1, 1e2, 1e3,
+      15e2, 1e4, 1e5, 1e6, 1e7, 1e8, 1e9,
+    ])("%# should format %s ms", (duration) =>
+      expect(formatDuration(duration)).toMatchSnapshot(),
+    );
+  });
 });