From 914865798731760f67b38f58d41771226f36542e Mon Sep 17 00:00:00 2001 From: Anton Date: Thu, 23 Jul 2026 21:10:03 +0300 Subject: [PATCH] feat: add captureStack profile mode via CpuProfiler --- ARCHITECTURE.md | 31 ++-- COMPATIBILITY.md | 16 +- README.md | 22 +-- native/addon.cpp | 16 ++ native/cpu_profile.h | 159 +++++++++++++++++ native/watchdog.cpp | 307 +++++++++++++++++++++++++++------ native/watchdog.h | 45 ++++- src/config.js | 35 +++- src/index.d.ts | 30 ++-- test/stack.integration.test.js | 101 +++++++++++ 10 files changed, 663 insertions(+), 99 deletions(-) create mode 100644 native/cpu_profile.h diff --git a/ARCHITECTURE.md b/ARCHITECTURE.md index 73596ca..65dd383 100644 --- a/ARCHITECTURE.md +++ b/ARCHITECTURE.md @@ -74,24 +74,35 @@ Event classes: - `freeze_recovered` - `freeze_stack` (optional; when `captureStack` is enabled) -### 4) Stack capture (opt-in) +### 4) Stack / profile capture (opt-in) -When `captureStack` is enabled, the monitor thread calls V8 `RequestInterrupt`. +**Interrupt mode** (`mode: "interrupt"`, including `captureStack: true`): + +When enabled, the monitor thread calls V8 `RequestInterrupt`. The interrupt callback runs on the isolate thread, captures `v8::StackTrace`, and only stashes frames (+ queues a pending event). The monitor thread then writes `freeze_stack` / notifies JS — never logger or N-API from the interrupt. - Default sampling: on `freeze_started` and each `freeze_heartbeat` (`on: "both"`). -- `"started"` / `"heartbeat"` narrow when interrupts are requested. - Unique stack shapes are aggregated per freeze (capped by `maxSamples`); on `freeze_recovered`, `stack` is the most frequent sample and `stack_samples` lists `{ count, stack }` sorted by count descending. - A single interrupt sample is not reliable attribution under many concurrent - async handlers (often only `processTicksAndRejections`); multi-sample helps - longer freezes but is not a CPU profile. A future experimental profiler mode - may cover that case. -- Sync I/O / native blocks may never reach a safepoint → `stack_status: "unavailable"` (no `stack` field). -- `freeze_stack` reuses `rss_mb` / `cpu_pct` from the latest lifecycle event so a near-zero-delta CPU sample is not emitted. + async handlers (often only `processTicksAndRejections`); the sample line is + the safepoint after native work, not always the hottest statement. + +**Profile mode** (`mode: "profile"`): + +- Arms V8 `CpuProfiler` when lag ≥ `freezeThresholdMs / 2`; discards if lag + drops without a freeze; on recover stops and attaches top hit-count paths as + `stack_samples` with `stack_mode: "profile"` (no live `freeze_stack` events). +- Start/stop/dispose run only on the isolate thread via `RequestInterrupt`. +- Adds sampling overhead while armed; still experimental / ABI-gated. + +Shared: + +- Sync I/O / native blocks may yield `stack_status: "unavailable"`. +- `freeze_stack` reuses `rss_mb` / `cpu_pct` from the latest lifecycle event. - Implemented in-core (experimental); not a separate package. ## Freeze Detection Model @@ -142,9 +153,9 @@ Recommended fields: Optional (experimental, when `captureStack` is enabled): - `stack_status` — `"ok"` \| `"unavailable"` -- `stack_mode` — `"interrupt"` +- `stack_mode` — `"interrupt"` \| `"profile"` - `stack` — string frames; present only when `stack_status` is `"ok"` - (on recovered: most frequent sample) + (on recovered: most frequent interrupt sample or hottest profile path) - `stack_samples` — on recovered: `[{ count, stack }, ...]` sorted by count descending ## Error Handling and Safety diff --git a/COMPATIBILITY.md b/COMPATIBILITY.md index af05d33..355cb2e 100644 --- a/COMPATIBILITY.md +++ b/COMPATIBILITY.md @@ -42,19 +42,23 @@ Notes on `ts`: - Opt-in stack capture is experimental and may change shape without a major bump until marked stable: - config: `captureStack` (`false` \| `true` \| `{ mode, on, maxFrames, maxSamples }`); default `false`; - `true` expands to `{ mode: "interrupt", on: "both", maxFrames: 50, maxSamples: 8 }`; - - additive event value `freeze_stack` (same channels as other freeze events); - - payload fields: `stack_status`, `stack_mode`, `stack` (`stack` only when status is `"ok"`); + - `mode`: `"interrupt"` (RequestInterrupt samples) or `"profile"` (V8 CpuProfiler; + early-arm at `freezeThresholdMs / 2`; `on` ignored); + - additive event value `freeze_stack` (interrupt mode; same channels as other freeze events); + - payload fields: `stack_status`, `stack_mode` (`"interrupt"` \| `"profile"`), + `stack` (`stack` only when status is `"ok"`); - on `freeze_recovered`: optional `stack_samples` (`[{ count, stack }, ...]`, count-desc) - when at least one interrupt sample succeeded; `stack` is the most frequent sample; - - uses V8 `RequestInterrupt` (JS busy-loop stacks; sync I/O / native blocks may yield `unavailable`; - under concurrent async work a sample may show only the promise microtask runner); + when at least one sample succeeded; `stack` is the top sample (most frequent or hottest); + - interrupt mode: JS busy-loop stacks; sync I/O / native blocks may yield `unavailable`; + under concurrent async work a sample may show only the promise microtask runner; + - profile mode: hit counts while armed; thin/`unavailable` possible if start never ran + before recover; sampling overhead while armed; - stack frames may include absolute file paths — treat logs as sensitive when enabled; - if the loaded native addon ABI (`NODE_MODULE_VERSION`) differs from the runtime (no matching published prebuild for this Node major), `captureStack` is disabled with a warning. - Linux prebuilds are libc-tagged (`glibc` / `musl`); loading an untagged glibc binary on Alpine is unsupported and may SIGSEGV under `captureStack`. - - A future experimental CPU-profile capture mode is reserved and not part of v1 yet. ## Behavioral guarantees diff --git a/README.md b/README.md index e9c9b58..fff9f4b 100644 --- a/README.md +++ b/README.md @@ -104,24 +104,24 @@ node examples/log-max-bytes.js ### `captureStack` (experimental) -Uses V8 `RequestInterrupt` to sample the JS stack when a freeze is detected. Works best for JS busy-loops; sync I/O / native blocks may leave `stack_status: "unavailable"`. +Two modes: -Under heavy parallel async work, a single sample often lands in `processTicksAndRejections` only — that does **not** identify which of many concurrent handlers blocked the loop. Prefer `on: "both"` (the `true` default) so longer freezes re-sample on heartbeat; on `freeze_recovered`, `stack` is the **most frequent** shape and `stack_samples` lists unique stacks with counts. Nearby request-completion logs are weak attribution under concurrency. +**`interrupt` (default via `true`)** — V8 `RequestInterrupt` snapshots. Works best for JS busy-loops; sync I/O / native blocks may leave `stack_status: "unavailable"`. Under heavy parallel async work, a sample often lands in `processTicksAndRejections` only. Prefer `on: "both"` so longer freezes re-sample; on recovered, `stack` is the most frequent shape and `stack_samples` lists counts. Interrupt stacks show the JS line at the next safepoint — often the statement **after** a long native call (e.g. `JSON.parse`). -Stack capture calls V8 C++ APIs. Release CI ships one ABI-tagged binary per supported Node major; `node-gyp-build` picks the match at install/load time. +**`profile`** — V8 `CpuProfiler` over the stall. Arms when lag ≥ `freezeThresholdMs / 2`, stops on recover (or discards if lag drops without freezing). On recovered, `stack_mode: "profile"` and `stack_samples` are top hot paths by hit count (no live `freeze_stack` spam). Better attribution for CPU-bound work that yields to safepoints while profiling; a single unbroken native call that never yields before recover may still produce a thin/`unavailable` profile. Adds sampling overhead while armed — keep opt-in. -A future experimental CPU-profile mode (V8 `CpuProfiler` over the freeze window) is planned for stronger attribution; not available yet. +Stack/profile capture uses V8 C++ APIs. Release CI ships one ABI-tagged binary per supported Node major; `node-gyp-build` picks the match at install/load time. | Value | Meaning | | --- | --- | | `false` / omit | disabled (default) | | `true` | `{ mode: "interrupt", on: "both", maxFrames: 50, maxSamples: 8 }` | -| `{ mode, on, maxFrames, maxSamples }` | `mode`: `"interrupt"` only; `on`: `"started"` \| `"heartbeat"` \| `"both"`; `maxFrames`: `1..256`; `maxSamples`: `1..32` unique shapes retained per freeze | +| `{ mode, on, maxFrames, maxSamples }` | `mode`: `"interrupt"` \| `"profile"`; `on` (interrupt only): `"started"` \| `"heartbeat"` \| `"both"`; `maxFrames`: `1..256`; `maxSamples`: `1..32` | When enabled, native logs / JS events may include: -- `freeze_stack` — live sample (`channel: "freeze"`); `rss_mb` / `cpu_pct` are copied from the latest lifecycle event (started/heartbeat), not re-sampled -- on `freeze_recovered`: `stack_status`, `stack_mode`, and `stack` only when status is `"ok"`; `stack_samples` (`[{ count, stack }, ...]`, count-desc) when at least one sample succeeded +- `freeze_stack` — interrupt mode live sample (`channel: "freeze"`); `rss_mb` / `cpu_pct` copied from the latest lifecycle event +- on `freeze_recovered`: `stack_status`, `stack_mode` (`"interrupt"` \| `"profile"`), and `stack` when status is `"ok"`; `stack_samples` (`[{ count, stack }, ...]`, count-desc) when samples exist - frames often contain absolute paths — keep logs access-controlled when capture is on ### Event payload @@ -143,7 +143,7 @@ When enabled, native logs / JS events may include: cpu_pct: 79.92, // -1 if unavailable // only when captureStack is enabled (on freeze_stack / freeze_recovered): // stack_status: "ok" | "unavailable", - // stack_mode: "interrupt", + // stack_mode: "interrupt" | "profile", // stack: ["at busyWait (test.js:12:5)", ...], // omitted when unavailable // on freeze_recovered when samples exist: // stack_samples: [{ count: 3, stack: ["at busyWait ..."] }, ...], @@ -160,8 +160,10 @@ When enabled, native logs / JS events may include: | Config throws `TypeError` / `RangeError` | Invalid options | See config table; values must be plain object + ranges | | Log file missing | Unwritable path / missing directories | Logger fails open quietly; stderr/`both` still work; create parent dirs if you need a file | | High `cpu_pct` during freeze | Busy-loop / CPU-bound block | Expected for sync CPU spins; use with RSS/duration context | -| No `freeze_stack` / `stack_status: "unavailable"` | Sync I/O, native addon, or interrupt never reached a V8 safepoint | Expected for non-JS blocks; check native logs around recovery; try `on: "both"` for retries | -| `stack_status: "ok"` but only `processTicksAndRejections` / `task_queues` | Interrupt landed in the promise microtask runner under async load | Expected for many concurrent awaits; use `stack_samples` + duration/RSS/CPU; do not trust nearby API method logs for attribution; raise `freezeThresholdMs` if short stalls are noise | +| No `freeze_stack` / `stack_status: "unavailable"` | Sync I/O, native addon, or interrupt never reached a V8 safepoint | Expected for non-JS blocks; check native logs around recovery; try `on: "both"` or `mode: "profile"` | +| `stack_status: "ok"` but only `processTicksAndRejections` / `task_queues` | Interrupt landed in the promise microtask runner under async load | Expected for many concurrent awaits; try `mode: "profile"`; use duration/RSS/CPU; raise `freezeThresholdMs` if short stalls are noise | +| Interrupt stack line is after `JSON.parse` / other native | Interrupt runs at the next safepoint after native returns | Expected; use `mode: "profile"` for hit-count attribution when the profiler was armed in time | +| Profile `unavailable` / empty on short native-only stalls | Profiler start interrupt could not run until after the block | Expected for one unbroken native call; lengthen work or accept interrupt function-level hint | | `captureStack` off + ABI warning | No prebuild for this Node major / wrong binary loaded | Use Node 22/24/26, or upgrade `@js-ak/watchdog` once that ABI is published | | `npm ci` in Debian slim tries to compile / needs Python | Linux prebuild needs newer `libstdc++` than the image, so load fails and install falls back to `node-gyp` | Use a newer base image, or upgrade `@js-ak/watchdog` (Ubuntu 22.04 prebuilds) | | Container exit **139** / SIGSEGV (often with `captureStack`) on Alpine | glibc Linux prebuild loaded on musl | Use a release with libc-tagged + musl prebuilds; or switch to a glibc image (`node:*-bookworm-slim`); or rebuild from source on Alpine after removing `node_modules/@js-ak/watchdog/prebuilds` | diff --git a/native/addon.cpp b/native/addon.cpp index 0e00575..88cb1f5 100644 --- a/native/addon.cpp +++ b/native/addon.cpp @@ -321,6 +321,22 @@ bool ReadConfig(napi_env env, napi_value object, config->capture_stack = true; napi_value field; + if (napi_get_named_property(env, value, "mode", &field) == napi_ok) { + size_t len = 0; + napi_get_value_string_utf8(env, field, nullptr, 0, &len); + std::string mode(len, '\0'); + if (napi_get_value_string_utf8(env, field, mode.data(), len + 1, + &len) == napi_ok) { + if (mode == "profile") { + config->capture_stack_mode = + jsak::watchdog::StackCaptureMode::Profile; + } else if (mode == "interrupt") { + config->capture_stack_mode = + jsak::watchdog::StackCaptureMode::Interrupt; + } + } + } + if (napi_get_named_property(env, value, "on", &field) == napi_ok) { size_t len = 0; napi_get_value_string_utf8(env, field, nullptr, 0, &len); diff --git a/native/cpu_profile.h b/native/cpu_profile.h new file mode 100644 index 0000000..3e0c291 --- /dev/null +++ b/native/cpu_profile.h @@ -0,0 +1,159 @@ +#pragma once + +#include +#include +#include + +#include +#include + +#include "watchdog.h" + +namespace jsak { +namespace watchdog { +namespace { + +inline constexpr const char kCpuProfileTitle[] = "js-ak/watchdog"; + +inline std::string FormatProfileFrame(v8::Isolate* isolate, + const v8::CpuProfileNode* node) { + if (node == nullptr) { + return "at "; + } + + v8::String::Utf8Value fn(isolate, node->GetFunctionName()); + v8::String::Utf8Value script(isolate, node->GetScriptResourceName()); + const int line = node->GetLineNumber(); + const int column = node->GetColumnNumber(); + + std::string out = "at "; + if (fn.length() > 0) { + out.append(*fn, static_cast(fn.length())); + out += " ("; + } + + if (script.length() > 0) { + out.append(*script, static_cast(script.length())); + } else { + out += ""; + } + if (line > 0) { + out += ':'; + out += std::to_string(line); + if (column > 0) { + out += ':'; + out += std::to_string(column); + } + } + + if (fn.length() > 0) { + out += ')'; + } + return out; +} + +inline void WalkProfileNode(v8::Isolate* isolate, + const v8::CpuProfileNode* node, + std::vector& path, + std::vector& samples, + int max_frames) { + if (node == nullptr) { + return; + } + + path.push_back(FormatProfileFrame(isolate, node)); + + const unsigned hits = node->GetHitCount(); + if (hits > 0 && path.size() > 1) { + // Skip pure root-only hits; keep paths with real frames. + StackSample sample; + sample.count = hits; + // Leaf-first order to match interrupt / Error.stack style. + const size_t n = path.size(); + const size_t take = + max_frames > 0 ? std::min(n, static_cast(max_frames)) : n; + sample.stack.reserve(take); + for (size_t i = 0; i < take; i += 1) { + sample.stack.push_back(path[n - 1 - i]); + } + samples.push_back(std::move(sample)); + } + + const int children = node->GetChildrenCount(); + for (int i = 0; i < children; i += 1) { + WalkProfileNode(isolate, node->GetChild(i), path, samples, max_frames); + } + + path.pop_back(); +} + +} // namespace + +inline std::vector CollectCpuProfileSamples( + v8::Isolate* isolate, const v8::CpuProfile* profile, int max_frames, + uint32_t max_samples) { + std::vector samples; + if (isolate == nullptr || profile == nullptr) { + return samples; + } + + std::vector path; + WalkProfileNode(isolate, profile->GetTopDownRoot(), path, samples, + max_frames); + + std::stable_sort(samples.begin(), samples.end(), + [](const StackSample& a, const StackSample& b) { + return a.count > b.count; + }); + + const uint32_t cap = ClampStackSamples(max_samples); + if (samples.size() > static_cast(cap)) { + samples.resize(static_cast(cap)); + } + return samples; +} + +inline bool StartCpuProfiling(v8::Isolate* isolate, + v8::CpuProfiler** profiler) { + if (isolate == nullptr || profiler == nullptr) { + return false; + } + if (*profiler == nullptr) { + *profiler = v8::CpuProfiler::New(isolate); + } + if (*profiler == nullptr) { + return false; + } + + v8::HandleScope handle_scope(isolate); + v8::Local title = + v8::String::NewFromUtf8(isolate, kCpuProfileTitle, + v8::NewStringType::kNormal) + .ToLocalChecked(); + (*profiler)->StartProfiling(title, true); + return true; +} + +inline v8::CpuProfile* StopCpuProfiling(v8::Isolate* isolate, + v8::CpuProfiler* profiler) { + if (isolate == nullptr || profiler == nullptr) { + return nullptr; + } + v8::HandleScope handle_scope(isolate); + v8::Local title = + v8::String::NewFromUtf8(isolate, kCpuProfileTitle, + v8::NewStringType::kNormal) + .ToLocalChecked(); + return profiler->StopProfiling(title); +} + +inline void DisposeCpuProfiler(v8::CpuProfiler** profiler) { + if (profiler == nullptr || *profiler == nullptr) { + return; + } + (*profiler)->Dispose(); + *profiler = nullptr; +} + +} // namespace watchdog +} // namespace jsak diff --git a/native/watchdog.cpp b/native/watchdog.cpp index 266182d..0b9b1c6 100644 --- a/native/watchdog.cpp +++ b/native/watchdog.cpp @@ -3,6 +3,7 @@ #include #include +#include "cpu_profile.h" #include "logger.h" #include "metrics.h" #include "stack_capture.h" @@ -28,7 +29,7 @@ void StackInterruptCallback(v8::Isolate* isolate, void* data) { Watchdog* watchdog = nullptr; { // Pin Watchdog via in_flight so Stop()/DisableInterrupts waits before - // nulling watchdog — CaptureJsStack must not run under gate->mutex. + // nulling watchdog — isolate work must not run under gate->mutex. std::lock_guard lock(gate->mutex); if (!gate->open || gate->watchdog == nullptr) { return; @@ -37,8 +38,9 @@ void StackInterruptCallback(v8::Isolate* isolate, void* data) { gate->in_flight += 1; } - watchdog->OnStackInterrupt(isolate, payload->freeze_id, payload->generation, - payload->sequence, payload->max_frames); + watchdog->OnInterrupt(isolate, payload->action, payload->freeze_id, + payload->generation, payload->sequence, + payload->max_frames); { std::lock_guard lock(gate->mutex); @@ -73,18 +75,30 @@ void Watchdog::DisableInterrupts() { interrupt_gate_->watchdog = nullptr; } +bool Watchdog::IsProfileMode() const { + return config_.capture_stack && + config_.capture_stack_mode == StackCaptureMode::Profile; +} + bool Watchdog::ShouldCaptureOnStarted() const { return config_.capture_stack && + config_.capture_stack_mode == StackCaptureMode::Interrupt && (config_.capture_stack_on == StackCaptureOn::Started || config_.capture_stack_on == StackCaptureOn::Both); } bool Watchdog::ShouldCaptureOnHeartbeat() const { return config_.capture_stack && + config_.capture_stack_mode == StackCaptureMode::Interrupt && (config_.capture_stack_on == StackCaptureOn::Heartbeat || config_.capture_stack_on == StackCaptureOn::Both); } +uint32_t Watchdog::ProfileArmMs() const { + const uint32_t half = config_.freeze_threshold_ms / 2; + return half < 1 ? 1 : half; +} + bool Watchdog::Start(const Config& config) { if (running_.exchange(true)) { return false; @@ -103,6 +117,8 @@ bool Watchdog::Start(const Config& config) { SampleCpuPercent(&prev_wall_ms_, &prev_cpu_ms_); last_kick_ms_.store(NowMs(), std::memory_order_release); active_freeze_id_.store(0, std::memory_order_release); + profile_running_.store(false, std::memory_order_release); + profile_start_pending_.store(false, std::memory_order_release); { std::lock_guard lock(metrics_cache_mutex_); @@ -122,6 +138,11 @@ bool Watchdog::Start(const Config& config) { pending_stack_event_ = Event{}; } + { + std::lock_guard lock(profile_op_mutex_); + profile_op_done_ = true; + } + if (config_.capture_stack && isolate_ != nullptr) { interrupt_gate_ = std::make_shared(); std::lock_guard lock(interrupt_gate_->mutex); @@ -140,11 +161,18 @@ void Watchdog::Stop() { return; } - DisableInterrupts(); - + // Join first so the monitor can still RequestInterrupt for profile stop / + // dispose while the gate is open. if (monitor_.joinable()) { monitor_.join(); } + + if (IsProfileMode() && interrupt_gate_ && isolate_ != nullptr) { + RequestInterruptAction(InterruptAction::ProfileDispose, 0, 0); + WaitInterruptAction(500); + } + + DisableInterrupts(); } bool Watchdog::IsRunning() const { @@ -155,16 +183,26 @@ void Watchdog::Kick() { last_kick_ms_.store(NowMs(), std::memory_order_release); } -void Watchdog::RequestStackCapture(uint64_t freeze_id, uint32_t sequence) { +void Watchdog::RequestInterruptAction(InterruptAction action, + uint64_t freeze_id, uint32_t sequence) { if (!config_.capture_stack || isolate_ == nullptr || !interrupt_gate_) { + if (action != InterruptAction::CaptureStack) { + SignalInterruptActionDone(); + } return; } const uint64_t generation = interrupt_generation_.load(std::memory_order_acquire); + if (action != InterruptAction::CaptureStack) { + std::lock_guard lock(profile_op_mutex_); + profile_op_done_ = false; + } + auto* payload = new StackInterruptPayload(); payload->gate = interrupt_gate_; + payload->action = action; payload->freeze_id = freeze_id; payload->generation = generation; payload->sequence = sequence; @@ -173,54 +211,145 @@ void Watchdog::RequestStackCapture(uint64_t freeze_id, uint32_t sequence) { isolate_->RequestInterrupt(StackInterruptCallback, payload); } -void Watchdog::OnStackInterrupt(v8::Isolate* isolate, uint64_t freeze_id, - uint64_t generation, uint32_t sequence, - uint32_t max_frames) { +bool Watchdog::WaitInterruptAction(uint32_t timeout_ms) { + std::unique_lock lock(profile_op_mutex_); + return profile_op_cv_.wait_for( + lock, std::chrono::milliseconds(timeout_ms), + [this]() { return profile_op_done_; }); +} + +void Watchdog::SignalInterruptActionDone() { + std::lock_guard lock(profile_op_mutex_); + profile_op_done_ = true; + profile_op_cv_.notify_all(); +} + +void Watchdog::OnInterrupt(v8::Isolate* isolate, InterruptAction action, + uint64_t freeze_id, uint64_t generation, + uint32_t sequence, uint32_t max_frames) { if (generation != interrupt_generation_.load(std::memory_order_acquire)) { + if (action != InterruptAction::CaptureStack) { + SignalInterruptActionDone(); + } return; } - if (freeze_id == 0 || - freeze_id != active_freeze_id_.load(std::memory_order_acquire)) { - return; - } - if (!running_.load(std::memory_order_acquire)) { + if (!running_.load(std::memory_order_acquire) && + action != InterruptAction::ProfileDispose && + action != InterruptAction::ProfileStopAttach && + action != InterruptAction::ProfileStopDiscard) { + if (action != InterruptAction::CaptureStack) { + SignalInterruptActionDone(); + } return; } - // Keep this callback minimal: no logger, no N-API/TSFN, no metrics sample. - // Emitting via TSFN from a V8 interrupt re-enters Node on the isolate thread - // and can abort the process (seen with captureStack enabled). - std::vector frames = - CaptureJsStack(isolate, static_cast(max_frames)); - if (frames.empty()) { - return; - } + switch (action) { + case InterruptAction::CaptureStack: { + if (freeze_id == 0 || + freeze_id != active_freeze_id_.load(std::memory_order_acquire)) { + return; + } - { - std::lock_guard lock(stack_mutex_); - RecordStackSampleLocked(freeze_id, frames); - } + // Keep this callback minimal: no logger, no N-API/TSFN, no metrics sample. + std::vector frames = + CaptureJsStack(isolate, static_cast(max_frames)); + if (frames.empty()) { + return; + } + + { + std::lock_guard lock(stack_mutex_); + RecordStackSampleLocked(freeze_id, frames); + } - const uint64_t now = NowMs(); - const uint64_t last = last_kick_ms_.load(std::memory_order_acquire); - const uint64_t lag = now > last ? now - last : 0; + const uint64_t now = NowMs(); + const uint64_t last = last_kick_ms_.load(std::memory_order_acquire); + const uint64_t lag = now > last ? now - last : 0; + + Event event; + event.type = EventType::FreezeStack; + event.freeze_id = freeze_id; + event.duration_ms = lag; + event.threshold_ms = config_.freeze_threshold_ms; + event.heartbeat_ms = config_.heartbeat_ms; + event.sequence = sequence; + event.stack_status = StackStatus::Ok; + event.stack_mode = "interrupt"; + event.stack = std::move(frames); - Event event; - event.type = EventType::FreezeStack; - event.freeze_id = freeze_id; - event.duration_ms = lag; - event.threshold_ms = config_.freeze_threshold_ms; - event.heartbeat_ms = config_.heartbeat_ms; - event.sequence = sequence; - event.stack_status = StackStatus::Ok; - event.stack_mode = "interrupt"; - event.stack = std::move(frames); + { + std::lock_guard lock(pending_stack_mutex_); + pending_stack_event_ = std::move(event); + pending_stack_ready_ = true; + } + return; + } - { - std::lock_guard lock(pending_stack_mutex_); - pending_stack_event_ = std::move(event); - pending_stack_ready_ = true; + case InterruptAction::ProfileStart: { + if (profile_running_.load(std::memory_order_acquire)) { + profile_start_pending_.store(false, std::memory_order_release); + SignalInterruptActionDone(); + return; + } + const bool started = StartCpuProfiling(isolate, &cpu_profiler_); + profile_running_.store(started, std::memory_order_release); + profile_start_pending_.store(false, std::memory_order_release); + SignalInterruptActionDone(); + return; + } + + case InterruptAction::ProfileStopDiscard: { + if (profile_running_.load(std::memory_order_acquire) && + cpu_profiler_ != nullptr) { + v8::CpuProfile* profile = StopCpuProfiling(isolate, cpu_profiler_); + if (profile != nullptr) { + profile->Delete(); + } + } + profile_running_.store(false, std::memory_order_release); + profile_start_pending_.store(false, std::memory_order_release); + SignalInterruptActionDone(); + return; + } + + case InterruptAction::ProfileStopAttach: { + std::vector samples; + if (profile_running_.load(std::memory_order_acquire) && + cpu_profiler_ != nullptr) { + v8::CpuProfile* profile = StopCpuProfiling(isolate, cpu_profiler_); + if (profile != nullptr) { + samples = CollectCpuProfileSamples( + isolate, profile, static_cast(max_frames), + config_.capture_stack_max_samples); + profile->Delete(); + } + } + profile_running_.store(false, std::memory_order_release); + profile_start_pending_.store(false, std::memory_order_release); + + { + std::lock_guard lock(stack_mutex_); + ApplyProfileSamplesLocked(freeze_id, std::move(samples)); + } + SignalInterruptActionDone(); + return; + } + + case InterruptAction::ProfileDispose: { + if (profile_running_.load(std::memory_order_acquire) && + cpu_profiler_ != nullptr) { + v8::CpuProfile* profile = StopCpuProfiling(isolate, cpu_profiler_); + if (profile != nullptr) { + profile->Delete(); + } + } + profile_running_.store(false, std::memory_order_release); + profile_start_pending_.store(false, std::memory_order_release); + DisposeCpuProfiler(&cpu_profiler_); + SignalInterruptActionDone(); + return; + } } } @@ -229,6 +358,22 @@ void Watchdog::ClearStackAggregationLocked() { stacked_status_ = StackStatus::None; stacked_frames_.clear(); stacked_samples_.clear(); + stacked_mode_.clear(); +} + +void Watchdog::ApplyProfileSamplesLocked(uint64_t freeze_id, + std::vector samples) { + stacked_freeze_id_ = freeze_id; + stacked_mode_ = "profile"; + if (samples.empty()) { + stacked_status_ = StackStatus::Unavailable; + stacked_frames_.clear(); + stacked_samples_.clear(); + return; + } + stacked_status_ = StackStatus::Ok; + stacked_samples_ = std::move(samples); + stacked_frames_ = stacked_samples_.front().stack; } void Watchdog::RecordStackSampleLocked( @@ -236,6 +381,7 @@ void Watchdog::RecordStackSampleLocked( stacked_freeze_id_ = freeze_id; stacked_status_ = StackStatus::Ok; stacked_frames_ = frames; + stacked_mode_ = "interrupt"; for (StackSample& sample : stacked_samples_) { if (sample.stack == frames) { @@ -270,14 +416,38 @@ void Watchdog::DrainPendingStackEvent() { Emit(event); } +void Watchdog::FinalizeProfileForRecovered(uint64_t freeze_id) { + if (!IsProfileMode()) { + return; + } + if (!profile_running_.load(std::memory_order_acquire) && + !profile_start_pending_.load(std::memory_order_acquire)) { + std::lock_guard lock(stack_mutex_); + if (stacked_freeze_id_ != freeze_id) { + stacked_freeze_id_ = freeze_id; + stacked_status_ = StackStatus::Unavailable; + stacked_mode_ = "profile"; + stacked_frames_.clear(); + stacked_samples_.clear(); + } + return; + } + + RequestInterruptAction(InterruptAction::ProfileStopAttach, freeze_id, 0); + WaitInterruptAction(1000); +} + void Watchdog::AttachRecoveredStack(Event* event, uint64_t freeze_id) { if (!config_.capture_stack || event == nullptr) { return; } - event->stack_mode = "interrupt"; - std::lock_guard lock(stack_mutex_); + event->stack_mode = + stacked_mode_.empty() + ? (IsProfileMode() ? "profile" : "interrupt") + : stacked_mode_; + if (stacked_freeze_id_ == freeze_id && stacked_status_ == StackStatus::Ok && !stacked_samples_.empty()) { std::vector samples = stacked_samples_; @@ -344,6 +514,7 @@ void Watchdog::Emit(Event event) { void Watchdog::MonitorLoop() { bool frozen = false; + bool profile_armed = false; uint64_t freeze_began_at_ms = 0; uint64_t freeze_id = 0; uint64_t last_heartbeat_at_ms = 0; @@ -369,6 +540,28 @@ void Watchdog::MonitorLoop() { const uint64_t now = NowMs(); const uint64_t last = last_kick_ms_.load(std::memory_order_acquire); const uint64_t lag = now > last ? now - last : 0; + const uint32_t arm_ms = ProfileArmMs(); + + if (IsProfileMode()) { + if (!frozen && lag >= arm_ms) { + if (!profile_running_.load(std::memory_order_acquire) && + !profile_start_pending_.load(std::memory_order_acquire)) { + profile_start_pending_.store(true, std::memory_order_release); + profile_armed = true; + RequestInterruptAction(InterruptAction::ProfileStart, 0, 0); + } else { + profile_armed = true; + } + } else if (!frozen && profile_armed && lag < arm_ms) { + // False alarm: stop and discard without a freeze episode. + if (profile_running_.load(std::memory_order_acquire) || + profile_start_pending_.load(std::memory_order_acquire)) { + RequestInterruptAction(InterruptAction::ProfileStopDiscard, 0, 0); + WaitInterruptAction(500); + } + profile_armed = false; + } + } if (!frozen && lag >= config_.freeze_threshold_ms) { frozen = true; @@ -382,6 +575,7 @@ void Watchdog::MonitorLoop() { ClearStackAggregationLocked(); stacked_freeze_id_ = freeze_id; stacked_status_ = StackStatus::Unavailable; + stacked_mode_ = IsProfileMode() ? "profile" : "interrupt"; } { std::lock_guard lock(pending_stack_mutex_); @@ -389,8 +583,16 @@ void Watchdog::MonitorLoop() { pending_stack_event_ = Event{}; } emit(EventType::FreezeStarted, lag); - if (ShouldCaptureOnStarted()) { - RequestStackCapture(freeze_id, sequence); + if (IsProfileMode()) { + if (!profile_running_.load(std::memory_order_acquire) && + !profile_start_pending_.load(std::memory_order_acquire)) { + profile_start_pending_.store(true, std::memory_order_release); + RequestInterruptAction(InterruptAction::ProfileStart, freeze_id, 0); + } + profile_armed = true; + } else if (ShouldCaptureOnStarted()) { + RequestInterruptAction(InterruptAction::CaptureStack, freeze_id, + sequence); } } else if (frozen && lag >= config_.freeze_threshold_ms) { if (now - last_heartbeat_at_ms >= config_.heartbeat_ms) { @@ -398,14 +600,17 @@ void Watchdog::MonitorLoop() { last_heartbeat_at_ms = now; emit(EventType::FreezeHeartbeat, now - freeze_began_at_ms); if (ShouldCaptureOnHeartbeat()) { - RequestStackCapture(freeze_id, sequence); + RequestInterruptAction(InterruptAction::CaptureStack, freeze_id, + sequence); } } } else if (frozen && lag < config_.freeze_threshold_ms) { // Flush any stack sample captured just before recovery. DrainPendingStackEvent(); + FinalizeProfileForRecovered(freeze_id); emit(EventType::FreezeRecovered, now - freeze_began_at_ms); frozen = false; + profile_armed = false; freeze_began_at_ms = 0; last_heartbeat_at_ms = 0; sequence = 0; @@ -420,9 +625,15 @@ void Watchdog::MonitorLoop() { // Close out an in-flight freeze when stop() interrupts the monitor. if (frozen) { + FinalizeProfileForRecovered(freeze_id); const uint64_t now = NowMs(); emit(EventType::FreezeRecovered, now - freeze_began_at_ms); active_freeze_id_.store(0, std::memory_order_release); + } else if (IsProfileMode() && + (profile_running_.load(std::memory_order_acquire) || + profile_start_pending_.load(std::memory_order_acquire))) { + RequestInterruptAction(InterruptAction::ProfileStopDiscard, 0, 0); + WaitInterruptAction(500); } } diff --git a/native/watchdog.h b/native/watchdog.h index d5ec4c9..d84f824 100644 --- a/native/watchdog.h +++ b/native/watchdog.h @@ -12,6 +12,7 @@ namespace v8 { class Isolate; +class CpuProfiler; } namespace jsak { @@ -31,6 +32,19 @@ enum class StackCaptureOn : uint8_t { Both = 2, }; +enum class StackCaptureMode : uint8_t { + Interrupt = 0, + Profile = 1, +}; + +enum class InterruptAction : uint8_t { + CaptureStack = 0, + ProfileStart = 1, + ProfileStopDiscard = 2, + ProfileStopAttach = 3, + ProfileDispose = 4, +}; + struct Config { uint32_t freeze_threshold_ms = 1000; uint32_t heartbeat_ms = 1000; @@ -42,6 +56,7 @@ struct Config { // Optional app/service label; empty means omit `source` from payloads. std::string source; bool capture_stack = false; + StackCaptureMode capture_stack_mode = StackCaptureMode::Interrupt; StackCaptureOn capture_stack_on = StackCaptureOn::Both; uint32_t capture_stack_max_frames = 50; uint32_t capture_stack_max_samples = 8; @@ -106,7 +121,7 @@ struct Event { StackStatus stack_status = StackStatus::None; std::string stack_mode; std::vector stack; - // Aggregated unique stacks for this freeze (recovered only); empty otherwise. + // Aggregated unique stacks / profile hot paths (recovered); empty otherwise. std::vector stack_samples; }; @@ -119,13 +134,14 @@ struct InterruptGate { std::condition_variable cv; bool open = false; Watchdog* watchdog = nullptr; - // Active StackInterruptCallback bodies that may touch Watchdog without + // Active interrupt callback bodies that may touch Watchdog without // holding mutex (after the open/watchdog check). Stop waits for zero. int in_flight = 0; }; struct StackInterruptPayload { std::shared_ptr gate; + InterruptAction action = InterruptAction::CaptureStack; uint64_t freeze_id = 0; uint64_t generation = 0; uint32_t sequence = 0; @@ -151,18 +167,24 @@ class Watchdog { void Kick(); // Called from V8 interrupt on the isolate thread. - void OnStackInterrupt(v8::Isolate* isolate, uint64_t freeze_id, - uint64_t generation, uint32_t sequence, - uint32_t max_frames); + void OnInterrupt(v8::Isolate* isolate, InterruptAction action, + uint64_t freeze_id, uint64_t generation, uint32_t sequence, + uint32_t max_frames); private: void MonitorLoop(); void Emit(Event event); - void RequestStackCapture(uint64_t freeze_id, uint32_t sequence); + void RequestInterruptAction(InterruptAction action, uint64_t freeze_id, + uint32_t sequence); + bool WaitInterruptAction(uint32_t timeout_ms); + void SignalInterruptActionDone(); void DisableInterrupts(); + bool IsProfileMode() const; bool ShouldCaptureOnStarted() const; bool ShouldCaptureOnHeartbeat() const; + uint32_t ProfileArmMs() const; void AttachRecoveredStack(Event* event, uint64_t freeze_id); + void FinalizeProfileForRecovered(uint64_t freeze_id); // Publishes a freeze_stack queued by the V8 interrupt (monitor thread only). void DrainPendingStackEvent(); // Insert/increment a unique stack sample for the active freeze (caller holds @@ -170,6 +192,8 @@ class Watchdog { void RecordStackSampleLocked(uint64_t freeze_id, const std::vector& frames); void ClearStackAggregationLocked(); + void ApplyProfileSamplesLocked(uint64_t freeze_id, + std::vector samples); Config config_{}; EventCallback on_event_; @@ -197,12 +221,21 @@ class Watchdog { StackStatus stacked_status_ = StackStatus::None; std::vector stacked_frames_; std::vector stacked_samples_; + std::string stacked_mode_; // Set on isolate thread inside RequestInterrupt; drained on monitor thread. // Never call N-API / TSFN / logger from the interrupt callback. std::mutex pending_stack_mutex_; bool pending_stack_ready_ = false; Event pending_stack_event_; + + // CpuProfiler (profile mode). Touched only on isolate thread except atomics. + v8::CpuProfiler* cpu_profiler_ = nullptr; + std::atomic profile_running_{false}; + std::atomic profile_start_pending_{false}; + std::mutex profile_op_mutex_; + std::condition_variable profile_op_cv_; + bool profile_op_done_ = true; }; } // namespace watchdog diff --git a/src/config.js b/src/config.js index 6da59d6..77c8401 100644 --- a/src/config.js +++ b/src/config.js @@ -10,6 +10,13 @@ const DEFAULT_CAPTURE_STACK = Object.freeze({ maxSamples: 8, }); +const DEFAULT_CAPTURE_STACK_PROFILE = Object.freeze({ + mode: "profile", + on: "both", // ignored by native; kept for a stable normalized shape + maxFrames: 50, + maxSamples: 8, +}); + const DEFAULTS = Object.freeze({ freezeThresholdMs: 1000, heartbeatMs: 1000, @@ -82,16 +89,9 @@ function normalizeCaptureStack(value) { } const mode = options.mode === undefined ? DEFAULT_CAPTURE_STACK.mode : options.mode; - if (mode !== "interrupt") { - throw new TypeError( - `captureStack.mode must be "interrupt", got ${describeValue(mode)}`, - ); - } - - const on = options.on === undefined ? DEFAULT_CAPTURE_STACK.on : options.on; - if (!CAPTURE_STACK_ON.has(on)) { + if (mode !== "interrupt" && mode !== "profile") { throw new TypeError( - `captureStack.on must be one of "started", "heartbeat", "both", got ${describeValue(on)}`, + `captureStack.mode must be "interrupt" or "profile", got ${describeValue(mode)}`, ); } @@ -125,6 +125,22 @@ function normalizeCaptureStack(value) { ); } + if (mode === "profile") { + return Object.freeze({ + mode, + on: DEFAULT_CAPTURE_STACK_PROFILE.on, + maxFrames, + maxSamples, + }); + } + + const on = options.on === undefined ? DEFAULT_CAPTURE_STACK.on : options.on; + if (!CAPTURE_STACK_ON.has(on)) { + throw new TypeError( + `captureStack.on must be one of "started", "heartbeat", "both", got ${describeValue(on)}`, + ); + } + return Object.freeze({ mode, on, @@ -213,6 +229,7 @@ module.exports = { LIB, DEFAULTS, DEFAULT_CAPTURE_STACK, + DEFAULT_CAPTURE_STACK_PROFILE, LOG_TARGETS, CAPTURE_STACK_ON, MIN_MS, diff --git a/src/index.d.ts b/src/index.d.ts index b283157..5b9662c 100644 --- a/src/index.d.ts +++ b/src/index.d.ts @@ -1,15 +1,22 @@ declare namespace watchdog { export type CaptureStackOn = "started" | "heartbeat" | "both"; + export type CaptureStackMode = "interrupt" | "profile"; export interface CaptureStackConfig { - /** Capture strategy. Currently only V8 RequestInterrupt. Default: "interrupt". */ - mode?: "interrupt"; - /** When to request a stack sample. Default: "both". */ + /** + * Capture strategy. Default: "interrupt". + * "profile" uses V8 CpuProfiler over the stall (early-arm at threshold/2). + */ + mode?: CaptureStackMode; + /** + * When to request interrupt stack samples. Default: "both". + * Ignored when `mode` is `"profile"`. + */ on?: CaptureStackOn; - /** Max JS frames to capture. Default: 50. Range: 1..256. */ + /** Max JS frames to capture / path depth. Default: 50. Range: 1..256. */ maxFrames?: number; /** - * Max unique stack shapes retained per freeze for aggregation on recovered. + * Max unique stacks (interrupt) or top hot paths (profile) on recovered. * Default: 8. Range: 1..32. */ maxSamples?: number; @@ -56,7 +63,10 @@ declare namespace watchdog { export type StackStatus = "ok" | "unavailable"; export interface StackSample { - /** How many interrupt samples matched this stack shape during the freeze. */ + /** + * Interrupt: how many samples matched this stack. + * Profile: V8 CpuProfileNode hit count for this path. + */ count: number; /** Captured JS frames (`at ...`). */ stack: string[]; @@ -92,15 +102,15 @@ declare namespace watchdog { cpu_pct: number; /** Present when stack capture is enabled for this event. */ stack_status?: StackStatus; - /** Capture mode used for this stack sample. */ - stack_mode?: "interrupt"; + /** Capture mode used for this stack / profile sample. */ + stack_mode?: CaptureStackMode; /** * Captured JS frames (`at ...`); omitted when `stack_status` is not `"ok"`. - * On `freeze_recovered`, the most frequent sample across the freeze. + * On `freeze_recovered`, the most frequent interrupt sample or hottest profile path. */ stack?: string[]; /** - * Unique stacks sampled during the freeze, sorted by `count` descending. + * Unique stacks / hot paths, sorted by `count` descending. * Present on `freeze_recovered` when at least one sample succeeded. */ stack_samples?: StackSample[]; diff --git a/test/stack.integration.test.js b/test/stack.integration.test.js index 86aa81b..0c2a0e7 100644 --- a/test/stack.integration.test.js +++ b/test/stack.integration.test.js @@ -73,6 +73,20 @@ describe("captureStack config", () => { 32, ); }); + + it("accepts profile mode and ignores on", () => { + assert.deepEqual( + normalizeConfig({ + captureStack: { mode: "profile", on: "started", maxSamples: 4 }, + }).captureStack, + { + mode: "profile", + on: "both", + maxFrames: 50, + maxSamples: 4, + }, + ); + }); }); describe("captureStack interrupt", () => { @@ -222,3 +236,90 @@ describe("captureStack interrupt", () => { } }); }); + +describe("captureStack profile", () => { + const logFile = path.join( + os.tmpdir(), + `watchdog-profile-${process.pid}-${Date.now()}.log`, + ); + + before(() => { + watchdog.stop(); + watchdog.removeAllListeners(); + }); + + after(() => { + watchdog.stop(); + watchdog.removeAllListeners(); + try { + fs.unlinkSync(logFile); + } catch { + // ignore + } + }); + + it("attaches CpuProfiler hot paths on recovered", async () => { + const events = []; + const onEvent = (event) => events.push(event); + watchdog.on("event", onEvent); + + assert.equal( + watchdog.start({ + freezeThresholdMs: 100, + heartbeatMs: 80, + logTarget: "file", + logFile, + captureStack: { mode: "profile", maxSamples: 8 }, + }), + true, + ); + + await sleep(40); + // Long busy-wait so early-arm (threshold/2) and freeze both see JS samples. + busyWait(700); + await sleep(400); + + watchdog.off("event", onEvent); + watchdog.stop(); + + const types = events.map((event) => event.event); + assert.ok(types.includes("freeze_started"), `missing started: ${types}`); + assert.ok(types.includes("freeze_recovered"), `missing recovered: ${types}`); + assert.equal( + types.includes("freeze_stack"), + false, + `profile mode should not emit freeze_stack: ${types}`, + ); + + const recovered = events.find((event) => event.event === "freeze_recovered"); + assert.ok(recovered); + assert.equal(recovered.stack_mode, "profile"); + assert.equal(recovered.stack_status, "ok"); + assert.ok(Array.isArray(recovered.stack)); + assert.ok(recovered.stack.length > 0); + assert.ok(Array.isArray(recovered.stack_samples)); + assert.ok(recovered.stack_samples.length >= 1); + assert.ok(recovered.stack_samples[0].count >= 1); + assert.deepEqual(recovered.stack, recovered.stack_samples[0].stack); + assert.ok( + recovered.stack_samples.some((sample) => + sample.stack.some((frame) => /busyWait|Date\.now|at /.test(frame)), + ), + `unexpected profile frames: ${JSON.stringify(recovered.stack_samples.slice(0, 3))}`, + ); + + const lines = fs + .readFileSync(logFile, "utf8") + .split(/\r?\n/) + .map((line) => line.trim()) + .filter(Boolean) + .map((line) => JSON.parse(line)); + const recoveredLine = lines.find( + (event) => event.event === "freeze_recovered", + ); + assert.ok(recoveredLine); + assert.equal(recoveredLine.stack_mode, "profile"); + assert.equal(recoveredLine.stack_status, "ok"); + assert.ok(Array.isArray(recoveredLine.stack_samples)); + }); +});