From e031cd4108faa1175c7b5e9aa87ecb7ecb8f5256 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E6=99=9A=E6=99=B4?= <2917149421@qq.com> Date: Fri, 6 Nov 2026 21:51:46 +0800 Subject: [PATCH] perf(common): reduce log snapshot and file-only allocation overhead (#656) Refs #651 --- packages/common/bench/logger.bench.ts | 39 ++++++++ packages/common/src/logger.ts | 70 ++++++++----- packages/common/tests/logger-snapshot.test.ts | 99 +++++++++++++++++++ .../proton/test/upstream/codegen/wire.test.ts | 2 +- packages/sdk/tests/package.test.ts | 2 +- 5 files changed, 183 insertions(+), 29 deletions(-) create mode 100644 packages/common/bench/logger.bench.ts create mode 100644 packages/common/tests/logger-snapshot.test.ts diff --git a/packages/common/bench/logger.bench.ts b/packages/common/bench/logger.bench.ts new file mode 100644 index 00000000..469fccd4 --- /dev/null +++ b/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); + }); +}); diff --git a/packages/common/src/logger.ts b/packages/common/src/logger.ts index 30ae1584..a397e76c 100644 --- a/packages/common/src/logger.ts +++ b/packages/common/src/logger.ts @@ -97,20 +97,13 @@ class RingBuffer { 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(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 { 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(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 { diff --git a/packages/common/tests/logger-snapshot.test.ts b/packages/common/tests/logger-snapshot.test.ts new file mode 100644 index 00000000..2a29c1a2 --- /dev/null +++ b/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([]); + }); +}); diff --git a/packages/proton/test/upstream/codegen/wire.test.ts b/packages/proton/test/upstream/codegen/wire.test.ts index 5ced78bb..04ed3e58 100644 --- a/packages/proton/test/upstream/codegen/wire.test.ts +++ b/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 }>( diff --git a/packages/sdk/tests/package.test.ts b/packages/sdk/tests/package.test.ts index 76f2fb09..73917728 100644 --- a/packages/sdk/tests/package.test.ts +++ b/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([