perf(common): reduce log snapshot and file-only allocation overhead (#656)

Refs #651

packages/common/bench/logger.bench.ts

@@ -0,0 +1,39 @@
+// pnpm --filter @snowluma/common exec vitest bench --run bench/logger.bench.ts
+import { bench, describe, vi } from 'vitest';
+
+vi.stubEnv('SNOWLUMA_LOG_LEVEL', 'trace');
+vi.stubEnv('SNOWLUMA_LOG_FILE', '0');
+vi.stubEnv('SNOWLUMA_TRACE_BUFFER', '5000');
+const { createLogger, getLogSnapshot, getRecentLogs, setLogLevel } = await import('../src/logger');
+const stdout = vi.spyOn(process.stdout, 'write').mockReturnValue(true);
+const log = createLogger('Benchmark');
+
+for (let i = 0; i < 5000; i += 1) {
+    log.trace('trace %d', i);
+
+    if (i % 5 === 0) {
+        log.info('normal %d', i);
+    }
+}
+
+stdout.mockRestore();
+
+describe('6,000 retained records', () => {
+    bench('recent 30', () => {
+        getRecentLogs(30);
+    });
+    bench('recent 300', () => {
+        getRecentLogs(300);
+    });
+    bench('complete export', () => {
+        getLogSnapshot();
+    });
+});
+
+setLogLevel('info');
+
+describe('file-only debug records with disk disabled', () => {
+    bench('format and route debug', () => {
+        log.debug('packet command=%s bytes=%d', 'Example.Service', 1024);
+    });
+});

packages/common/src/logger.ts

@@ -97,20 +97,13 @@ class RingBuffer<T> {
             this.start = (this.start + 1) % this.cap;
         } // full → overwrite oldest
     }
-    /** Most recent `n` items, oldest→newest. */
-    recent(n: number): T[] {
-        const take = Math.max(0, Math.min(Math.trunc(n), this.count));
-        const out: T[] = new Array<T>(take);
-        const first = this.start + (this.count - take);
-
-        for (let i = 0; i < take; i += 1) {
-            out[i] = this.buf[(first + i) % this.cap]!;
+    /** Read from newest to oldest without copying the retained buffer. */
+    newest(offset: number): T | undefined {
+        if (offset >= this.count) {
+            return undefined;
         }
 
-        return out;
-    }
-    toArray(): T[] {
-        return this.recent(this.count);
+        return this.buf[(this.start + this.count - 1 - offset) % this.cap];
     }
     get size(): number {
         return this.count;
@@ -282,18 +275,22 @@ function emit(level: LogLevel, options: LogOptions, args: unknown[]): void {
     const formattedMessage = format(...realArgs);
     const message = level === 'trace' ? formattedMessage : redactLogMessage(formattedMessage);
     const line = render(level, options, message, reqId);
-    const entry: LogEntry = {
-        id: nextLogId++,
-        time: new Date().toISOString(),
-        level,
-        scope: options.scope,
-        ...(options.uin !== undefined ? { uin: options.uin } : {}),
-        ...(reqId !== undefined ? { req: reqId } : {}),
-        message,
-        line: sanitizeLogLine(line),
-    };
+    const id = nextLogId++;
 
     if (passesConsole) {
+        // File-only records are sanitized by the transport and need no memory
+        // entry, ISO timestamp, or second sanitized copy of the rendered line.
+        const entry: LogEntry = {
+            id,
+            time: new Date().toISOString(),
+            level,
+            scope: options.scope,
+            ...(options.uin !== undefined ? { uin: options.uin } : {}),
+            ...(reqId !== undefined ? { req: reqId } : {}),
+            message,
+            line: sanitizeLogLine(line),
+        };
+
         // Trace gets its own ring so its volume never evicts the normal log buffer.
         (level === 'trace' ? traceRing : logRing).push(entry);
 
@@ -337,10 +334,28 @@ export function closeLogger(): Promise<void> {
     return getFileTransport().close();
 }
 
-function mergeLogRings(): LogEntry[] {
-    return traceRing.size > 0
-        ? [...logRing.toArray(), ...traceRing.toArray()].sort((a, b) => a.id - b.id)
-        : logRing.toArray();
+function mergeLogRings(limit = logRing.size + traceRing.size): LogEntry[] {
+    const take = Math.min(limit, logRing.size + traceRing.size);
+    const entries = new Array<LogEntry>(take);
+    let normalOffset = 0;
+    let traceOffset = 0;
+
+    // Both rings already follow increasing IDs. Merge backwards so a small
+    // WebUI request visits only the requested tail, even with a large TRACE ring.
+    for (let i = take - 1; i >= 0; i -= 1) {
+        const normal = logRing.newest(normalOffset);
+        const trace = traceRing.newest(traceOffset);
+
+        if (normal && (!trace || normal.id > trace.id)) {
+            entries[i] = normal;
+            normalOffset += 1;
+        } else {
+            entries[i] = trace!;
+            traceOffset += 1;
+        }
+    }
+
+    return entries;
 }
 
 export function getLogSnapshot(): LogEntry[] {
@@ -349,7 +364,8 @@ export function getLogSnapshot(): LogEntry[] {
 
 export function getRecentLogs(limit = 300): LogEntry[] {
     const n = Math.max(1, Math.trunc(limit));
-    return mergeLogRings().slice(-n);
+    // Array.slice(-NaN) previously returned the full snapshot.
+    return mergeLogRings(Number.isNaN(n) ? undefined : n);
 }
 
 export function subscribeLogs(callback: (entry: LogEntry) => void): () => void {

packages/common/tests/logger-snapshot.test.ts

@@ -0,0 +1,99 @@
+import { afterEach, describe, expect, it, vi } from 'vitest';
+
+const { fileWrite } = vi.hoisted(() => ({ fileWrite: vi.fn() }));
+
+vi.mock('../src/log-file-transport', () => ({
+    getFileTransport: () => ({ write: fileWrite, close: async () => {} }),
+}));
+
+afterEach(() => {
+    vi.restoreAllMocks();
+    vi.unstubAllEnvs();
+    vi.resetModules();
+    fileWrite.mockClear();
+});
+
+async function setup() {
+    vi.stubEnv('SNOWLUMA_LOG_LEVEL', 'trace');
+    vi.stubEnv('SNOWLUMA_LOG_FILE_LEVEL', 'error');
+    vi.stubEnv('SNOWLUMA_TRACE_BUFFER', '100');
+    vi.spyOn(process.stdout, 'write').mockReturnValue(true);
+    vi.spyOn(process.stderr, 'write').mockReturnValue(true);
+    const logger = await import('../src/logger');
+    return { ...logger, log: logger.createLogger('Snapshot') };
+}
+
+describe('retained log snapshots', () => {
+    it('returns empty snapshots before any record has been emitted', async () => {
+        const logger = await setup();
+        expect(logger.getRecentLogs()).toEqual([]);
+        expect(logger.getLogSnapshot()).toEqual([]);
+    });
+
+    it('merges wrapped rings in emission order and returns only the requested tail', async () => {
+        const logger = await setup();
+        const emitted: import('../src/logger').LogEntry[] = [];
+        const unsubscribe = logger.subscribeLogs((entry) => emitted.push(entry));
+
+        for (let i = 0; i < 1100; i += 1) {
+            logger.log.info('normal %d', i);
+            logger.log.trace('trace %d', i);
+        }
+
+        unsubscribe();
+        const normal = emitted.filter((entry) => entry.level !== 'trace').slice(-1000);
+        const trace = emitted.filter((entry) => entry.level === 'trace').slice(-100);
+        const expected = [...normal, ...trace].sort((a, b) => a.id - b.id);
+        expect(logger.getLogSnapshot()).toEqual(expected);
+
+        for (const limit of [1, 2, 30, 300, 1000, 1100, 2000, 0, -1, 2.9, NaN, Infinity]) {
+            expect(logger.getRecentLogs(limit)).toEqual(
+                expected.slice(-Math.max(1, Math.trunc(limit))),
+            );
+        }
+
+        expect(logger.getRecentLogs()).toEqual(expected.slice(-300));
+        const snapshot = logger.getRecentLogs(5);
+        snapshot.pop();
+        expect(logger.getRecentLogs(5)).toEqual(expected.slice(-5));
+    });
+
+    it.each(['info', 'trace'] as const)(
+        'reads a tail when only the %s ring has records',
+        async (level) => {
+            const logger = await setup();
+            logger.log[level]('first');
+            logger.log[level]('second');
+            expect(logger.getRecentLogs(1).map((entry) => entry.message)).toEqual(['second']);
+            expect(logger.getLogSnapshot().map((entry) => entry.message)).toEqual([
+                'first',
+                'second',
+            ]);
+        },
+    );
+
+    it('preserves ID gaps and file routing without publishing file-only entries', async () => {
+        const logger = await setup();
+        vi.stubEnv('SNOWLUMA_LOG_FILE_LEVEL', 'debug');
+        vi.resetModules();
+        const fresh = await import('../src/logger');
+        fresh.setLogLevel('info');
+        const entries: import('../src/logger').LogEntry[] = [];
+        const unsubscribe = fresh.subscribeLogs((entry) => entries.push(entry));
+        const log = fresh.createLogger('FileOnly').child({ uin: 10001 });
+        log.info('before');
+        fresh.runWithRequestId(42, () => log.debug('password=secret file-only\x07'));
+        log.info('after');
+        unsubscribe();
+
+        expect(entries.map((entry) => entry.message)).toEqual(['before', 'after']);
+        expect(entries[1]!.id).toBe(entries[0]!.id + 2);
+        expect(fresh.getLogSnapshot()).toEqual(entries);
+        expect(fileWrite).toHaveBeenCalledWith(
+            expect.stringMatching(/\[req#42\] password=\*\*\* file-only/),
+            10001,
+        );
+        expect(process.stdout.write).toHaveBeenCalledTimes(2);
+        expect(logger.getLogSnapshot()).toEqual([]);
+    });
+});

packages/proton/test/upstream/codegen/wire.test.ts

@@ -25,7 +25,7 @@ describe('generated wire format', () => {
                 });
             }
         }
-    });
+    }, 30_000);
 
     it('decodes floating-point, fixed-width and byte fields from unaligned subarrays', () => {
         const codec = codecs<{ f: number; d: number; fixed: bigint; data: Uint8Array }>(

packages/sdk/tests/package.test.ts

@@ -169,7 +169,7 @@ afterAll(() => {
 describe('SDK package entry points', () => {
     it('keeps browser consumers independent of Node server declarations', () => {
         node([compiler, '-p', path.join(consumerRoot, 'tsconfig.browser.json')]);
-    });
+    }, 30_000);
 
     it('starts the published Node reverse server without workspace resolution', () => {
         node([