diff --git a/docs/runtime/nodejs-compat.mdx b/docs/runtime/nodejs-compat.mdx index 2331b3a5a030..cad1ba7771fb 100644 --- a/docs/runtime/nodejs-compat.mdx +++ b/docs/runtime/nodejs-compat.mdx @@ -129,7 +129,7 @@ We update this page regularly. It reflects the latest version of Bun's compatibi ### [`node:perf_hooks`](https://nodejs.org/api/perf_hooks.html) -🟡 `monitorEventLoopDelay()`, `createHistogram()`, `timerify()` and `PerformanceObserver` (`mark`, `measure`, `function`, `net`, `http` and `http2` entries) are implemented. Bun never emits `gc`, `dns` or `resource` entries. `eventLoopUtilization()` always returns zeros, and `performance.nodeTiming` holds placeholder values. The Node-specific additions to the global `performance` object only appear once `node:perf_hooks` has been imported. +🟡 `monitorEventLoopDelay()`, `createHistogram()`, `timerify()` and `PerformanceObserver` (`mark`, `measure`, `function`, `net`, `http` and `http2` entries) are implemented. Bun never emits `gc`, `dns` or `resource` entries. `eventLoopUtilization()` returns zeros on Windows, and `performance.nodeTiming` holds placeholder values. The Node-specific additions to the global `performance` object only appear once `node:perf_hooks` has been imported. ### [`node:process`](https://nodejs.org/api/process.html) @@ -373,7 +373,7 @@ The following list covers the globals implemented by Node.js and Bun's compatibi ### [`performance`](https://developer.mozilla.org/en-US/docs/Web/API/performance) -🟡 `now()`, `timeOrigin`, `mark()`, `measure()` and `getEntries()` are implemented. The Node.js additions (`eventLoopUtilization()`, `nodeTiming`, `timerify()`) only exist once `node:perf_hooks` has been loaded. `eventLoopUtilization()` always returns zeros and `nodeTiming` holds placeholder values. +🟡 `now()`, `timeOrigin`, `mark()`, `measure()` and `getEntries()` are implemented. The Node.js additions (`eventLoopUtilization()`, `nodeTiming`, `timerify()`) only exist once `node:perf_hooks` has been loaded. `eventLoopUtilization()` returns zeros on Windows and `nodeTiming` holds placeholder values. ### [`process`](https://nodejs.org/api/process.html) diff --git a/packages/bun-usockets/src/eventing/epoll_kqueue.c b/packages/bun-usockets/src/eventing/epoll_kqueue.c index 4d017cc34220..306c53bbf37c 100644 --- a/packages/bun-usockets/src/eventing/epoll_kqueue.c +++ b/packages/bun-usockets/src/eventing/epoll_kqueue.c @@ -479,6 +479,10 @@ void us_loop_run_bun_tick(struct us_loop_t *loop, const struct timespec* timeout if (loop->num_polls == 0) return; + /* Remember when this loop first ran (for eventLoopUtilization) */ + if (loop->data.loop_start_ns == 0) + loop->data.loop_start_ns = us_internal_monotonic_ns(); + loop->data.tick_depth++; /* Emit pre callback */ @@ -528,6 +532,12 @@ void us_loop_run_bun_tick(struct us_loop_t *loop, const struct timespec* timeout } } + uint64_t idle_start_ns = 0; + + /* We are about to block in the kernel, so measure how long we were idle. */ + if (will_idle_inside_event_loop) + idle_start_ns = us_internal_monotonic_ns(); + /* Fetch ready polls */ #ifdef LIBUS_USE_EPOLL /* A zero timespec already has a fast path in ep_poll (fs/eventpoll.c): @@ -546,6 +556,10 @@ void us_loop_run_bun_tick(struct us_loop_t *loop, const struct timespec* timeout timeout); #endif + /* We are back from the kernel, so measure how long we were idle. */ + if (will_idle_inside_event_loop) + loop->data.idle_time_ns += us_internal_monotonic_ns() - idle_start_ns; + /* Anything that stops a poll from here on scrubs this batch (us_internal_loop_update_pending_ready_polls). */ loop->current_ready_poll = 0; /* Before anything can allocate again. */ diff --git a/packages/bun-usockets/src/internal/loop_data.h b/packages/bun-usockets/src/internal/loop_data.h index a39aa4f9235a..28fcd444ef21 100644 --- a/packages/bun-usockets/src/internal/loop_data.h +++ b/packages/bun-usockets/src/internal/loop_data.h @@ -94,6 +94,11 @@ struct us_internal_loop_data_t { * sockets must be deferred to the outermost tick so the outer dispatch * doesn't read a freed poll. */ int tick_depth; + /* Total time spent blocked in epoll/kqueue */ + uint64_t idle_time_ns; + /* Monotonic time (ns) of the first us_loop_run_bun_tick on this loop, or 0 + * if it has not run yet. Used with idle_time_ns for eventLoopUtilization(). */ + uint64_t loop_start_ns; }; #endif // LOOP_DATA_H diff --git a/src/js/node/perf_hooks.ts b/src/js/node/perf_hooks.ts index 60b54f817404..3625fe96a1b8 100644 --- a/src/js/node/perf_hooks.ts +++ b/src/js/node/perf_hooks.ts @@ -15,6 +15,10 @@ const cppCreateHistogram = $newCppFunction("JSNodePerformanceHooksHistogram.cpp" figures: number, ) => import("node:perf_hooks").RecordableHistogram; +const eventLoopIdleTime = $newRustFunction("node_util_binding.rs", "eventLoopIdleTime", 0) as () => number; + +const eventLoopElapsedTime = $newRustFunction("node_util_binding.rs", "eventLoopElapsedTime", 0) as () => number; + var { Performance, PerformanceEntry, @@ -116,12 +120,23 @@ function createPerformanceNodeTiming() { return object; } -function eventLoopUtilization(_utilization1, _utilization2) { - return { - idle: 0, - active: 0, - utilization: 0, - }; +function eventLoopUtilization(utilization1, utilization2) { + const elapsed = eventLoopElapsedTime(); + if (elapsed <= 0) return { idle: 0, active: 0, utilization: 0 }; + + if (utilization2) { + const idle = utilization1.idle - utilization2.idle; + const active = utilization1.active - utilization2.active; + return { idle, active, utilization: active / (active + idle) }; + } + + const idle = eventLoopIdleTime(); + const active = elapsed - idle; + if (!utilization1) return { idle: idle, active, utilization: active / (active + idle) }; + + const idleDelta = idle - utilization1.idle; + const activeDelta = active - utilization1.active; + return { idle: idleDelta, active: activeDelta, utilization: activeDelta / (activeDelta + idleDelta) }; } const { PerformanceResourceTiming } = globalThis; diff --git a/src/runtime/node/node_util_binding.rs b/src/runtime/node/node_util_binding.rs index 4c5f190d98d2..f5268f169aee 100644 --- a/src/runtime/node/node_util_binding.rs +++ b/src/runtime/node/node_util_binding.rs @@ -244,3 +244,29 @@ pub(crate) fn parse_env(global: &JSGlobalObject, frame: &CallFrame) -> JsResult< } Ok(obj) } + +#[bun_jsc::host_fn] +pub(crate) fn event_loop_idle_time( + global: &JSGlobalObject, + _frame: &CallFrame, +) -> JsResult { + let loop_data = &global.bun_vm().uws_loop_mut().internal_loop_data; + Ok(JSValue::js_number( + loop_data.idle_time_ns as f64 / 1_000_000.0, + )) +} + +#[bun_jsc::host_fn] +pub(crate) fn event_loop_elapsed_time( + global: &JSGlobalObject, + _frame: &CallFrame, +) -> JsResult { + let loop_data = &global.bun_vm().uws_loop_mut().internal_loop_data; + let elapsed_ns = if loop_data.loop_start_ns == 0 { + 0 + } else { + bun_core::Timespec::now(bun_core::TimespecMockMode::ForceRealTime).ns() + - loop_data.loop_start_ns + }; + Ok(JSValue::js_number(elapsed_ns as f64 / 1_000_000.0)) +} diff --git a/src/uws_sys/InternalLoopData.rs b/src/uws_sys/InternalLoopData.rs index 80cf50a7ed03..fd5bc2a3f3f4 100644 --- a/src/uws_sys/InternalLoopData.rs +++ b/src/uws_sys/InternalLoopData.rs @@ -64,6 +64,10 @@ pub struct InternalLoopData { // Higher tier (`bun_runtime`) casts this back when reading. pub jsc_vm: *const c_void, pub tick_depth: c_int, + // Total time spent blocked in epoll/kqueue + pub idle_time_ns: u64, + // Monotonic ns of the first tick (0 = not started); see loop_data.h + pub loop_start_ns: u64, } impl InternalLoopData { diff --git a/test/js/node/perf_hooks/perf_hooks.test.ts b/test/js/node/perf_hooks/perf_hooks.test.ts index eb2f8c096bb6..c05ae0e7e2a9 100644 --- a/test/js/node/perf_hooks/perf_hooks.test.ts +++ b/test/js/node/perf_hooks/perf_hooks.test.ts @@ -364,3 +364,30 @@ test("mark/measure toJSON and inspection include detail without perf_hooks being expect(result.polluted).toBe("PerformanceMark {"); expect(exitCode).toBe(0); }); + +test("eventLoopUtilization reports busy and idle time", async () => { + const { eventLoopUtilization } = perf.performance; + // Like Node, it reports zeros until the event loop has run once. + await Bun.sleep(1); + + // Busy: block the thread for 50ms. That should count as active time. + const beforeBusy = eventLoopUtilization(); + const start = performance.now(); + while (performance.now() - start < 50) {} + const busy = eventLoopUtilization(beforeBusy); + expect(busy.active).toBeGreaterThan(40); + expect(busy.utilization).toBeGreaterThan(0.9); + + // Idle: wait on a 50ms timer. The loop sleeps, so that should count as idle time. + const beforeIdle = eventLoopUtilization(); + await Bun.sleep(50); + const idle = eventLoopUtilization(beforeIdle); + expect(idle.idle).toBeGreaterThan(25); + expect(idle.utilization).toBeLessThan(0.5); + + // With two samples, the result is their difference. + const later = eventLoopUtilization(); + const diff = eventLoopUtilization(later, beforeIdle); + expect(diff.idle).toBe(later.idle - beforeIdle.idle); + expect(diff.active).toBe(later.active - beforeIdle.active); +});