diff --git a/src/jsc/ConsoleObject.rs b/src/jsc/ConsoleObject.rs index 96dae5137792..6e9d1e168ae8 100644 --- a/src/jsc/ConsoleObject.rs +++ b/src/jsc/ConsoleObject.rs @@ -5922,6 +5922,48 @@ thread_local! { static PENDING_TIME_LOGS_LOADED: Cell = const { Cell::new(false) }; } +/// Write `label: ` to `w` using Node.js's `console.timeEnd` / +/// `console.timeLog` formatting rules (see Node's `internal/util/debuglog.js` +/// `formatTime`): `ms` below one second, `s` below one minute, then +/// `m:ss.mmm` / `h:mm:ss.mmm` above that. +fn write_timer_label_and_duration(w: &mut bun_core::io::Writer, label: &[u8], ms: f64) { + const SECOND: f64 = 1_000.0; + const MINUTE: f64 = 60.0 * SECOND; + const HOUR: f64 = 60.0 * MINUTE; + + let _ = w.write_all(label); + let _ = w.write_all(b": "); + + if ms >= MINUTE { + let mut rem = ms; + let hours = if rem >= HOUR { + let h = (rem / HOUR).floor(); + rem -= h * HOUR; + h as u64 + } else { + 0 + }; + let minutes = { + let m = (rem / MINUTE).floor(); + rem -= m * MINUTE; + m as u64 + }; + let seconds = rem / SECOND; + if hours != 0 { + let _ = write!(w, "{hours}:{minutes:02}:{seconds:06.3} (h:mm:ss.mmm)"); + } else { + let _ = write!(w, "{minutes}:{seconds:06.3} (m:ss.mmm)"); + } + } else if ms >= SECOND { + let _ = write!(w, "{:.3}s", ms / SECOND); + } else { + // Node: `Number(ms.toFixed(3))` — round to three decimals, then print + // with JS number formatting (trailing zeros stripped). + let rounded = (ms * 1000.0).round() / 1000.0; + let _ = write!(w, "{}ms", bun_core::fmt::double(rounded)); + } +} + #[unsafe(no_mangle)] #[crate::host_call] pub extern "C" fn Bun__ConsoleObject__time( @@ -5949,7 +5991,7 @@ pub extern "C" fn Bun__ConsoleObject__time( #[crate::host_call] pub extern "C" fn Bun__ConsoleObject__timeEnd( _console: *mut ConsoleObject, - _global: &JSGlobalObject, + global: &JSGlobalObject, chars: *const u8, len: usize, ) { @@ -5967,15 +6009,15 @@ pub extern "C" fn Bun__ConsoleObject__timeEnd( }; let Some(value) = prev else { return }; // get the duration in microseconds, then display it in milliseconds - Output::print_elapsed( - (value.read() / bun_core::time::NS_PER_US) as f64 / bun_core::time::US_PER_MS as f64, - ); - match len { - 0 => Output::print_errorln(format_args!("")), - _ => Output::print_errorln(format_args!(" {}", bstr::BStr::new(slice))), - } + let elapsed_ms = + (value.read() / bun_core::time::NS_PER_US) as f64 / bun_core::time::US_PER_MS as f64; - Output::flush(); + // SAFETY: top-level JS-thread host call ⇒ exclusive access to the + // set-once `VirtualMachine.console` box. + let writer = unsafe { vm_console_mut(global) }.writer(); + write_timer_label_and_duration(writer, slice, elapsed_ms); + let _ = writer.write_all(b"\n"); + let _ = writer.flush(); } #[unsafe(no_mangle)] @@ -5999,14 +6041,16 @@ pub extern "C" fn Bun__ConsoleObject__timeLog( return; }; // get the duration in microseconds, then display it in milliseconds - Output::print_elapsed( - (value.read() / bun_core::time::NS_PER_US) as f64 / bun_core::time::US_PER_MS as f64, - ); - match len { - 0 => {} - _ => Output::print_error(format_args!(" {}", bstr::BStr::new(slice))), - } - Output::flush(); + let elapsed_ms = + (value.read() / bun_core::time::NS_PER_US) as f64 / bun_core::time::US_PER_MS as f64; + + let console = vm_console(global); + // SAFETY: see [`vm_console`] — points at the live boxed `ConsoleObject` for + // this VM; JS-thread-only. Kept as a raw deref (not `vm_console_mut`) so the + // resulting `writer` borrow does not pin a long-lived `&mut ConsoleObject` + // across the `fmt.format(...)` calls below, which can re-enter JS. + let mut writer = unsafe { (*console).writer() }; + write_timer_label_and_duration(writer, slice, elapsed_ms); // print the arguments // `Formatter` has a `Drop` impl, so struct-update from a @@ -6017,19 +6061,14 @@ pub extern "C" fn Bun__ConsoleObject__timeLog( .unwrap_or(DEFAULT_CONSOLE_LOG_DEPTH); fmt.stack_check = StackCheck::init(); fmt.can_throw_stack_overflow = true; - let console = vm_console(global); - // SAFETY: see [`vm_console`] — points at the live boxed `ConsoleObject` for - // this VM; JS-thread-only. Kept as a raw deref (not `vm_console_mut`) so the - // resulting `writer` borrow does not pin a long-lived `&mut ConsoleObject` - // across the `fmt.format(...)` calls below, which can re-enter JS. - let mut writer = unsafe { (*console).error_writer() }; + let enable_colors = Output::enable_ansi_colors_stdout(); // SAFETY: caller passes a valid (args, args_len) pair. for &arg in unsafe { bun_core::ffi::slice(args, args_len) } { let Ok(tag) = formatter::Tag::get(arg, global) else { return; }; let _ = bun_io::Write::write_all(&mut writer, b" "); - if Output::enable_ansi_colors_stderr() { + if enable_colors { let _ = fmt.format::(tag, &mut writer, arg, global); } else { let _ = fmt.format::(tag, &mut writer, arg, global); diff --git a/test/js/web/console/console-timeLog.expected.txt b/test/js/web/console/console-timeLog.expected.txt index 464475e83a60..83b196cf8c72 100644 --- a/test/js/web/console/console-timeLog.expected.txt +++ b/test/js/web/console/console-timeLog.expected.txt @@ -1,18 +1,18 @@ -[0.00ms] label -[0.06ms] label Hello World! -[0.09ms] label a %s b c d -[0.11ms] label 0 -0 123 -123 123.567 -123.567 Infinity -Infinity -[0.14ms] label true false -[0.15ms] label null undefined -[0.17ms] label Symbol(Symbol Description) -[0.22ms] label 2000-06-27T02:24:34.304Z -[0.29ms] label [ 123, 456, 789 ] -[0.34ms] label { +label: 0.00ms +label: 0.06ms Hello World! +label: 0.09ms a %s b c d +label: 0.11ms 0 -0 123 -123 123.567 -123.567 Infinity -Infinity +label: 0.14ms true false +label: 0.15ms null undefined +label: 0.17ms Symbol(Symbol Description) +label: 0.22ms 2000-06-27T02:24:34.304Z +label: 0.29ms [ 123, 456, 789 ] +label: 0.34ms { name: "foo", } -[0.37ms] label { +label: 0.37ms { a: 123, b: 456, c: 789, } -[0.39ms] label +label: 0.39ms diff --git a/test/js/web/console/console-timeLog.test.ts b/test/js/web/console/console-timeLog.test.ts index bf7ddc485e5b..7c3dd651d524 100644 --- a/test/js/web/console/console-timeLog.test.ts +++ b/test/js/web/console/console-timeLog.test.ts @@ -1,8 +1,28 @@ import { file, spawn } from "bun"; -import { expect, it } from "bun:test"; +import { describe, expect, it } from "bun:test"; import { bunEnv, bunExe } from "harness"; import { join } from "node:path"; +// Matches Node.js: `label: 0.123ms`, `label: 1.234s`, `label: 1:02.345 (m:ss.mmm)`, ... +const DURATION = /(?:[\d.]+ms|[\d.]+s|[\d:.]+ \((?:h:mm|m):ss\.mmm\))/; + +it.concurrent("console.time/timeLog/timeEnd write to stdout, not stderr", async () => { + await using proc = Bun.spawn({ + cmd: [bunExe(), "-e", `console.time("t"); console.timeLog("t", "x"); console.timeEnd("t");`], + env: bunEnv, + stdout: "pipe", + stderr: "pipe", + }); + const [stdout, stderr, exitCode] = await Promise.all([proc.stdout.text(), proc.stderr.text(), proc.exited]); + expect(stderr).toBe(""); + expect(stdout.split("\n")).toEqual([ + expect.stringMatching(new RegExp(String.raw`^t: ${DURATION.source} x$`)), + expect.stringMatching(new RegExp(String.raw`^t: ${DURATION.source}$`)), + "", + ]); + expect(exitCode).toBe(0); +}); + it.concurrent("console.timeEnd with empty label emits exactly one trailing newline", async () => { await using proc = Bun.spawn({ cmd: [bunExe(), "-e", `console.time(""); console.timeEnd("");`], @@ -11,8 +31,8 @@ it.concurrent("console.timeEnd with empty label emits exactly one trailing newli stderr: "pipe", }); const [stdout, stderr, exitCode] = await Promise.all([proc.stdout.text(), proc.stderr.text(), proc.exited]); - expect(stdout).toBe(""); - expect(stderr).toMatch(/^\[[\d.]+[mnµ]?s\]\n$/); + expect(stderr).toBe(""); + expect(stdout).toMatch(new RegExp(String.raw`^: ${DURATION.source}\n$`)); expect(exitCode).toBe(0); }); @@ -24,25 +44,103 @@ it.concurrent("console.timeEnd with non-empty label emits exactly one trailing n stderr: "pipe", }); const [stdout, stderr, exitCode] = await Promise.all([proc.stdout.text(), proc.stderr.text(), proc.exited]); - expect(stdout).toBe(""); - expect(stderr).toMatch(/^\[[\d.]+[mnµ]?s\] abc\n$/); + expect(stderr).toBe(""); + expect(stdout).toMatch(new RegExp(String.raw`^abc: ${DURATION.source}\n$`)); + expect(exitCode).toBe(0); +}); + +it.concurrent("console.timeEnd prints ms below one second", async () => { + await using proc = Bun.spawn({ + cmd: [bunExe(), "-e", `console.time("fast"); console.timeEnd("fast");`], + env: bunEnv, + stdout: "pipe", + stderr: "pipe", + }); + const [stdout, stderr, exitCode] = await Promise.all([proc.stdout.text(), proc.stderr.text(), proc.exited]); + expect(stderr).toBe(""); + expect(stdout).toMatch(/^fast: \d+(?:\.\d{1,3})?ms\n$/); expect(exitCode).toBe(0); }); +it.concurrent("console.timeEnd scales to seconds at >=1000ms", async () => { + await using proc = Bun.spawn({ + cmd: [ + bunExe(), + "-e", + // Busy-wait just past one second so the elapsed time is >= 1000 ms. + `console.time("sc"); const t0=Date.now(); while (Date.now()-t0 < 1100) {} console.timeEnd("sc");`, + ], + env: bunEnv, + stdout: "pipe", + stderr: "pipe", + }); + const [stdout, stderr, exitCode] = await Promise.all([proc.stdout.text(), proc.stderr.text(), proc.exited]); + expect(stderr).toBe(""); + expect(stdout).toMatch(/^sc: \d+\.\d{3}s\n$/); + expect(exitCode).toBe(0); +}); + +it.concurrent("console.timeEnd uses the default label when none is given", async () => { + await using proc = Bun.spawn({ + cmd: [bunExe(), "-e", `console.time(); console.timeEnd();`], + env: bunEnv, + stdout: "pipe", + stderr: "pipe", + }); + const [stdout, stderr, exitCode] = await Promise.all([proc.stdout.text(), proc.stderr.text(), proc.exited]); + expect(stderr).toBe(""); + expect(stdout).toMatch(new RegExp(String.raw`^default: ${DURATION.source}\n$`)); + expect(exitCode).toBe(0); +}); + +describe("duplicate / unknown labels", () => { + it.concurrent("console.time on an existing label keeps the original timer", async () => { + await using proc = Bun.spawn({ + cmd: [ + bunExe(), + "-e", + `console.time("d"); const t0=Date.now(); while (Date.now()-t0 < 1100) {} console.time("d"); console.timeEnd("d");`, + ], + env: bunEnv, + stdout: "pipe", + stderr: "pipe", + }); + const [stdout, stderr, exitCode] = await Promise.all([proc.stdout.text(), proc.stderr.text(), proc.exited]); + // Node emits a warning on duplicate console.time; Bun currently does not. + // Either way the original timer must be kept, so the duration is >= 1s. + expect(stdout).toMatch(/^d: \d+\.\d{3}s\n$/); + expect(exitCode).toBe(0); + }); + + it.concurrent("console.timeEnd / timeLog on an unknown label produce no stdout", async () => { + await using proc = Bun.spawn({ + cmd: [bunExe(), "-e", `console.timeLog("nope"); console.timeEnd("nope");`], + env: bunEnv, + stdout: "pipe", + stderr: "pipe", + }); + const [stdout, , exitCode] = await Promise.all([proc.stdout.text(), proc.stderr.text(), proc.exited]); + expect(stdout).toBe(""); + expect(exitCode).toBe(0); + }); +}); + it("should log to console correctly", async () => { - const { stderr, exited } = spawn({ + const { stdout, stderr, exited } = spawn({ cmd: [bunExe(), join(import.meta.dir, "console-timeLog.js")], stdin: null, stdout: "pipe", stderr: "pipe", env: bunEnv, }); - expect(await exited).toBe(0); - const outText = await stderr.text(); + const [outText, errText, exitCode] = await Promise.all([stdout.text(), stderr.text(), exited]); + expect(errText).toBe(""); const expectedText = (await file(join(import.meta.dir, "console-timeLog.expected.txt")).text()).replaceAll( "\r\n", "\n", ); - expect(outText.replace(/^\[.+?s\] /gm, "")).toBe(expectedText.replace(/^\[.+?s\] /gm, "")); + const normalize = (s: string) => s.replace(new RegExp(String.raw`^(.*?): ${DURATION.source}`, "gm"), "$1: