Skip to content
32 changes: 31 additions & 1 deletion packages/bun-usockets/src/eventing/epoll_kqueue.c
Original file line number Diff line number Diff line change
Expand Up @@ -401,13 +401,28 @@ void us_loop_run_bun_tick(struct us_loop_t *loop, const struct timespec* timeout
if (!handed_off && will_idle_inside_event_loop) {
static const uint64_t idle_sweep_interval_ns = 100 * 1000000ULL;
static _Thread_local uint64_t last_idle_sweep_ns = 0;
const uint64_t sweep_now_ns = now_ns ? now_ns : us_internal_monotonic_ns();
const uint64_t sweep_now_ns = now_ns ? now_ns : us_loop_monotonic_ns();
if (sweep_now_ns >= last_idle_sweep_ns + idle_sweep_interval_ns) {
last_idle_sweep_ns = sweep_now_ns;
mi_on_thread_idle();
}
}

/* Measure time blocked in the event provider for
* performance.eventLoopUtilization(). Gate on the timeout only (like libuv),
* NOT on will_idle_inside_event_loop: a stale pending_wakeups (the wakeup
* eventfd is edge-triggered and consumed by the previous tick's dispatch,
* but pending_wakeups is only cleared by the exchange above) would make
* will_idle false while the provider still blocks, mis-attributing the wait
* to active. A zero-timeout poll-through is not idle. Publish the wait's
* start so a cross-thread reader can credit the in-progress wait to idle.
* Timestamped after the inline sweep above: that sweep is CPU work on this
* thread, not time blocked in the provider. */
const int will_track_idle = !timeout || (timeout->tv_nsec != 0 || timeout->tv_sec != 0);
const uint64_t idle_start_ns = will_track_idle ? us_loop_monotonic_ns() : 0;
if (will_track_idle)
__atomic_store_n(&loop->data.idle_entry_ns, idle_start_ns, __ATOMIC_RELEASE);

/* Fetch ready polls */
#ifdef LIBUS_USE_EPOLL
/* A zero timespec already has a fast path in ep_poll (fs/eventpoll.c):
Expand All @@ -432,6 +447,21 @@ void us_loop_run_bun_tick(struct us_loop_t *loop, const struct timespec* timeout
if (handed_off)
mi_on_thread_idle_end();

if (will_track_idle) {
const uint64_t idle_end_ns = us_loop_monotonic_ns();
/* Clear the in-progress marker, then credit the total. The credit is a
* release store and the reader loads idle_time_ns with acquire, so a
* reader that observes the credited total also observes the cleared
* marker (never both, which would double-count the just-finished wait).
* A reader landing between the two stores sees a slightly-low idle
* instead, which is acceptable. Release on the clear alone would not
* order the later credit, so on weak-memory targets the credit could
* become visible first without the acquire/release pairing below. */
__atomic_store_n(&loop->data.idle_entry_ns, 0, __ATOMIC_RELEASE);
if (idle_end_ns > idle_start_ns)
__atomic_add_fetch(&loop->data.idle_time_ns, idle_end_ns - idle_start_ns, __ATOMIC_RELEASE);
}

us_internal_dispatch_ready_polls(loop);
us_internal_drain_ready_polls(loop);
us_internal_sweep_if_due(loop);
Expand Down
4 changes: 4 additions & 0 deletions packages/bun-usockets/src/eventing/libuv.c
Original file line number Diff line number Diff line change
Expand Up @@ -162,6 +162,10 @@ struct us_loop_t *us_create_loop(void *hint,
loop->uv_loop = hint ? hint : uv_loop_new();
loop->is_default = hint != 0;

// Required before uv_metrics_idle_time() accumulates anything; it backs
// performance.eventLoopUtilization() on the libuv (Windows) path.
uv_loop_configure(loop->uv_loop, UV_METRICS_IDLE_TIME);

Comment thread
coderabbitai[bot] marked this conversation as resolved.
loop->uv_pre = malloc(sizeof(uv_prepare_t));
uv_prepare_init(loop->uv_loop, loop->uv_pre);
uv_prepare_start(loop->uv_pre, prepare_cb);
Expand Down
10 changes: 7 additions & 3 deletions packages/bun-usockets/src/internal/internal.h
Original file line number Diff line number Diff line change
Expand Up @@ -75,6 +75,13 @@ extern void __attribute__((__noreturn__)) Bun__panic(const char *message, size_t
* allocations this library has no way to fail gracefully from. */
extern void __attribute__((__noreturn__)) Bun__outOfMemory(void);

/* Monotonic clock (ns): uv_hrtime under libuv, else CLOCK_MONOTONIC. Used for
* event-loop-utilization accounting and (POSIX) the sweep-timer deadlines, so
* anything comparing against a loop deadline must read it and not another. */
uint64_t us_loop_monotonic_ns(void);
/* Sample the loop's accumulated idle time and active time (both ns). */
void us_loop_event_loop_utilization(struct us_loop_t *loop, uint64_t *idle_ns_out, uint64_t *active_ns_out);

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This seems wasteful and doesn't actually fix the issue at hand. Find another approach

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Want to make sure I rework this in the direction you have in mind, so a bit of context on both points:

On cost: the two clock reads happen only when the wait can actually block (NULL or nonzero timeout). Zero-timeout poll-throughs, i.e. every tick while the loop is busy, skip the instrumentation entirely, so the steady-state overhead is two vDSO clock_gettime calls per sleep/wake cycle, paid next to a syscall that already context-switches. This is the same measurement libuv performs under UV_METRICS_IDLE_TIME, which Node enables unconditionally for every loop including workers; the Windows path here just uses that.

On the issue: the reporter's repro from #32609 now produces Node's output and exits the same way. This branch prints { idle: 0, active: 168.4, utilization: 1 } and climbing, where Node v26 prints { idle: 0, active: 167.6, utilization: 1 }; the released Bun prints the NotImplementedError warning and zeros forever. So I may be missing what you mean by not fixing the issue at hand; if you saw a case where the numbers are wrong, I would like to chase it.

If the objection is that the accounting is always on, I can gate it behind a per-loop flag that flips on the first eventLoopUtilization() call, making the cost exactly zero until someone uses the API. The tradeoff is that idle time before the first call gets reported as active (Node reports absolute idle since loop start), though the common delta usage elu(prev) is unaffected. If you have a different mechanism in mind instead, point me at it and I will rework the PR.

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can you show me in libuv?

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sure. In libuv the measurement is the UV_METRICS_IDLE_TIME machinery:

  • Right before the provider wait, gated on a nonzero timeout exactly like this PR: src/unix/linux.c#L1453-L1465
    /* Only need to set the provider_entry_time if timeout != 0. ... */
    if (timeout != 0)
      uv__metrics_set_provider_entry_time(loop);
    ...
    nfds = epoll_pwait(epollfd, events, ARRAY_SIZE(events), timeout, sigmask);
  • The entry/exit clock reads and accumulation: src/uv-common.c#L986-L1025 (uv__metrics_set_provider_entry_time takes uv_hrtime() under a mutex before the wait; uv__metrics_update_idle_time takes it again after wake at linux.c#L1564 and #L1580 and adds the delta to provider_idle_time).
  • The reader crediting an in-flight wait, which is what idle_entry_ns does here: src/uv-common.c#L1040-L1053, if (entry_time > 0) idle_time += uv_hrtime() - entry_time;

Node turns this on unconditionally for every loop it creates:

and eventLoopUtilization() is computed from it in lib/internal/perf/event_loop_utilization.js via nodeTiming.idleTime, which is uv_metrics_idle_time().

One difference: libuv takes a mutex around both the entry and exit bookkeeping on every wait. This PR uses lock-free atomics for the same two stores, so the per-wait cost here is strictly lower than what every Node process (and Bun on Windows, where we run libuv) already pays. On Windows this PR does not add any measurement of its own, it just flips the same UV_METRICS_IDLE_TIME flag and reads uv_metrics_idle_time().


#ifdef _WIN32
#define IS_EINTR(rc) (rc == SOCKET_ERROR && WSAGetLastError() == WSAEINTR)
#define LIBUS_ERR WSAGetLastError()
Expand Down Expand Up @@ -150,9 +157,6 @@ void us_internal_timer_sweep(us_loop_r loop);
void us_internal_enable_sweep_timer(struct us_loop_t *loop);
void us_internal_disable_sweep_timer(struct us_loop_t *loop);
#ifndef LIBUS_USE_LIBUV
/* CLOCK_MONOTONIC in ns. The clock every deadline on the loop is measured
* against, so anything comparing against one must read it and not another. */
uint64_t us_internal_monotonic_ns(void);
long long us_internal_sweep_timeout_ns(struct us_loop_t *loop);
void us_internal_sweep_if_due(struct us_loop_t *loop);
#endif
Expand Down
16 changes: 16 additions & 0 deletions packages/bun-usockets/src/internal/loop_data.h
Original file line number Diff line number Diff line change
Expand Up @@ -87,6 +87,22 @@ 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;
/* Monotonic timestamp (ns) captured when the loop was created; the origin
* for event-loop-utilization. Set once in us_internal_loop_data_init. */
uint64_t creation_monotonic_ns;
/* Accumulated time (ns) the loop spent blocked in the event provider
* (epoll_pwait2 / kevent64). Written with __atomic_* by the owning thread
* in us_loop_run_bun_tick; read atomically by any thread (the parent reads
* a worker's counter for Worker.performance.eventLoopUtilization()). On
* Windows the idle time comes from uv_metrics_idle_time() instead, so this
* field is left at zero there. */
uint64_t idle_time_ns;
/* Monotonic timestamp (ns) of an in-progress provider wait, or 0 when not
* waiting. Lets a cross-thread reader credit the currently-blocked wait to
* idle instead of active (mirrors libuv's provider_entry_time). Written
* with __atomic_* by the owning thread around the epoll/kevent syscall;
* unused on Windows (uv_metrics_idle_time already accounts for it). */
uint64_t idle_entry_ns;
};

#endif // LOOP_DATA_H
55 changes: 46 additions & 9 deletions packages/bun-usockets/src/loop.c
Original file line number Diff line number Diff line change
Expand Up @@ -30,6 +30,48 @@
#include <linux/errqueue.h>
#endif

uint64_t us_loop_monotonic_ns(void) {
#ifdef LIBUS_USE_LIBUV
return uv_hrtime();
#else
struct timespec ts;
clock_gettime(CLOCK_MONOTONIC, &ts);
return (uint64_t)ts.tv_sec * 1000000000ull + (uint64_t)ts.tv_nsec;
#endif
}
Comment thread
robobun marked this conversation as resolved.

/* Fills *idle_ns_out / *active_ns_out with the loop's accumulated idle time and
* the active (non-idle) time since the loop was created. Thread-safe: the idle
* counter is read atomically and the creation timestamp is immutable, so the
* parent thread can sample a worker's loop. */
void us_loop_event_loop_utilization(struct us_loop_t *loop, uint64_t *idle_ns_out, uint64_t *active_ns_out) {
if (!loop) {
*idle_ns_out = 0;
*active_ns_out = 0;
return;
}
uint64_t now_ns = us_loop_monotonic_ns();
#ifdef LIBUS_USE_LIBUV
/* libuv folds any in-progress provider wait into this value itself. */
uint64_t idle_ns = uv_metrics_idle_time(loop->uv_loop);
#else
Comment thread
robobun marked this conversation as resolved.
Comment thread
coderabbitai[bot] marked this conversation as resolved.
/* Acquire pairs with the release credit in us_loop_run_bun_tick: if we see
* a just-credited idle_time_ns we also see the cleared idle_entry_ns below,
* so an in-progress wait is never counted twice. */
uint64_t idle_ns = __atomic_load_n(&loop->data.idle_time_ns, __ATOMIC_ACQUIRE);
/* If the loop is blocked in the provider right now, credit the elapsed part
* of that wait to idle (it is not yet added to idle_time_ns). Without this a
* loop sampled mid-wait looks fully active. */
uint64_t idle_entry_ns = __atomic_load_n(&loop->data.idle_entry_ns, __ATOMIC_ACQUIRE);
if (idle_entry_ns != 0 && now_ns > idle_entry_ns)
Comment thread
robobun marked this conversation as resolved.
idle_ns += now_ns - idle_entry_ns;
#endif
uint64_t created_ns = loop->data.creation_monotonic_ns;
uint64_t elapsed_ns = (created_ns && now_ns > created_ns) ? (now_ns - created_ns) : 0;
*idle_ns_out = idle_ns;
*active_ns_out = elapsed_ns > idle_ns ? elapsed_ns - idle_ns : 0;
}

#if __has_include("wtf/Platform.h")
#include "wtf/Platform.h"
#elif !defined(ASSERT_ENABLED)
Expand Down Expand Up @@ -72,16 +114,10 @@ void us_internal_disable_sweep_timer(struct us_loop_t *loop) {

#define LIBUS_TIMEOUT_GRANULARITY_NS ((long long) LIBUS_TIMEOUT_GRANULARITY * 1000000000LL)

uint64_t us_internal_monotonic_ns(void) {
struct timespec ts;
clock_gettime(CLOCK_MONOTONIC, &ts);
return (uint64_t) ts.tv_sec * 1000000000ULL + (uint64_t) ts.tv_nsec;
}

void us_internal_enable_sweep_timer(struct us_loop_t *loop) {
loop->data.sweep_timer_count++;
if (loop->data.sweep_timer_count == 1) {
loop->data.sweep_next_tick_ns = (long long) us_internal_monotonic_ns() + LIBUS_TIMEOUT_GRANULARITY_NS;
loop->data.sweep_next_tick_ns = (long long) us_loop_monotonic_ns() + LIBUS_TIMEOUT_GRANULARITY_NS;
Bun__internal_ensureDateHeaderTimerIsEnabled(loop);
}
}
Expand All @@ -99,15 +135,15 @@ long long us_internal_sweep_timeout_ns(struct us_loop_t *loop) {
}
/* Its own reading, deliberately: this bounds the poll so the sweep is not
* starved, and a caller's older reading would round the deadline up. */
long long diff = loop->data.sweep_next_tick_ns - (long long) us_internal_monotonic_ns();
long long diff = loop->data.sweep_next_tick_ns - (long long) us_loop_monotonic_ns();
return diff > 0 ? diff : 0;
}

void us_internal_sweep_if_due(struct us_loop_t *loop) {
if (loop->data.sweep_next_tick_ns < 0) {
return;
}
long long now = (long long) us_internal_monotonic_ns();
long long now = (long long) us_loop_monotonic_ns();
if (now < loop->data.sweep_next_tick_ns) {
return;
}
Expand All @@ -122,6 +158,7 @@ void us_internal_sweep_if_due(struct us_loop_t *loop) {
void us_internal_loop_data_init(struct us_loop_t *loop, void (*wakeup_cb)(struct us_loop_t *loop),
void (*pre_cb)(struct us_loop_t *loop), void (*post_cb)(struct us_loop_t *loop)) {
// We allocate with calloc, so we only need to initialize the specific fields in use.
loop->data.creation_monotonic_ns = us_loop_monotonic_ns();
#ifdef LIBUS_USE_LIBUV
loop->data.sweep_timer = us_create_timer(loop, 1, 0);
#else
Expand Down
41 changes: 27 additions & 14 deletions src/js/internal/shared.ts
Original file line number Diff line number Diff line change
Expand Up @@ -37,19 +37,6 @@ function hideFromStack(...fns: Function[]) {
}
}

let warned: Set<string>;
function warnNotImplementedOnce(feature: string, issue?: number) {
if (!warned) {
warned = new Set();
}

if (warned.has(feature)) {
return;
}
warned.add(feature);
console.warn(new NotImplementedError(feature, issue));
}

let util: typeof import("node:util");
class ExceptionWithHostPort extends Error {
errno: number;
Expand Down Expand Up @@ -271,11 +258,37 @@ function makeNodeEntryList(entries) {

//

// Shared by perf_hooks and worker_threads. `getRaw` returns the loop's total
// { idle, active } time in ms; the two optional arguments are prior ELU
// snapshots to diff against. Mirrors Node's internal/perf/event_loop_utilization.
function eventLoopUtilization(getRaw: () => { idle: number; active: number }, util1?, util2?) {
if (util2) {
const idle = util1.idle - util2.idle;
const active = util1.active - util2.active;
const total = idle + active;
return { idle, active, utilization: total === 0 ? 0 : active / total };
}

const { idle, active } = getRaw();
if (!util1) {
const total = idle + active;
return { idle, active, utilization: total === 0 ? 0 : active / total };
}

// Clamp: a cross-thread prior sample taken mid-wait can exceed a later read
// that lands between the writer's entry-clear and idle-credit stores; a
// negative delta would otherwise surface as utilization > 1.
const idleDelta = Math.max(0, idle - util1.idle);
const activeDelta = Math.max(0, active - util1.active);
const total = idleDelta + activeDelta;
return { idle: idleDelta, active: activeDelta, utilization: total === 0 ? 0 : activeDelta / total };
}

export default {
NotImplementedError,
throwNotImplemented,
hideFromStack,
warnNotImplementedOnce,
eventLoopUtilization,
Comment thread
robobun marked this conversation as resolved.
ExceptionWithHostPort,
NodeAggregateError,
ConnResetException,
Expand Down
20 changes: 13 additions & 7 deletions src/js/node/perf_hooks.ts
Original file line number Diff line number Diff line change
@@ -1,5 +1,15 @@
// Hardcoded module "node:perf_hooks"
const { throwNotImplemented, kNodeEntryTypes, NodeEntryObserver } = require("internal/shared");
const {
throwNotImplemented,
kNodeEntryTypes,
NodeEntryObserver,
eventLoopUtilization: computeEventLoopUtilization,
} = require("internal/shared");

const getEventLoopUtilizationRaw = $newRustFunction("event_loop.rs", "jsEventLoopUtilization", 0) as () => {
idle: number;
active: number;
};

const cppCreateHistogram = $newCppFunction("JSNodePerformanceHooksHistogram.cpp", "jsFunction_createHistogram", 3) as (
min: number,
Expand Down Expand Up @@ -97,12 +107,8 @@ function createPerformanceNodeTiming() {
return object;
}

function eventLoopUtilization(_utilization1, _utilization2) {
return {
idle: 0,
active: 0,
utilization: 0,
};
function eventLoopUtilization(utilization1, utilization2) {
return computeEventLoopUtilization(getEventLoopUtilizationRaw, utilization1, utilization2);
}

// PerformanceEntry is not a valid constructor, so we have to fake it.
Expand Down
29 changes: 18 additions & 11 deletions src/js/node/worker_threads.ts
Original file line number Diff line number Diff line change
Expand Up @@ -7,7 +7,7 @@ const EventEmitter = require("node:events");
const { SafeMap } = require("internal/primordials");
const Readable = require("internal/streams/readable");
const Writable = require("internal/streams/writable");
const { throwNotImplemented, warnNotImplementedOnce } = require("internal/shared");
const { throwNotImplemented, eventLoopUtilization: computeEventLoopUtilization } = require("internal/shared");
const {
validateString,
validateObject,
Expand Down Expand Up @@ -1146,16 +1146,23 @@ class Worker extends EventEmitter {
}

get performance() {
return (this.#performance ??= {
eventLoopUtilization() {
warnNotImplementedOnce("worker_threads.Worker.performance");
return {
idle: 0,
active: 0,
utilization: 0,
};
},
});
if (this.#performance === undefined) {
const getRaw = () => this.#worker.eventLoopUtilizationInternal();
this.#performance = {
eventLoopUtilization(utilization1, utilization2) {
const raw = getRaw();
// The native side returns { idle: 0, active: 0 } while the worker
// isn't running (not yet online, terminating, or exited). Match Node:
// return zeros and ignore the prior samples rather than producing
// negative deltas from `raw - utilization1`.
if (raw.idle === 0 && raw.active === 0) {
return { idle: 0, active: 0, utilization: 0 };
}
return computeEventLoopUtilization(() => raw, utilization1, utilization2);
},
};
}
return this.#performance;
Comment thread
robobun marked this conversation as resolved.
}

terminate(callback: unknown) {
Expand Down
19 changes: 19 additions & 0 deletions src/jsc/bindings/webcore/JSWorker.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -88,6 +88,7 @@ static JSC_DECLARE_HOST_FUNCTION(jsWorkerPrototypeFunction_getHeapStatistics);
static JSC_DECLARE_HOST_FUNCTION(jsWorkerPrototypeFunction_startCpuProfileInternal);
static JSC_DECLARE_HOST_FUNCTION(jsWorkerPrototypeFunction_stopCpuProfileInternal);
static JSC_DECLARE_HOST_FUNCTION(jsWorkerPrototypeFunction_cpuUsageInternal);
static JSC_DECLARE_HOST_FUNCTION(jsWorkerPrototypeFunction_eventLoopUtilization);

// Attributes

Expand Down Expand Up @@ -447,6 +448,7 @@ static const HashTableValue JSWorkerPrototypeTableValues[] = {
{ "startCpuProfileInternal"_s, static_cast<unsigned>(JSC::PropertyAttribute::Function | JSC::PropertyAttribute::DontEnum), NoIntrinsic, { HashTableValue::NativeFunctionType, jsWorkerPrototypeFunction_startCpuProfileInternal, 0 } },
{ "stopCpuProfileInternal"_s, static_cast<unsigned>(JSC::PropertyAttribute::Function | JSC::PropertyAttribute::DontEnum), NoIntrinsic, { HashTableValue::NativeFunctionType, jsWorkerPrototypeFunction_stopCpuProfileInternal, 0 } },
{ "cpuUsageInternal"_s, static_cast<unsigned>(JSC::PropertyAttribute::Function | JSC::PropertyAttribute::DontEnum), NoIntrinsic, { HashTableValue::NativeFunctionType, jsWorkerPrototypeFunction_cpuUsageInternal, 0 } },
{ "eventLoopUtilizationInternal"_s, static_cast<unsigned>(JSC::PropertyAttribute::Function | JSC::PropertyAttribute::DontEnum), NoIntrinsic, { HashTableValue::NativeFunctionType, jsWorkerPrototypeFunction_eventLoopUtilization, 0 } },
};

const ClassInfo JSWorkerPrototype::s_info = { "Worker"_s, &Base::s_info, nullptr, nullptr, CREATE_METHOD_TABLE(JSWorkerPrototype) };
Expand Down Expand Up @@ -937,6 +939,23 @@ JSC_DEFINE_HOST_FUNCTION(jsWorkerPrototypeFunction_getHeapSnapshot, (JSGlobalObj
return IDLOperation<JSWorker>::call<jsWorkerPrototypeFunction_getHeapSnapshotBody>(*lexicalGlobalObject, *callFrame, "getHeapSnapshot");
}

static inline JSC::EncodedJSValue jsWorkerPrototypeFunction_eventLoopUtilizationBody(JSC::JSGlobalObject* lexicalGlobalObject, JSC::CallFrame* callFrame, typename IDLOperation<JSWorker>::ClassParameter castedThis)
{
auto& vm = JSC::getVM(lexicalGlobalObject);
double idleMs = 0;
double activeMs = 0;
castedThis->wrapped().eventLoopUtilization(idleMs, activeMs);
auto* result = JSC::constructEmptyObject(lexicalGlobalObject, lexicalGlobalObject->objectPrototype(), 2);
result->putDirect(vm, JSC::Identifier::fromString(vm, "idle"_s), JSC::jsDoubleNumber(idleMs));
result->putDirect(vm, JSC::Identifier::fromString(vm, "active"_s), JSC::jsDoubleNumber(activeMs));
return JSValue::encode(result);
}

JSC_DEFINE_HOST_FUNCTION(jsWorkerPrototypeFunction_eventLoopUtilization, (JSGlobalObject * lexicalGlobalObject, CallFrame* callFrame))
{
return IDLOperation<JSWorker>::call<jsWorkerPrototypeFunction_eventLoopUtilizationBody>(*lexicalGlobalObject, *callFrame, "eventLoopUtilization");
}

JSC::GCClient::IsoSubspace* JSWorker::subspaceForImpl(JSC::VM& vm)
{
return WebCore::subspaceForImpl<JSWorker, UseCustomHeapCellType::No>(
Expand Down
Loading
Loading