From 6d7fca31347c2ee989cfe2231241bca5fa7308e1 Mon Sep 17 00:00:00 2001 From: Hiroshi Ogawa Date: Mon, 6 Jan 2025 13:00:42 +0900 Subject: [PATCH 1/5] fix: batch console logs by microtask --- packages/utils/src/timers.ts | 5 ++++ packages/vitest/src/runtime/console.ts | 32 ++++++++++++++++++++++---- 2 files changed, 33 insertions(+), 4 deletions(-) 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..9e0353923942 100644 --- a/packages/vitest/src/runtime/console.ts +++ b/packages/vitest/src/runtime/console.ts @@ -37,10 +37,23 @@ export function createCustomConsole(defaultState?: WorkerGlobalState) { const stderrBuffer = new Map() const timers = new Map< string, - { stdoutTime: number; stderrTime: number; timer: any } + { stdoutTime: number; stderrTime: number; timer: any; cancel?: () => void } >() - const { setTimeout, clearTimeout } = getSafeTimers() + // 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() @@ -48,8 +61,8 @@ export function createCustomConsole(defaultState?: WorkerGlobalState) { 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) @@ -59,6 +72,17 @@ export function createCustomConsole(defaultState?: WorkerGlobalState) { sendStderr(taskId) } }) + // clearTimeout(timer.timer) + // timer.timer = setTimeout(() => { + // if (stderrTime < stdoutTime) { + // sendStderr(taskId) + // sendStdout(taskId) + // } + // else { + // sendStdout(taskId) + // sendStderr(taskId) + // } + // }) } function sendStdout(taskId: string) { sendBuffer('stdout', taskId) From c38327b829ce50508b42cfa2b285b0765c6297f7 Mon Sep 17 00:00:00 2001 From: Hiroshi Ogawa Date: Mon, 6 Jan 2025 13:13:00 +0900 Subject: [PATCH 2/5] test: add test --- packages/vitest/src/runtime/console.ts | 2 +- .../fixtures/console-batch/basic.test.ts | 25 ++++++++++++++ test/config/test/console.test.ts | 34 +++++++++++++++++++ 3 files changed, 60 insertions(+), 1 deletion(-) create mode 100644 test/config/fixtures/console-batch/basic.test.ts diff --git a/packages/vitest/src/runtime/console.ts b/packages/vitest/src/runtime/console.ts index 9e0353923942..88e5739789c4 100644 --- a/packages/vitest/src/runtime/console.ts +++ b/packages/vitest/src/runtime/console.ts @@ -57,7 +57,7 @@ export function createCustomConsole(defaultState?: WorkerGlobalState) { 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 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..682000ac6125 --- /dev/null +++ b/test/config/fixtures/console-batch/basic.test.ts @@ -0,0 +1,25 @@ +import { afterAll, afterEach, beforeAll, beforeEach, describe, test } from 'vitest' + +beforeAll(() => { + console.log('[beforeAll]') +}) + +afterAll(() => { + console.log('[afterAll]') +}) + +beforeEach(() => { + console.log('[beforeEach]') +}) + +afterEach(() => { + console.log('[afterEach]') +}) + +test('test', async () => { + console.log('a') + console.log('b') + await Promise.resolve() + console.log('c') + console.log('d') +}) diff --git a/test/config/test/console.test.ts b/test/config/test/console.test.ts index aa52de328786..f4783e7c7cbb 100644 --- a/test/config/test/console.test.ts +++ b/test/config/test/console.test.ts @@ -1,3 +1,4 @@ +import type { UserConsoleLog } from 'vitest' import { expect, test, vi } from 'vitest' import { runVitest } from '../../test-utils' @@ -21,3 +22,36 @@ 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 logs: UserConsoleLog[] = [] + await runVitest({ + root: './fixtures/console-batch', + reporters: [ + 'default', + { + onUserConsoleLog(log) { + logs.push(log) + }, + }, + ], + }) + expect(logs.map(log => log.content)).toMatchInlineSnapshot(` + [ + "[beforeAll] + ", + "[beforeEach] + ", + "a + b + ", + "c + d + ", + "[afterEach] + ", + "[afterAll] + ", + ] + `) +}) From b110c3dc9ffc34ec58faaefba58467b6d81fc4e9 Mon Sep 17 00:00:00 2001 From: Hiroshi Ogawa Date: Mon, 6 Jan 2025 13:13:54 +0900 Subject: [PATCH 3/5] chore: cleanup --- packages/vitest/src/runtime/console.ts | 16 +--------------- 1 file changed, 1 insertion(+), 15 deletions(-) diff --git a/packages/vitest/src/runtime/console.ts b/packages/vitest/src/runtime/console.ts index 88e5739789c4..4f84c577f53f 100644 --- a/packages/vitest/src/runtime/console.ts +++ b/packages/vitest/src/runtime/console.ts @@ -37,10 +37,9 @@ export function createCustomConsole(defaultState?: WorkerGlobalState) { const stderrBuffer = new Map() const timers = new Map< string, - { stdoutTime: number; stderrTime: number; timer: any; cancel?: () => void } + { stdoutTime: number; stderrTime: number; cancel?: () => void } >() - // const { setTimeout, clearTimeout } = getSafeTimers() const { queueMicrotask } = getSafeTimers() function queueCancelableMicrotask(callback: () => void) { @@ -72,17 +71,6 @@ export function createCustomConsole(defaultState?: WorkerGlobalState) { sendStderr(taskId) } }) - // clearTimeout(timer.timer) - // timer.timer = setTimeout(() => { - // if (stderrTime < stdoutTime) { - // sendStderr(taskId) - // sendStdout(taskId) - // } - // else { - // sendStdout(taskId) - // sendStderr(taskId) - // } - // }) } function sendStdout(taskId: string) { sendBuffer('stdout', taskId) @@ -152,7 +140,6 @@ export function createCustomConsole(defaultState?: WorkerGlobalState) { timer = { stdoutTime: RealDate.now(), stderrTime: RealDate.now(), - timer: 0, } timers.set(id, timer) } @@ -192,7 +179,6 @@ export function createCustomConsole(defaultState?: WorkerGlobalState) { timer = { stderrTime: RealDate.now(), stdoutTime: RealDate.now(), - timer: 0, } timers.set(id, timer) } From b46c9b555a881feb73196cd65cf071aaedfb09f2 Mon Sep 17 00:00:00 2001 From: Hiroshi Ogawa Date: Mon, 6 Jan 2025 13:24:01 +0900 Subject: [PATCH 4/5] test: tweak --- .../fixtures/console-batch/basic.test.ts | 28 +++++++++++++------ test/config/test/console.test.ts | 24 ++++++++++------ 2 files changed, 36 insertions(+), 16 deletions(-) diff --git a/test/config/fixtures/console-batch/basic.test.ts b/test/config/fixtures/console-batch/basic.test.ts index 682000ac6125..41f774a33a09 100644 --- a/test/config/fixtures/console-batch/basic.test.ts +++ b/test/config/fixtures/console-batch/basic.test.ts @@ -1,25 +1,37 @@ import { afterAll, afterEach, beforeAll, beforeEach, describe, test } from 'vitest' beforeAll(() => { - console.log('[beforeAll]') + console.log('[beforeAll 1]') +}) +beforeAll(() => { + console.log('[beforeAll 2]') }) afterAll(() => { - console.log('[afterAll]') + console.log('[afterAll 1]') +}) +afterAll(() => { + console.log('[afterAll 2]') }) beforeEach(() => { - console.log('[beforeEach]') + console.log('[beforeEach 1]') +}) +beforeEach(() => { + console.log('[beforeEach 2]') }) afterEach(() => { - console.log('[afterEach]') + console.log('[afterEach 1]') +}) +afterEach(() => { + console.log('[afterEach 2]') }) test('test', async () => { - console.log('a') - console.log('b') + console.log('[test 1]') + console.log('[test 2]') await Promise.resolve() - console.log('c') - console.log('d') + console.log('[test 3]') + console.log('[test 4]') }) diff --git a/test/config/test/console.test.ts b/test/config/test/console.test.ts index f4783e7c7cbb..9241b671fa20 100644 --- a/test/config/test/console.test.ts +++ b/test/config/test/console.test.ts @@ -38,19 +38,27 @@ test('group synchronous console logs', async () => { }) expect(logs.map(log => log.content)).toMatchInlineSnapshot(` [ - "[beforeAll] + "[beforeAll 1] ", - "[beforeEach] + "[beforeAll 2] ", - "a - b + "[beforeEach 1] ", - "c - d + "[beforeEach 2] ", - "[afterEach] + "[test 1] + [test 2] ", - "[afterAll] + "[test 3] + [test 4] + ", + "[afterEach 2] + ", + "[afterEach 1] + ", + "[afterAll 2] + ", + "[afterAll 1] ", ] `) From 1bb01f14133914c208f8f707c88cb85be9a429dd Mon Sep 17 00:00:00 2001 From: Hiroshi Ogawa Date: Tue, 7 Jan 2025 18:53:50 +0900 Subject: [PATCH 5/5] test: test stdout --- .../fixtures/console-batch/basic.test.ts | 24 +++--- test/config/test/console.test.ts | 74 ++++++++++--------- 2 files changed, 50 insertions(+), 48 deletions(-) diff --git a/test/config/fixtures/console-batch/basic.test.ts b/test/config/fixtures/console-batch/basic.test.ts index 41f774a33a09..e30a6c1b3bff 100644 --- a/test/config/fixtures/console-batch/basic.test.ts +++ b/test/config/fixtures/console-batch/basic.test.ts @@ -1,37 +1,37 @@ import { afterAll, afterEach, beforeAll, beforeEach, describe, test } from 'vitest' beforeAll(() => { - console.log('[beforeAll 1]') + console.log('__TEST__ [beforeAll 1]') }) beforeAll(() => { - console.log('[beforeAll 2]') + console.log('__TEST__ [beforeAll 2]') }) afterAll(() => { - console.log('[afterAll 1]') + console.log('__TEST__ [afterAll 1]') }) afterAll(() => { - console.log('[afterAll 2]') + console.log('__TEST__ [afterAll 2]') }) beforeEach(() => { - console.log('[beforeEach 1]') + console.log('__TEST__ [beforeEach 1]') }) beforeEach(() => { - console.log('[beforeEach 2]') + console.log('__TEST__ [beforeEach 2]') }) afterEach(() => { - console.log('[afterEach 1]') + console.log('__TEST__ [afterEach 1]') }) afterEach(() => { - console.log('[afterEach 2]') + console.log('__TEST__ [afterEach 2]') }) test('test', async () => { - console.log('[test 1]') - console.log('[test 2]') + console.log('__TEST__ [test 1]') + console.log('__TEST__ [test 2]') await Promise.resolve() - console.log('[test 3]') - console.log('[test 4]') + 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 9241b671fa20..94c5272c361c 100644 --- a/test/config/test/console.test.ts +++ b/test/config/test/console.test.ts @@ -1,4 +1,3 @@ -import type { UserConsoleLog } from 'vitest' import { expect, test, vi } from 'vitest' import { runVitest } from '../../test-utils' @@ -24,42 +23,45 @@ test.each(['threads', 'vmThreads'] as const)(`disable intercept pool=%s`, async }) test('group synchronous console logs', async () => { - const logs: UserConsoleLog[] = [] - await runVitest({ + const { stdout } = await runVitest({ root: './fixtures/console-batch', - reporters: [ - 'default', - { - onUserConsoleLog(log) { - logs.push(log) - }, - }, - ], }) - expect(logs.map(log => log.content)).toMatchInlineSnapshot(` - [ - "[beforeAll 1] - ", - "[beforeAll 2] - ", - "[beforeEach 1] - ", - "[beforeEach 2] - ", - "[test 1] - [test 2] - ", - "[test 3] - [test 4] - ", - "[afterEach 2] - ", - "[afterEach 1] - ", - "[afterAll 2] - ", - "[afterAll 1] - ", - ] + 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]" `) })