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); +});