From f8a07b31e47bd976770b747e7e63d5efeeabd7e3 Mon Sep 17 00:00:00 2001 From: robobun <117481402+robobun@users.noreply.github.com> Date: Fri, 14 Aug 2026 11:41:26 +0000 Subject: [PATCH] perf_hooks: record nodeTiming milestones and resolve their names in User Timing performance.nodeTiming reported timeOrigin (an epoch timestamp) for every startup milestone, and performance.measure() could not reference the milestone names because the native User Timing code only knew user marks. The VM now stamps nodeStart, v8Start, environment, bootstrapComplete, loopStart and loopExit relative to origin_timer, exposed through Bun__getNodeTimingMilestone. PerformanceUserTiming gets back WebKit's restricted-mark-name table, pointed at those milestones: measure() resolves the six names to the milestone values, while mark(), new PerformanceMark() and clearMarks() reject them with ERR_INVALID_ARG_VALUE like Node. perf_hooks' nodeTiming reads the same values through own accessor properties, matching Node's object shape. Co-authored-by: Ciro Spaciari --- src/js/node/perf_hooks.ts | 98 +++++--- src/jsc/JSErrorCode.rs | 2 + src/jsc/VirtualMachine.rs | 79 ++++++ src/jsc/bindings/ExceptionCode.h | 2 + src/jsc/bindings/JSDOMExceptionHandling.cpp | 3 + src/jsc/bindings/webcore/JSPerformance.cpp | 13 + src/jsc/bindings/webcore/JSPerformance.h | 3 + src/jsc/bindings/webcore/Performance.cpp | 4 +- src/jsc/bindings/webcore/Performance.h | 2 +- src/jsc/bindings/webcore/PerformanceMark.cpp | 3 + .../webcore/PerformanceUserTiming.cpp | 43 +++- .../bindings/webcore/PerformanceUserTiming.h | 13 +- src/jsc/virtual_machine_exports.rs | 10 + test/js/node/perf_hooks/perf_hooks.test.ts | 234 +++++++++++++++++- .../parallel/test-performance-nodetiming.js | 46 ++++ 15 files changed, 512 insertions(+), 43 deletions(-) create mode 100644 test/js/node/test/parallel/test-performance-nodetiming.js diff --git a/src/js/node/perf_hooks.ts b/src/js/node/perf_hooks.ts index 858b4df289f2..8e24b131ae3e 100644 --- a/src/js/node/perf_hooks.ts +++ b/src/js/node/perf_hooks.ts @@ -59,31 +59,64 @@ var constants = { NODE_PERFORMANCE_MILESTONE_V8_START: 4, }; -// PerformanceEntry is not a valid constructor, so we have to fake it. -class PerformanceNodeTiming { - bootstrapComplete: number = 0; - environment: number = 0; - idleTime: number = 0; - loopExit: number = 0; - loopStart: number = 0; - nodeStart: number = 0; - v8Start: number = 0; - - // we have to fake the properties since it's not real - get name() { - return "node"; - } - - get entryType() { - return "node"; - } +// Milliseconds since timeOrigin, or -1 until the milestone is reached. Same +// table performance.measure() resolves these names against. +const getNodeTimingMilestone = $newCppFunction("JSPerformance.cpp", "jsPerformance_getNodeTimingMilestone", 1) as ( + name: string, +) => number; - get startTime() { - return this.nodeStart; - } +function milestoneDescriptor(name: string): PropertyDescriptor { + return { + __proto__: null, + enumerable: true, + configurable: true, + get() { + return getNodeTimingMilestone(name); + }, + }; +} - get duration() { - return performance.now(); +// Ported from node's lib/internal/perf/nodetiming.js: every property is an own +// enumerable slot (so `{ ...performance.nodeTiming }` copies them), and the +// milestones are getters because loopStart/loopExit are stamped after this +// module has loaded. PerformanceEntry is not constructible, so the prototype +// chain is linked below instead of with `extends`. +class PerformanceNodeTiming { + declare readonly name: string; + declare readonly entryType: string; + declare readonly startTime: number; + declare readonly duration: number; + declare readonly nodeStart: number; + declare readonly v8Start: number; + declare readonly environment: number; + declare readonly loopStart: number; + declare readonly loopExit: number; + declare readonly bootstrapComplete: number; + declare readonly idleTime: number; + + constructor() { + Object.defineProperties(this, { + name: { __proto__: null, enumerable: true, configurable: true, value: "node" }, + entryType: { __proto__: null, enumerable: true, configurable: true, value: "node" }, + startTime: { __proto__: null, enumerable: true, configurable: true, value: 0 }, + duration: { + __proto__: null, + enumerable: true, + configurable: true, + get() { + return performance.now(); + }, + }, + nodeStart: milestoneDescriptor("nodeStart"), + v8Start: milestoneDescriptor("v8Start"), + environment: milestoneDescriptor("environment"), + loopStart: milestoneDescriptor("loopStart"), + loopExit: milestoneDescriptor("loopExit"), + bootstrapComplete: milestoneDescriptor("bootstrapComplete"), + // Bun does not track time parked in the poll, matching the zeros + // eventLoopUtilization() reports. + idleTime: { __proto__: null, enumerable: true, configurable: true, value: 0 }, + }); } toJSON() { @@ -92,13 +125,13 @@ class PerformanceNodeTiming { entryType: this.entryType, startTime: this.startTime, duration: this.duration, + nodeStart: this.nodeStart, + v8Start: this.v8Start, bootstrapComplete: this.bootstrapComplete, environment: this.environment, - idleTime: this.idleTime, - loopExit: this.loopExit, loopStart: this.loopStart, - nodeStart: this.nodeStart, - v8Start: this.v8Start, + loopExit: this.loopExit, + idleTime: this.idleTime, }; } } @@ -107,15 +140,6 @@ if (PerformanceEntry) { Object.setPrototypeOf(PerformanceNodeTiming, PerformanceEntry); } -function createPerformanceNodeTiming() { - const object = Object.create(PerformanceNodeTiming.prototype); - - object.bootstrapComplete = object.environment = object.nodeStart = object.v8Start = performance.timeOrigin; - object.loopStart = object.idleTime = 1; - object.loopExit = -1; - return object; -} - function eventLoopUtilization(_utilization1, _utilization2) { return { idle: 0, @@ -320,7 +344,7 @@ function processTimerifyComplete(name, start, args, histogram) { } } -const nodeTiming = createPerformanceNodeTiming(); +const nodeTiming = new PerformanceNodeTiming(); // Node augments the real `performance` object (not a forwarding shim), so // timerify/eventLoopUtilization/nodeTiming go on Performance.prototype, diff --git a/src/jsc/JSErrorCode.rs b/src/jsc/JSErrorCode.rs index ae18b10990dd..bfec2e2bef38 100644 --- a/src/jsc/JSErrorCode.rs +++ b/src/jsc/JSErrorCode.rs @@ -68,4 +68,6 @@ pub enum DOMExceptionCode { InvalidThisError, InvalidURLError, CryptoOperationFailedError, + EventRecursion, + InvalidArgValueError, } diff --git a/src/jsc/VirtualMachine.rs b/src/jsc/VirtualMachine.rs index ca925367b68a..5b22c727f6c0 100644 --- a/src/jsc/VirtualMachine.rs +++ b/src/jsc/VirtualMachine.rs @@ -133,6 +133,32 @@ impl Default for InitOptions { } } +/// The `performance.nodeTiming` milestones, stamped at Bun's equivalent of each +/// Node startup phase. The discriminants index +/// [`VirtualMachine::node_timing_milestones`] and are shared with the name +/// table in `src/jsc/bindings/webcore/PerformanceUserTiming.cpp`. +#[derive(Clone, Copy)] +#[repr(u32)] +pub(crate) enum NodeTimingMilestone { + /// The runtime started building this VM (a hair after `timeOrigin`). + NodeStart = 0, + /// Bun's own per-VM state exists; the JavaScriptCore VM is about to be created. + V8Start = 1, + /// The JSC VM and global object exist (`init` is done). + Environment = 2, + /// Pre-execution bootstrap is done; preloads and the entry point are about to run. + BootstrapComplete = 3, + /// The event loop polled for the first time, i.e. the entry point's + /// synchronous evaluation (and its microtasks) finished. + LoopStart = 4, + /// The event loop drained and 'exit' is about to be emitted. + LoopExit = 5, +} + +impl NodeTimingMilestone { + pub(crate) const COUNT: usize = 6; +} + pub struct VirtualMachine { pub global: *mut JSGlobalObject, // allocator dropped per §Allocators (global mimalloc) @@ -281,6 +307,9 @@ pub struct VirtualMachine { pub origin_timer: std::time::Instant, pub(crate) origin_timestamp: u64, + /// Nanoseconds since `origin_timer` at which each [`NodeTimingMilestone`] + /// was reached; `-1` until it is. Read by `Bun__getNodeTimingMilestone`. + pub(crate) node_timing_milestones: [i64; NodeTimingMilestone::COUNT], /// For fake timers: override performance.now() with a specific value (in nanoseconds). pub overridden_performance_now: Option, pub(crate) macro_event_loop: EventLoop, @@ -1590,6 +1619,9 @@ impl VirtualMachine { self.exit_on_uncaught_exception = true; return; } + // A script with no async work never polled the loop; Node still + // reports it as having started (and, below, exited) around now. + self.record_node_timing_milestone(NodeTimingMilestone::LoopStart); ExitHandler::dispatch_on_before_exit(self); let mut dispatch = false; loop { @@ -1613,6 +1645,11 @@ impl VirtualMachine { break; } + // Only a cleanly drained loop stamps this: `process.exit()` and a + // fatal exception leave it at -1 for the 'exit' listeners, as in Node. + if self.unhandled_error_counter == 0 { + self.record_node_timing_milestone(NodeTimingMilestone::LoopExit); + } } pub fn on_exit(&mut self) { @@ -2443,6 +2480,8 @@ impl VirtualMachine { .write(VirtualMachine::default_on_unhandled_rejection); addr_of_mut!((*vm).origin_timer).write(std::time::Instant::now()); addr_of_mut!((*vm).origin_timestamp).write(get_origin_timestamp()); + addr_of_mut!((*vm).node_timing_milestones).write([-1; NodeTimingMilestone::COUNT]); + Self::record_node_timing_milestone_raw(vm, NodeTimingMilestone::NodeStart); addr_of_mut!((*vm).smol).write(opts.smol); // `Option<{CPU,Heap}ProfilerConfig>` are NOT zero-valid: each // payload contains a `bool`, and rustc picks that field's invalid @@ -2523,6 +2562,10 @@ impl VirtualMachine { unsafe { (*vm).runtime_state = (hooks.init_runtime_state)(vm, &mut opts)? }; } + // SAFETY: `origin_timer` and `node_timing_milestones` were written in + // the block above. + unsafe { Self::record_node_timing_milestone_raw(vm, NodeTimingMilestone::V8Start) }; + // JSGlobalObject creation. `ensure_waker()` must run before the FFI. // SAFETY: `vm` is the unique live VM on this thread; raw-ptr deref so // no `&mut` is held across the FFI re-entry (`Bun__getVM()` — @@ -2579,6 +2622,9 @@ impl VirtualMachine { IS_SMOL_MODE.store(true, core::sync::atomic::Ordering::Relaxed); } + // SAFETY: see the `V8Start` stamp above. + unsafe { Self::record_node_timing_milestone_raw(vm, NodeTimingMilestone::Environment) }; + Ok(vm) } @@ -2610,10 +2656,40 @@ impl VirtualMachine { self.event_loop_mut().wait_for_promise(promise) } + /// First write wins: `LoopStart` is recorded on every tick and + /// `BootstrapComplete` on every hot reload, and both mean the first time. + /// + /// # Safety + /// `(*vm).origin_timer` and `(*vm).node_timing_milestones` must be + /// initialized. Nothing else is touched and no `&mut VirtualMachine` is + /// formed, which lets [`init`](Self::init) stamp a partially built VM (see + /// the validity note there). + unsafe fn record_node_timing_milestone_raw( + vm: *mut VirtualMachine, + milestone: NodeTimingMilestone, + ) { + // SAFETY: per the contract above; only the two fields are projected. + unsafe { + let slots = core::ptr::addr_of_mut!((*vm).node_timing_milestones); + if (*slots)[milestone as usize] >= 0 { + return; + } + let elapsed = (*core::ptr::addr_of!((*vm).origin_timer)).elapsed(); + (*slots)[milestone as usize] = elapsed.as_nanos() as i64; + } + } + + #[inline] + pub(crate) fn record_node_timing_milestone(&mut self, milestone: NodeTimingMilestone) { + // SAFETY: a `&mut self` is a fully initialized VM. + unsafe { Self::record_node_timing_milestone_raw(self, milestone) } + } + /// `eventLoop().autoTick()` — dispatched through the runtime hook /// (needs `Timer::All` for the poll timeout). #[inline] pub fn auto_tick(&mut self) { + self.record_node_timing_milestone(NodeTimingMilestone::LoopStart); if let Some(hooks) = runtime_hooks() { // SAFETY: hook contract — `self` is the live per-thread VM. unsafe { (hooks.auto_tick)(self) }; @@ -2631,6 +2707,7 @@ impl VirtualMachine { /// `on_before_exit` / `bun_main` still make forward progress. #[inline] pub fn auto_tick_active(&mut self) { + self.record_node_timing_milestone(NodeTimingMilestone::LoopStart); if let Some(hooks) = runtime_hooks() { // SAFETY: `self` is the live per-thread VM (hook contract). unsafe { (hooks.auto_tick_active)(self) }; @@ -2692,6 +2769,7 @@ impl VirtualMachine { // evaluating `internal/process/pre_execution`. crate::cpp::Bun__preExecutionBootstrap(self.global()); } + self.record_node_timing_milestone(NodeTimingMilestone::BootstrapComplete); if !self.main_is_html_entrypoint { if let Some(hooks) = hooks { @@ -4821,6 +4899,7 @@ impl VirtualMachine { self.event_loop_mut().ensure_waker(); let _ = self.ensure_debugger(true); + self.record_node_timing_milestone(NodeTimingMilestone::BootstrapComplete); if !self.transpiler.options.disable_transpilation { if let Some(hooks) = runtime_hooks() { diff --git a/src/jsc/bindings/ExceptionCode.h b/src/jsc/bindings/ExceptionCode.h index 6772e376a6ec..87cd2c6ddbd8 100644 --- a/src/jsc/bindings/ExceptionCode.h +++ b/src/jsc/bindings/ExceptionCode.h @@ -78,6 +78,8 @@ enum ExceptionCode : uint8_t { InvalidURLError, CryptoOperationFailedError, EVENT_RECURSION, + // ERR_INVALID_ARG_VALUE with the message supplied by the thrower. + InvalidArgValueError, }; } // namespace WebCore diff --git a/src/jsc/bindings/JSDOMExceptionHandling.cpp b/src/jsc/bindings/JSDOMExceptionHandling.cpp index 9db6f0f283de..4721ae93fe04 100644 --- a/src/jsc/bindings/JSDOMExceptionHandling.cpp +++ b/src/jsc/bindings/JSDOMExceptionHandling.cpp @@ -175,6 +175,9 @@ JSValue createDOMException(JSGlobalObject* lexicalGlobalObject, ExceptionCode ec case ExceptionCode::EVENT_RECURSION: return Bun::createError(lexicalGlobalObject, Bun::ErrorCode::ERR_EVENT_RECURSION, message); + case ExceptionCode::InvalidArgValueError: + return Bun::createError(lexicalGlobalObject, Bun::ErrorCode::ERR_INVALID_ARG_VALUE, message); + default: { // FIXME: All callers to createDOMException need to pass in the correct global object. // For now, we're going to assume the lexicalGlobalObject. Which is wrong in cases like this: diff --git a/src/jsc/bindings/webcore/JSPerformance.cpp b/src/jsc/bindings/webcore/JSPerformance.cpp index 32e439b725b7..95400bc009ce 100644 --- a/src/jsc/bindings/webcore/JSPerformance.cpp +++ b/src/jsc/bindings/webcore/JSPerformance.cpp @@ -51,6 +51,7 @@ #include "JSPerformanceMeasureOptions.h" // #include "JSPerformanceNavigation.h" #include "JSPerformanceTiming.h" +#include "PerformanceUserTiming.h" #include "ScriptExecutionContext.h" #include "WebCoreJSClientData.h" @@ -140,6 +141,18 @@ JSC_DEFINE_HOST_FUNCTION(jsPerformancePrototypeFunction_markResourceTiming, (JSG return JSValue::encode(jsUndefined()); } +JSC_DEFINE_HOST_FUNCTION(jsPerformance_getNodeTimingMilestone, (JSGlobalObject * globalObject, JSC::CallFrame* callFrame)) +{ + auto& vm = JSC::getVM(globalObject); + auto scope = DECLARE_THROW_SCOPE(vm); + auto name = callFrame->argument(0).toWTFString(globalObject); + RETURN_IF_EXCEPTION(scope, {}); + auto milestone = PerformanceUserTiming::nodeTimingMilestone(vm, name); + if (!milestone) + return JSValue::encode(jsUndefined()); + return JSValue::encode(jsNumber(*milestone)); +} + // -- end copied -- class JSPerformancePrototype final : public JSC::JSNonFinalObject { diff --git a/src/jsc/bindings/webcore/JSPerformance.h b/src/jsc/bindings/webcore/JSPerformance.h index 0cbb94095963..eab4f79d1f4b 100644 --- a/src/jsc/bindings/webcore/JSPerformance.h +++ b/src/jsc/bindings/webcore/JSPerformance.h @@ -100,4 +100,7 @@ template<> struct JSDOMWrapperConverterTraits { using ToWrappedReturnType = Performance*; }; +// (milestoneName) => the value performance.nodeTiming reports for it; backs node/perf_hooks.ts. +JSC_DECLARE_HOST_FUNCTION(jsPerformance_getNodeTimingMilestone); + } // namespace WebCore diff --git a/src/jsc/bindings/webcore/Performance.cpp b/src/jsc/bindings/webcore/Performance.cpp index 0fc725039d55..3dcb4b9ab976 100644 --- a/src/jsc/bindings/webcore/Performance.cpp +++ b/src/jsc/bindings/webcore/Performance.cpp @@ -221,11 +221,11 @@ ExceptionOr> Performance::mark(JSC::JSGlobalObject& globalO return mark.releaseReturnValue(); } -void Performance::clearMarks(const String& markName) +ExceptionOr Performance::clearMarks(const String& markName) { if (!m_userTiming) m_userTiming = makeUnique(*this); - m_userTiming->clearMarks(markName); + return m_userTiming->clearMarks(markName); } ExceptionOr> Performance::measure(JSC::JSGlobalObject& globalObject, const String& measureName, std::optional&& startOrMeasureOptions, const String& endMark) diff --git a/src/jsc/bindings/webcore/Performance.h b/src/jsc/bindings/webcore/Performance.h index d6149dc59496..ff8b07506116 100644 --- a/src/jsc/bindings/webcore/Performance.h +++ b/src/jsc/bindings/webcore/Performance.h @@ -95,7 +95,7 @@ class Performance final : public RefCounted, public ContextDestruct void setResourceTimingBufferSize(unsigned); ExceptionOr> mark(JSC::JSGlobalObject&, const String& markName, std::optional&&); - void clearMarks(const String& markName); + ExceptionOr clearMarks(const String& markName); using StartOrMeasureOptions = std::variant; ExceptionOr> measure(JSC::JSGlobalObject&, const String& measureName, std::optional&&, const String& endMark); diff --git a/src/jsc/bindings/webcore/PerformanceMark.cpp b/src/jsc/bindings/webcore/PerformanceMark.cpp index 6ddda4c5f8b9..9d118ec54d0f 100644 --- a/src/jsc/bindings/webcore/PerformanceMark.cpp +++ b/src/jsc/bindings/webcore/PerformanceMark.cpp @@ -46,6 +46,9 @@ static double performanceNow(ScriptExecutionContext& scriptExecutionContext) ExceptionOr> PerformanceMark::create(JSC::JSGlobalObject& globalObject, ScriptExecutionContext& scriptExecutionContext, const String& name, std::optional&& markOptions) { + if (PerformanceUserTiming::isRestrictedMarkName(name)) + return PerformanceUserTiming::restrictedMarkNameException(name); + double startTime; JSC::JSValue detail; if (markOptions) { diff --git a/src/jsc/bindings/webcore/PerformanceUserTiming.cpp b/src/jsc/bindings/webcore/PerformanceUserTiming.cpp index 3bca2b85001f..4bb4a528e3f3 100644 --- a/src/jsc/bindings/webcore/PerformanceUserTiming.cpp +++ b/src/jsc/bindings/webcore/PerformanceUserTiming.cpp @@ -27,19 +27,53 @@ #include "config.h" #include "PerformanceUserTiming.h" +#include "BunClientData.h" #include "MessagePort.h" #include "PerformanceMarkOptions.h" #include "PerformanceMeasureOptions.h" #include "SerializedScriptValue.h" #include +#include + +// Defined in src/jsc/virtual_machine_exports.rs. +extern "C" double Bun__getNodeTimingMilestone(void* bunVM, uint32_t milestone); namespace WebCore { +// Values are `NodeTimingMilestone` discriminants from src/jsc/VirtualMachine.rs. +static constexpr SortedArrayMap nodeTimingMilestoneIndices { std::to_array>({ + { "bootstrapComplete"_s, 3 }, + { "environment"_s, 2 }, + { "loopExit"_s, 5 }, + { "loopStart"_s, 4 }, + { "nodeStart"_s, 0 }, + { "v8Start"_s, 1 }, +}) }; + PerformanceUserTiming::PerformanceUserTiming(Performance& performance) : m_performance(performance) { } +bool PerformanceUserTiming::isRestrictedMarkName(const String& markName) +{ + return nodeTimingMilestoneIndices.contains(markName); +} + +Exception PerformanceUserTiming::restrictedMarkNameException(const String& markName) +{ + // lib/internal/perf/usertiming.js: `throw new ERR_INVALID_ARG_VALUE('name', name)`. + return Exception { InvalidArgValueError, makeString("The argument 'name' is invalid. Received '"_s, markName, '\'') }; +} + +std::optional PerformanceUserTiming::nodeTimingMilestone(JSC::VM& vm, const String& name) +{ + auto* index = nodeTimingMilestoneIndices.tryGet(name); + if (!index) + return std::nullopt; + return Bun__getNodeTimingMilestone(bunVM(vm), *index); +} + size_t PerformanceUserTiming::memoryCost() const { size_t size = sizeof(PerformanceUserTiming); @@ -96,10 +130,13 @@ ExceptionOr> PerformanceUserTiming::mark(JSC::JSGlobalObjec return mark.releaseReturnValue(); } -void PerformanceUserTiming::clearMarks(const String& markName) +ExceptionOr PerformanceUserTiming::clearMarks(const String& markName) { + if (isRestrictedMarkName(markName)) + return restrictedMarkNameException(markName); clearPerformanceEntries(m_marksMap, markName); m_markCounter = 0; + return {}; } ExceptionOr PerformanceUserTiming::convertMarkToTimestamp(const std::variant& mark) const @@ -112,6 +149,10 @@ ExceptionOr PerformanceUserTiming::convertMarkToTimestamp(const std::var ExceptionOr PerformanceUserTiming::convertMarkToTimestamp(const String& mark) const { + // Node hands back the milestone even while it is still -1 (loopStart before the loop runs). + if (auto milestone = nodeTimingMilestone(m_performance.scriptExecutionContext()->vm(), mark)) + return *milestone; + auto iterator = m_marksMap.find(mark); if (iterator != m_marksMap.end()) return iterator->value.last()->startTime(); diff --git a/src/jsc/bindings/webcore/PerformanceUserTiming.h b/src/jsc/bindings/webcore/PerformanceUserTiming.h index f99913bc52c1..9c090c9bddbc 100644 --- a/src/jsc/bindings/webcore/PerformanceUserTiming.h +++ b/src/jsc/bindings/webcore/PerformanceUserTiming.h @@ -33,6 +33,7 @@ namespace JSC { class JSGlobalObject; +class VM; } namespace WebCore { @@ -47,8 +48,18 @@ class PerformanceUserTiming { public: explicit PerformanceUserTiming(Performance&); + // Node reserves the PerformanceNodeTiming milestone names (nodeStart, v8Start, environment, + // loopStart, loopExit, bootstrapComplete): mark() and clearMarks() reject them, and measure() + // resolves them to performance.nodeTiming's values. Upstream WebKit does the same with the + // PerformanceTiming attribute names. + static bool isRestrictedMarkName(const String&); + static Exception restrictedMarkNameException(const String&); + // The milestone's value as performance.nodeTiming reports it (ms since timeOrigin, -1 until + // reached), or nullopt when `name` is not a milestone. + static std::optional nodeTimingMilestone(JSC::VM&, const String& name); + ExceptionOr> mark(JSC::JSGlobalObject&, const String& markName, std::optional&&); - void clearMarks(const String& markName); + ExceptionOr clearMarks(const String& markName); using StartOrMeasureOptions = std::variant; ExceptionOr> measure(JSC::JSGlobalObject&, const String& measureName, std::optional&&, const String& endMark); diff --git a/src/jsc/virtual_machine_exports.rs b/src/jsc/virtual_machine_exports.rs index c81f5f148d68..2059aeda532b 100644 --- a/src/jsc/virtual_machine_exports.rs +++ b/src/jsc/virtual_machine_exports.rs @@ -57,6 +57,16 @@ pub fn read_origin_timer_start(vm: &VirtualMachine) -> f64 { / 1_000_000.0 } +/// `performance.nodeTiming` milestone `index` (a `NodeTimingMilestone` +/// discriminant) in milliseconds since `timeOrigin`, or -1 until it is reached. +// HOST_EXPORT(Bun__getNodeTimingMilestone, c) +pub fn get_node_timing_milestone(vm: &VirtualMachine, index: u32) -> f64 { + match vm.node_timing_milestones.get(index as usize) { + Some(&nanos) if nanos >= 0 => nanos as f64 / 1_000_000.0, + _ => -1.0, + } +} + // HOST_EXPORT(Bun__VirtualMachine__exitDuringUncaughtException, c) pub fn exit_during_uncaught_exception(this: &mut VirtualMachine) { this.exit_on_uncaught_exception = true; diff --git a/test/js/node/perf_hooks/perf_hooks.test.ts b/test/js/node/perf_hooks/perf_hooks.test.ts index bdf207de7fc5..03570ab359dc 100644 --- a/test/js/node/perf_hooks/perf_hooks.test.ts +++ b/test/js/node/perf_hooks/perf_hooks.test.ts @@ -1,4 +1,4 @@ -import { expect, test } from "bun:test"; +import { describe, expect, test } from "bun:test"; import { bunEnv, bunExe } from "harness"; import net from "net"; import perf, { PerformanceObserver } from "perf_hooks"; @@ -189,3 +189,235 @@ test("net entries are instanceof PerformanceEntry", async () => { expect(entry.constructor.name).toBe("PerformanceNodeEntry"); expect(entry.entryType).toBe("net"); }); + +// performance.nodeTiming reports each startup phase in ms since timeOrigin +// (-1 until reached), and Node reserves the six milestone names in the User +// Timing API: mark()/clearMarks() reject them and measure() resolves them to +// nodeTiming's values. Behaviour verified against Node v26.3.0. +describe("nodeTiming milestones", () => { + const milestones = ["nodeStart", "v8Start", "environment", "bootstrapComplete", "loopStart", "loopExit"] as const; + + function thrown(fn: () => unknown) { + try { + fn(); + } catch (e: any) { + return { isTypeError: e instanceof TypeError, code: e.code, message: e.message }; + } + return "did not throw"; + } + + test("nodeTiming has Node's shape and its values are offsets from timeOrigin", () => { + const nodeTiming = perf.performance.nodeTiming; + expect(nodeTiming).toBeInstanceOf(PerformanceEntry); + expect(Object.keys(nodeTiming)).toEqual([ + "name", + "entryType", + "startTime", + "duration", + "nodeStart", + "v8Start", + "environment", + "loopStart", + "loopExit", + "bootstrapComplete", + "idleTime", + ]); + for (const name of milestones) { + expect(Object.getOwnPropertyDescriptor(nodeTiming, name)).toEqual({ + get: expect.any(Function), + set: undefined, + enumerable: true, + configurable: true, + }); + } + + const { nodeStart, v8Start, environment, bootstrapComplete, loopStart } = nodeTiming; + expect(nodeStart).toBeGreaterThanOrEqual(0); + expect(v8Start).toBeGreaterThan(nodeStart); + expect(environment).toBeGreaterThan(v8Start); + expect(bootstrapComplete).toBeGreaterThan(environment); + expect(bootstrapComplete).toBeLessThanOrEqual(performance.now()); + // The test runner entered the event loop before running this test body, + // and will not leave it until the file is done. + expect(loopStart).toBeGreaterThanOrEqual(0); + expect(nodeTiming.toJSON()).toEqual({ + name: "node", + entryType: "node", + startTime: 0, + duration: expect.any(Number), + nodeStart, + v8Start, + bootstrapComplete, + environment, + loopStart, + loopExit: -1, + idleTime: 0, + }); + expect(nodeTiming.duration).toBeLessThanOrEqual(performance.now()); + }); + + test("measure() resolves the milestone names to nodeTiming's values", () => { + const nodeTiming = perf.performance.nodeTiming; + const timing = (entry: PerformanceMeasure) => ({ startTime: entry.startTime, duration: entry.duration }); + + // Like Node, an unreached milestone (loopExit) resolves to -1 rather than throwing. + for (const name of milestones) { + expect(performance.measure(`since ${name}`, name).startTime).toBe(nodeTiming[name]); + } + expect(timing(performance.measure("boot", "nodeStart", "bootstrapComplete"))).toEqual({ + startTime: nodeTiming.nodeStart, + duration: nodeTiming.bootstrapComplete - nodeTiming.nodeStart, + }); + expect(timing(performance.measure("jsc", { start: "v8Start", end: "environment" }))).toEqual({ + startTime: nodeTiming.v8Start, + duration: nodeTiming.environment - nodeTiming.v8Start, + }); + expect(timing(performance.measure("until bootstrap", undefined, "bootstrapComplete"))).toEqual({ + startTime: 0, + duration: nodeTiming.bootstrapComplete, + }); + const fromStart = performance.measure("after nodeStart", { start: "nodeStart", duration: 5 }); + expect(fromStart.startTime).toBe(nodeTiming.nodeStart); + expect(fromStart.duration).toBeCloseTo(5, 6); + const untilEnd = performance.measure("before bootstrap", { end: "bootstrapComplete", duration: 5 }); + expect(untilEnd.startTime).toBe(nodeTiming.bootstrapComplete - 5); + expect(untilEnd.duration).toBeCloseTo(5, 6); + + // Only marks are looked up this way: a measure may be named after a + // milestone, and unknown mark names still throw. + expect(performance.measure("nodeStart").entryType).toBe("measure"); + expect(() => performance.measure("m", "noSuchMark")).toThrow(); + expect(() => performance.measure("m", { start: "nodeStart", end: "noSuchMark" })).toThrow(); + performance.clearMeasures(); + }); + + test("mark(), new PerformanceMark() and clearMarks() reject the milestone names", () => { + for (const name of milestones) { + const expected = { + isTypeError: true, + code: "ERR_INVALID_ARG_VALUE", + message: `The argument 'name' is invalid. Received '${name}'`, + }; + expect(thrown(() => performance.mark(name))).toEqual(expected); + expect(thrown(() => new PerformanceMark(name))).toEqual(expected); + expect(thrown(() => performance.clearMarks(name))).toEqual(expected); + expect(performance.getEntriesByName(name, "mark")).toEqual([]); + } + // Only the six milestones are reserved; other nodeTiming property names are ordinary marks. + expect(performance.mark("idleTime").entryType).toBe("mark"); + performance.clearMarks("idleTime"); + expect(performance.getEntriesByName("idleTime", "mark")).toEqual([]); + }); + + test.concurrent("loopStart and loopExit follow the main script's lifecycle", async () => { + await using proc = Bun.spawn({ + cmd: [ + bunExe(), + "-e", + `const { performance } = require("perf_hooks"); + const nodeTiming = performance.nodeTiming; + const seen = { topLevel: { loopStart: nodeTiming.loopStart, loopExit: nodeTiming.loopExit } }; + setImmediate(() => { + seen.inLoop = { + loopStartAfterBootstrap: nodeTiming.loopStart >= nodeTiming.bootstrapComplete, + measureStartsAtLoopStart: performance.measure("loop", "loopStart").startTime === nodeTiming.loopStart, + loopExit: nodeTiming.loopExit, + }; + }); + process.on("beforeExit", () => { + seen.beforeExit = { loopExit: nodeTiming.loopExit }; + }); + process.on("exit", () => { + seen.exit = { + loopExitAfterLoopStart: nodeTiming.loopExit >= nodeTiming.loopStart, + measureStartsAtLoopExit: performance.measure("exit", "loopExit").startTime === nodeTiming.loopExit, + }; + console.log(JSON.stringify(seen)); + });`, + ], + 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(JSON.parse(stdout)).toEqual({ + topLevel: { loopStart: -1, loopExit: -1 }, + inLoop: { loopStartAfterBootstrap: true, measureStartsAtLoopStart: true, loopExit: -1 }, + beforeExit: { loopExit: -1 }, + exit: { loopExitAfterLoopStart: true, measureStartsAtLoopExit: true }, + }); + expect(exitCode).toBe(0); + }); + + test.concurrent("process.exit() does not count as the loop exiting", async () => { + await using proc = Bun.spawn({ + cmd: [ + bunExe(), + "-e", + `const { performance } = require("perf_hooks"); + process.on("exit", () => console.log(performance.nodeTiming.loopStart >= 0, performance.nodeTiming.loopExit)); + setImmediate(() => process.exit(0));`, + ], + 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).toBe("true -1\n"); + expect(exitCode).toBe(0); + }); + + test.concurrent("a script with no async work still gets loopStart and loopExit", async () => { + await using proc = Bun.spawn({ + cmd: [ + bunExe(), + "-e", + `const { nodeTiming } = require("perf_hooks").performance; + process.on("beforeExit", () => console.log("beforeExit", nodeTiming.loopStart >= nodeTiming.bootstrapComplete, nodeTiming.loopExit)); + process.on("exit", () => console.log("exit", nodeTiming.loopExit >= nodeTiming.loopStart));`, + ], + 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).toBe("beforeExit true -1\nexit true\n"); + expect(exitCode).toBe(0); + }); + + // Workers boot through the same VM setup, so a worker's performance object + // gets a complete set of milestones of its own. + test.concurrent("worker threads report their own startup milestones", async () => { + await using proc = Bun.spawn({ + cmd: [ + bunExe(), + "-e", + `const { Worker } = require("worker_threads"); + const worker = new Worker( + \`const { parentPort } = require("worker_threads"); + const { performance } = require("perf_hooks"); + const { nodeStart, v8Start, environment, bootstrapComplete } = performance.nodeTiming; + let markRejected; + try { performance.mark("nodeStart"); } catch (e) { markRejected = e.code; } + parentPort.postMessage({ + ordered: 0 <= nodeStart && nodeStart < v8Start && v8Start < environment && environment < bootstrapComplete, + bootMeasure: performance.measure("boot", "nodeStart", "bootstrapComplete").duration === bootstrapComplete - nodeStart, + markRejected, + });\`, + { eval: true }, + ); + worker.on("message", message => console.log(JSON.stringify(message)));`, + ], + 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(JSON.parse(stdout)).toEqual({ ordered: true, bootMeasure: true, markRejected: "ERR_INVALID_ARG_VALUE" }); + expect(exitCode).toBe(0); + }); +}); diff --git a/test/js/node/test/parallel/test-performance-nodetiming.js b/test/js/node/test/parallel/test-performance-nodetiming.js new file mode 100644 index 000000000000..cc76c80a647a --- /dev/null +++ b/test/js/node/test/parallel/test-performance-nodetiming.js @@ -0,0 +1,46 @@ +'use strict'; + +const common = require('../common'); +const assert = require('assert'); +const { performance } = require('perf_hooks'); +const { isMainThread } = require('worker_threads'); + +const { nodeTiming } = performance; +assert.strictEqual(nodeTiming.name, 'node'); +assert.strictEqual(nodeTiming.entryType, 'node'); + +assert.strictEqual(nodeTiming.startTime, 0); +const now = performance.now(); +assert.ok(nodeTiming.duration >= now); + +// Check that the nodeTiming milestone values are in the correct order and greater than 0. +const keys = ['nodeStart', 'v8Start', 'environment', 'bootstrapComplete']; +for (let idx = 0; idx < keys.length; idx++) { + if (idx === 0) { + assert.ok(nodeTiming[keys[idx]] >= 0); + continue; + } + assert.ok(nodeTiming[keys[idx]] > nodeTiming[keys[idx - 1]], `expect nodeTiming['${keys[idx]}'] > nodeTiming['${keys[idx - 1]}']`); +} + +// loop milestones. +assert.strictEqual(nodeTiming.idleTime, 0); +if (isMainThread) { + // Main thread does not start loop until the first tick is finished. + assert.strictEqual(nodeTiming.loopStart, -1); +} else { + // Worker threads run the user script after loop is started. + assert.ok(nodeTiming.loopStart >= nodeTiming.bootstrapComplete); +} +assert.strictEqual(nodeTiming.loopExit, -1); + +setTimeout(common.mustCall(() => { + assert.ok(nodeTiming.idleTime >= 0); + assert.ok(nodeTiming.idleTime + nodeTiming.loopExit <= nodeTiming.duration); + assert.ok(nodeTiming.loopStart >= nodeTiming.bootstrapComplete); +}, 1), 1); + +// Can not be wrapped in common.mustCall(). +process.on('exit', () => { + assert.ok(nodeTiming.loopExit > 0); +});