From 53d1d5f5df9de8d5a1658c343117779afc7461dc Mon Sep 17 00:00:00 2001 From: Hiroshi Ogawa Date: Tue, 7 Jan 2025 21:03:50 +0900 Subject: [PATCH] fix: batch console logs by microtask (#7183) --- packages/utils/src/timers.ts | 5 +++ packages/vitest/src/runtime/console.ts | 24 +++++++--- .../fixtures/console-batch/basic.test.ts | 37 ++++++++++++++++ test/config/test/console.test.ts | 44 +++++++++++++++++++ 4 files changed, 103 insertions(+), 7 deletions(-) create mode 100644 test/config/fixtures/console-batch/basic.test.ts diff --git a/packages/utils/src/timers.ts b/packages/utils/src/timers.ts index bc95037d64ee..aa9f27480032 100644 --- a/packages/utils/src/timers.ts +++ b/packages/utils/src/timers.ts @@ -8,6 +8,7 @@ export interface SafeTimers { clearTimeout: typeof clearTimeout setImmediate: typeof setImmediate clearImmediate: typeof clearImmediate + queueMicrotask: typeof queueMicrotask } export function getSafeTimers(): SafeTimers { @@ -18,6 +19,7 @@ export function getSafeTimers(): SafeTimers { clearTimeout: safeClearTimeout, setImmediate: safeSetImmediate, clearImmediate: safeClearImmediate, + queueMicrotask: safeQueueMicrotask, } = (globalThis as any)[SAFE_TIMERS_SYMBOL] || globalThis const { nextTick: safeNextTick } = (globalThis as any)[SAFE_TIMERS_SYMBOL] @@ -31,6 +33,7 @@ export function getSafeTimers(): SafeTimers { clearTimeout: safeClearTimeout, setImmediate: safeSetImmediate, clearImmediate: safeClearImmediate, + queueMicrotask: safeQueueMicrotask, } } @@ -42,6 +45,7 @@ export function setSafeTimers(): void { clearTimeout: safeClearTimeout, setImmediate: safeSetImmediate, clearImmediate: safeClearImmediate, + queueMicrotask: safeQueueMicrotask, } = globalThis const { nextTick: safeNextTick } = globalThis.process || { @@ -56,6 +60,7 @@ export function setSafeTimers(): void { clearTimeout: safeClearTimeout, setImmediate: safeSetImmediate, clearImmediate: safeClearImmediate, + queueMicrotask: safeQueueMicrotask, }; (globalThis as any)[SAFE_TIMERS_SYMBOL] = timers diff --git a/packages/vitest/src/runtime/console.ts b/packages/vitest/src/runtime/console.ts index c8cdda97678e..4f84c577f53f 100644 --- a/packages/vitest/src/runtime/console.ts +++ b/packages/vitest/src/runtime/console.ts @@ -37,19 +37,31 @@ export function createCustomConsole(defaultState?: WorkerGlobalState) { const stderrBuffer = new Map() const timers = new Map< string, - { stdoutTime: number; stderrTime: number; timer: any } + { stdoutTime: number; stderrTime: number; cancel?: () => void } >() - const { setTimeout, clearTimeout } = getSafeTimers() + const { queueMicrotask } = getSafeTimers() + + function queueCancelableMicrotask(callback: () => void) { + let canceled = false + queueMicrotask(() => { + if (!canceled) { + callback() + } + }) + return () => { + canceled = true + } + } const state = () => defaultState || getWorkerState() - // group sync console.log calls with macro task + // group sync console.log calls with micro task function schedule(taskId: string) { const timer = timers.get(taskId)! const { stdoutTime, stderrTime } = timer - clearTimeout(timer.timer) - timer.timer = setTimeout(() => { + timer.cancel?.() + timer.cancel = queueCancelableMicrotask(() => { if (stderrTime < stdoutTime) { sendStderr(taskId) sendStdout(taskId) @@ -128,7 +140,6 @@ export function createCustomConsole(defaultState?: WorkerGlobalState) { timer = { stdoutTime: RealDate.now(), stderrTime: RealDate.now(), - timer: 0, } timers.set(id, timer) } @@ -168,7 +179,6 @@ export function createCustomConsole(defaultState?: WorkerGlobalState) { timer = { stderrTime: RealDate.now(), stdoutTime: RealDate.now(), - timer: 0, } timers.set(id, timer) } diff --git a/test/config/fixtures/console-batch/basic.test.ts b/test/config/fixtures/console-batch/basic.test.ts new file mode 100644 index 000000000000..e30a6c1b3bff --- /dev/null +++ b/test/config/fixtures/console-batch/basic.test.ts @@ -0,0 +1,37 @@ +import { afterAll, afterEach, beforeAll, beforeEach, describe, test } from 'vitest' + +beforeAll(() => { + console.log('__TEST__ [beforeAll 1]') +}) +beforeAll(() => { + console.log('__TEST__ [beforeAll 2]') +}) + +afterAll(() => { + console.log('__TEST__ [afterAll 1]') +}) +afterAll(() => { + console.log('__TEST__ [afterAll 2]') +}) + +beforeEach(() => { + console.log('__TEST__ [beforeEach 1]') +}) +beforeEach(() => { + console.log('__TEST__ [beforeEach 2]') +}) + +afterEach(() => { + console.log('__TEST__ [afterEach 1]') +}) +afterEach(() => { + console.log('__TEST__ [afterEach 2]') +}) + +test('test', async () => { + console.log('__TEST__ [test 1]') + console.log('__TEST__ [test 2]') + await Promise.resolve() + console.log('__TEST__ [test 3]') + console.log('__TEST__ [test 4]') +}) diff --git a/test/config/test/console.test.ts b/test/config/test/console.test.ts index aa52de328786..94c5272c361c 100644 --- a/test/config/test/console.test.ts +++ b/test/config/test/console.test.ts @@ -21,3 +21,47 @@ test.each(['threads', 'vmThreads'] as const)(`disable intercept pool=%s`, async const call = spy.mock.lastCall![0] expect(call.toString()).toBe('__test_console__\n') }) + +test('group synchronous console logs', async () => { + const { stdout } = await runVitest({ + root: './fixtures/console-batch', + }) + const logs = stdout + .split('\n') + .filter(row => row.length === 0 || row.startsWith('stdout | ') || row.startsWith('__TEST__')) + .join('\n') + .trim() + expect(logs).toMatchInlineSnapshot(` + "stdout | basic.test.ts + __TEST__ [beforeAll 1] + + stdout | basic.test.ts + __TEST__ [beforeAll 2] + + stdout | basic.test.ts > test + __TEST__ [beforeEach 1] + + stdout | basic.test.ts > test + __TEST__ [beforeEach 2] + + stdout | basic.test.ts > test + __TEST__ [test 1] + __TEST__ [test 2] + + stdout | basic.test.ts > test + __TEST__ [test 3] + __TEST__ [test 4] + + stdout | basic.test.ts > test + __TEST__ [afterEach 2] + + stdout | basic.test.ts > test + __TEST__ [afterEach 1] + + stdout | basic.test.ts + __TEST__ [afterAll 2] + + stdout | basic.test.ts + __TEST__ [afterAll 1]" + `) +})