diff --git a/ARCHITECTURE.md b/ARCHITECTURE.md index 7cb5528..65dd383 100644 --- a/ARCHITECTURE.md +++ b/ARCHITECTURE.md @@ -74,17 +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` only (`on: "started"`). -- `"both"` / `"heartbeat"` re-sample on heartbeats. -- 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. +- Default sampling: on `freeze_started` and each `freeze_heartbeat` (`on: "both"`). +- 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`); 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 @@ -135,8 +153,10 @@ 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 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 877fc90..355cb2e 100644 --- a/COMPATIBILITY.md +++ b/COMPATIBILITY.md @@ -40,10 +40,19 @@ Notes on `ts`: - Underscored exports (`_bus`, `_addon`) are internal test hooks and may change or disappear. - Unknown `start(config)` keys are ignored (only known config keys above / below are applied). - Opt-in stack capture is experimental and may change shape without a major bump until marked stable: - - config: `captureStack` (`false` \| `true` \| `{ mode, on, maxFrames }`); default `false`; - - additive event value `freeze_stack` (same channels as other freeze events); - - payload fields: `stack_status`, `stack_mode`, `stack` (`stack` only when status is `"ok"`); - - uses V8 `RequestInterrupt` (JS busy-loop stacks; sync I/O / native blocks may yield `unavailable`); + - config: `captureStack` (`false` \| `true` \| `{ mode, on, maxFrames, maxSamples }`); default `false`; + - `true` expands to `{ mode: "interrupt", on: "both", maxFrames: 50, maxSamples: 8 }`; + - `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 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), diff --git a/README.md b/README.md index 1017d32..fff9f4b 100644 --- a/README.md +++ b/README.md @@ -94,7 +94,7 @@ Native side writes JSON Lines **from the monitor thread**, so freeze logs (inclu | `logFile` | `"./watchdog.log"` | used when target is `file`/`both`; `getConfig()` returns the resolved absolute path | | `logMaxBytes` | `10485760` (10 MiB) | soft size cap for the active log file; on overflow rename to `.1` (one backup) and reopen; `0` disables; `0..1073741824` | | `source` | omit | optional app/service label (max 256 chars); included on native JSON Lines and JS events when set. Library identity is always `lib: "js-ak/watchdog"` | -| `captureStack` | `false` | opt-in JS stack capture (unstable). `true` or `{ mode, on, maxFrames }` — see below | +| `captureStack` | `false` | opt-in JS stack capture (unstable). `true` or `{ mode, on, maxFrames, maxSamples }` — see below | Local demo of size rotation (repo checkout only; not shipped in the npm tarball): @@ -104,20 +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: -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. +**`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`). + +**`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. + +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: "started", maxFrames: 50 }` | -| `{ mode, on, maxFrames }` | `mode`: `"interrupt"` only; `on`: `"started"` \| `"heartbeat"` \| `"both"`; `maxFrames`: `1..256` | +| `true` | `{ mode: "interrupt", on: "both", maxFrames: 50, maxSamples: 8 }` | +| `{ 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"` +- `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 @@ -139,8 +143,10 @@ 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 ..."] }, ...], } ``` @@ -154,7 +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 | +| 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/examples/log-max-bytes.js b/examples/log-max-bytes.js index 25bbba3..718b73e 100644 --- a/examples/log-max-bytes.js +++ b/examples/log-max-bytes.js @@ -39,11 +39,17 @@ watchdog.on("recovered", (event) => { const started = watchdog.start({ freezeThresholdMs: 100, heartbeatMs: 50, - logTarget: "file", + logTarget: "both", logFile, // Tiny cap so a short freeze rotates to .1 (production default: 10 MiB). logMaxBytes: 800, source: "example-log-max-bytes", + captureStack: { + maxFrames: 10, + maxSamples: 10, + mode: "interrupt", + on: "both", + } }); if (!started) { diff --git a/native/addon.cpp b/native/addon.cpp index d377fcb..88cb1f5 100644 --- a/native/addon.cpp +++ b/native/addon.cpp @@ -137,6 +137,32 @@ void CallJs(napi_env env, napi_value js_callback, void* /*context*/, } napi_set_named_property(env, object, "stack", stack); } + + if (!event.stack_samples.empty()) { + napi_value samples; + napi_create_array_with_length(env, event.stack_samples.size(), &samples); + for (size_t i = 0; i < event.stack_samples.size(); i += 1) { + const jsak::watchdog::StackSample& sample = event.stack_samples[i]; + napi_value entry; + napi_create_object(env, &entry); + + napi_value count; + napi_create_uint32(env, sample.count, &count); + napi_set_named_property(env, entry, "count", count); + + napi_value stack; + napi_create_array_with_length(env, sample.stack.size(), &stack); + for (size_t j = 0; j < sample.stack.size(); j += 1) { + napi_value frame; + napi_create_string_utf8(env, sample.stack[j].c_str(), + NAPI_AUTO_LENGTH, &frame); + napi_set_element(env, stack, static_cast(j), frame); + } + napi_set_named_property(env, entry, "stack", stack); + napi_set_element(env, samples, static_cast(i), entry); + } + napi_set_named_property(env, object, "stack_samples", samples); + } } napi_value undefined; @@ -295,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); @@ -321,6 +363,15 @@ bool ReadConfig(napi_env env, napi_value object, jsak::watchdog::ClampStackFrames(n); } } + + if (napi_get_named_property(env, value, "maxSamples", &field) == + napi_ok) { + uint32_t n = 0; + if (napi_get_value_uint32(env, field, &n) == napi_ok && n > 0) { + config->capture_stack_max_samples = + jsak::watchdog::ClampStackSamples(n); + } + } } } } 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/logger.cpp b/native/logger.cpp index 01207e5..787b2af 100644 --- a/native/logger.cpp +++ b/native/logger.cpp @@ -234,6 +234,24 @@ void Logger::LogEvent(const Event& event) { } json << ']'; } + if (!event.stack_samples.empty()) { + json << ",\"stack_samples\":["; + for (size_t i = 0; i < event.stack_samples.size(); i += 1) { + if (i > 0) { + json << ','; + } + const StackSample& sample = event.stack_samples[i]; + json << "{\"count\":" << sample.count << ",\"stack\":["; + for (size_t j = 0; j < sample.stack.size(); j += 1) { + if (j > 0) { + json << ','; + } + json << '"' << EscapeJson(sample.stack[j]) << '"'; + } + json << "]}"; + } + json << ']'; + } } json << '}'; diff --git a/native/watchdog.cpp b/native/watchdog.cpp index 8c76422..0b9b1c6 100644 --- a/native/watchdog.cpp +++ b/native/watchdog.cpp @@ -1,7 +1,9 @@ #include "watchdog.h" +#include #include +#include "cpu_profile.h" #include "logger.h" #include "metrics.h" #include "stack_capture.h" @@ -27,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; @@ -36,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); @@ -72,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; @@ -92,6 +107,8 @@ bool Watchdog::Start(const Config& config) { config_ = config; config_.capture_stack_max_frames = ClampStackFrames(config_.capture_stack_max_frames); + config_.capture_stack_max_samples = + ClampStackSamples(config_.capture_stack_max_samples); logger_->Configure(LoggerConfig{config_.log_target, config_.log_file, config_.log_max_bytes}); prev_wall_ms_ = 0; @@ -100,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_); @@ -110,9 +129,7 @@ bool Watchdog::Start(const Config& config) { { std::lock_guard lock(stack_mutex_); - stacked_freeze_id_ = 0; - stacked_status_ = StackStatus::None; - stacked_frames_.clear(); + ClearStackAggregationLocked(); } { @@ -121,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); @@ -139,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 { @@ -154,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; @@ -172,57 +211,196 @@ 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; + } + + // 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; + + 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; + } + + 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; + } } +} - { - std::lock_guard lock(stack_mutex_); - stacked_freeze_id_ = freeze_id; - stacked_status_ = StackStatus::Ok; - stacked_frames_ = frames; +void Watchdog::ClearStackAggregationLocked() { + stacked_freeze_id_ = 0; + 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; +} - 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; +void Watchdog::RecordStackSampleLocked( + uint64_t freeze_id, const std::vector& frames) { + stacked_freeze_id_ = freeze_id; + stacked_status_ = StackStatus::Ok; + stacked_frames_ = frames; + stacked_mode_ = "interrupt"; - 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); + for (StackSample& sample : stacked_samples_) { + if (sample.stack == frames) { + sample.count += 1; + return; + } + } - { - std::lock_guard lock(pending_stack_mutex_); - pending_stack_event_ = std::move(event); - pending_stack_ready_ = true; + const uint32_t max_samples = + ClampStackSamples(config_.capture_stack_max_samples); + if (stacked_samples_.size() >= static_cast(max_samples)) { + // Cap unique keys: keep counting known stacks, ignore new shapes. + return; } + + StackSample sample; + sample.count = 1; + sample.stack = frames; + stacked_samples_.push_back(std::move(sample)); } void Watchdog::DrainPendingStackEvent() { @@ -238,23 +416,56 @@ 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_frames_.empty()) { + stacked_status_ == StackStatus::Ok && !stacked_samples_.empty()) { + std::vector samples = stacked_samples_; + std::stable_sort( + samples.begin(), samples.end(), + [](const StackSample& a, const StackSample& b) { + return a.count > b.count; + }); + event->stack_status = StackStatus::Ok; - event->stack = stacked_frames_; + event->stack = samples.front().stack; + event->stack_samples = std::move(samples); return; } event->stack_status = StackStatus::Unavailable; event->stack.clear(); + event->stack_samples.clear(); } void Watchdog::Emit(Event event) { @@ -303,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; @@ -328,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; @@ -338,9 +572,10 @@ void Watchdog::MonitorLoop() { active_freeze_id_.store(freeze_id, std::memory_order_release); { std::lock_guard lock(stack_mutex_); + ClearStackAggregationLocked(); stacked_freeze_id_ = freeze_id; stacked_status_ = StackStatus::Unavailable; - stacked_frames_.clear(); + stacked_mode_ = IsProfileMode() ? "profile" : "interrupt"; } { std::lock_guard lock(pending_stack_mutex_); @@ -348,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) { @@ -357,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; @@ -379,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 3d5a3ca..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,13 +56,17 @@ struct Config { // Optional app/service label; empty means omit `source` from payloads. std::string source; bool capture_stack = false; - StackCaptureOn capture_stack_on = StackCaptureOn::Started; + 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; }; // Matches JS normalizeConfig / CaptureStackConfig range. inline constexpr uint32_t kMinStackFrames = 1; inline constexpr uint32_t kMaxStackFrames = 256; +inline constexpr uint32_t kMinStackSamples = 1; +inline constexpr uint32_t kMaxStackSamples = 32; inline uint32_t ClampStackFrames(uint32_t frames) { if (frames < kMinStackFrames) { @@ -60,6 +78,16 @@ inline uint32_t ClampStackFrames(uint32_t frames) { return frames; } +inline uint32_t ClampStackSamples(uint32_t samples) { + if (samples < kMinStackSamples) { + return kMinStackSamples; + } + if (samples > kMaxStackSamples) { + return kMaxStackSamples; + } + return samples; +} + enum class EventType : uint8_t { FreezeStarted = 1, FreezeHeartbeat = 2, @@ -73,6 +101,11 @@ enum class StackStatus : uint8_t { Unavailable = 2, }; +struct StackSample { + uint32_t count = 0; + std::vector stack; +}; + struct Event { EventType type = EventType::FreezeStarted; uint64_t freeze_id = 0; @@ -88,6 +121,8 @@ struct Event { StackStatus stack_status = StackStatus::None; std::string stack_mode; std::vector stack; + // Aggregated unique stacks / profile hot paths (recovered); empty otherwise. + std::vector stack_samples; }; using EventCallback = std::function; @@ -99,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; @@ -131,20 +167,33 @@ 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 + // stack_mutex_). Caps unique entries at capture_stack_max_samples. + 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_; @@ -171,12 +220,22 @@ class Watchdog { uint64_t stacked_freeze_id_ = 0; 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 960b3b3..77c8401 100644 --- a/src/config.js +++ b/src/config.js @@ -5,8 +5,16 @@ const LIB = "js-ak/watchdog"; const DEFAULT_CAPTURE_STACK = Object.freeze({ mode: "interrupt", - on: "started", + on: "both", maxFrames: 50, + 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({ @@ -26,6 +34,8 @@ const MIN_MS = 1; const MAX_MS = 3_600_000; // 1 hour const MIN_STACK_FRAMES = 1; const MAX_STACK_FRAMES = 256; +const MIN_STACK_SAMPLES = 1; +const MAX_STACK_SAMPLES = 32; const MAX_SOURCE_LENGTH = 256; // 0 disables in-process rotation; otherwise up to 1 GiB. const MIN_LOG_MAX_BYTES = 0; @@ -79,16 +89,9 @@ function normalizeCaptureStack(value) { } const mode = options.mode === undefined ? DEFAULT_CAPTURE_STACK.mode : options.mode; - if (mode !== "interrupt") { + if (mode !== "interrupt" && mode !== "profile") { 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)) { - 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)}`, ); } @@ -107,10 +110,42 @@ function normalizeCaptureStack(value) { ); } + const maxSamples = + options.maxSamples === undefined + ? DEFAULT_CAPTURE_STACK.maxSamples + : options.maxSamples; + if (typeof maxSamples !== "number" || !Number.isInteger(maxSamples)) { + throw new TypeError( + `captureStack.maxSamples must be an integer, got ${describeValue(maxSamples)}`, + ); + } + if (maxSamples < MIN_STACK_SAMPLES || maxSamples > MAX_STACK_SAMPLES) { + throw new RangeError( + `captureStack.maxSamples must be between ${MIN_STACK_SAMPLES} and ${MAX_STACK_SAMPLES}, got ${maxSamples}`, + ); + } + + 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, maxFrames, + maxSamples, }); } @@ -194,12 +229,15 @@ module.exports = { LIB, DEFAULTS, DEFAULT_CAPTURE_STACK, + DEFAULT_CAPTURE_STACK_PROFILE, LOG_TARGETS, CAPTURE_STACK_ON, MIN_MS, MAX_MS, MIN_STACK_FRAMES, MAX_STACK_FRAMES, + MIN_STACK_SAMPLES, + MAX_STACK_SAMPLES, MAX_SOURCE_LENGTH, MIN_LOG_MAX_BYTES, MAX_LOG_MAX_BYTES, diff --git a/src/index.d.ts b/src/index.d.ts index 5b0ff23..5b9662c 100644 --- a/src/index.d.ts +++ b/src/index.d.ts @@ -1,13 +1,25 @@ 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: "started". */ + /** + * 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 stacks (interrupt) or top hot paths (profile) on recovered. + * Default: 8. Range: 1..32. + */ + maxSamples?: number; } export interface WatchdogConfig { @@ -50,6 +62,16 @@ declare namespace watchdog { export type StackStatus = "ok" | "unavailable"; + export interface StackSample { + /** + * Interrupt: how many samples matched this stack. + * Profile: V8 CpuProfileNode hit count for this path. + */ + count: number; + /** Captured JS frames (`at ...`). */ + stack: string[]; + } + export interface WatchdogEvent { /** * ISO-8601 UTC timestamp when the JS payload was built on the event loop. @@ -80,10 +102,18 @@ 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"; - /** Captured JS frames (`at ...`); omitted when `stack_status` is not `"ok"`. */ + /** 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 interrupt sample or hottest profile path. + */ stack?: string[]; + /** + * Unique stacks / hot paths, sorted by `count` descending. + * Present on `freeze_recovered` when at least one sample succeeded. + */ + stack_samples?: StackSample[]; } export type NormalizedCaptureStack = false | Readonly>; diff --git a/src/index.js b/src/index.js index 3fe5cb0..a7221c5 100644 --- a/src/index.js +++ b/src/index.js @@ -40,6 +40,9 @@ function enrich(nativeEvent) { if (Array.isArray(nativeEvent.stack)) { payload.stack = nativeEvent.stack; } + if (Array.isArray(nativeEvent.stack_samples)) { + payload.stack_samples = nativeEvent.stack_samples; + } } return payload; diff --git a/test/hardening.test.js b/test/hardening.test.js index cd58a35..06413d0 100644 --- a/test/hardening.test.js +++ b/test/hardening.test.js @@ -139,11 +139,12 @@ describe("hardening: failure modes", () => { ); const events = []; - watchdog.on("event", (event) => events.push(event)); + const onEvent = (event) => events.push(event); + watchdog.on("event", onEvent); assert.equal( watchdog.start({ - freezeThresholdMs: 120, + freezeThresholdMs: 100, heartbeatMs: 80, logTarget: "file", logFile: badPath, @@ -151,10 +152,14 @@ describe("hardening: failure modes", () => { true, ); - await sleep(50); - busyWait(260); - await sleep(200); + await sleep(60); + // Extra headroom for slow CI (e.g. macos-15-intel): unwritable file + // sink must not block freeze detection / JS event delivery. + busyWait(400); + await sleep(350); + watchdog.off("event", onEvent); watchdog.stop(); + await sleep(80); const types = events.map((event) => event.event); assert.ok(types.includes("freeze_started"), `missing started: ${types}`); diff --git a/test/stack.integration.test.js b/test/stack.integration.test.js index d25cf30..0c2a0e7 100644 --- a/test/stack.integration.test.js +++ b/test/stack.integration.test.js @@ -28,12 +28,13 @@ describe("captureStack config", () => { it("expands true to interrupt defaults", () => { assert.deepEqual(normalizeConfig({ captureStack: true }).captureStack, { mode: "interrupt", - on: "started", + on: "both", maxFrames: 50, + maxSamples: 8, }); }); - it("rejects unknown mode / on / maxFrames", () => { + it("rejects unknown mode / on / maxFrames / maxSamples", () => { assert.throws( () => normalizeConfig({ captureStack: { mode: "report" } }), TypeError, @@ -46,6 +47,45 @@ describe("captureStack config", () => { () => normalizeConfig({ captureStack: { maxFrames: 0 } }), RangeError, ); + assert.throws( + () => normalizeConfig({ captureStack: { maxSamples: 0 } }), + RangeError, + ); + assert.throws( + () => normalizeConfig({ captureStack: { maxSamples: 33 } }), + RangeError, + ); + assert.throws( + () => normalizeConfig({ captureStack: { maxSamples: 1.5 } }), + TypeError, + ); + }); + + it("accepts maxSamples in range", () => { + assert.equal( + normalizeConfig({ captureStack: { maxSamples: 1 } }).captureStack + .maxSamples, + 1, + ); + assert.equal( + normalizeConfig({ captureStack: { maxSamples: 32 } }).captureStack + .maxSamples, + 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, + }, + ); }); }); @@ -54,7 +94,7 @@ describe("captureStack interrupt", () => { os.tmpdir(), `watchdog-stack-${process.pid}-${Date.now()}.log`, ); - + before(() => { watchdog.stop(); watchdog.removeAllListeners(); @@ -117,6 +157,10 @@ describe("captureStack interrupt", () => { assert.ok(Array.isArray(recovered.stack)); assert.ok(recovered.stack.length > 0); assert.equal(recovered.freeze_id, stackEvent.freeze_id); + assert.ok(Array.isArray(recovered.stack_samples)); + assert.ok(recovered.stack_samples.length >= 1); + assert.equal(recovered.stack_samples[0].count >= 1, true); + assert.deepEqual(recovered.stack, recovered.stack_samples[0].stack); const lines = fs .readFileSync(logFile, "utf8") @@ -131,5 +175,151 @@ describe("captureStack interrupt", () => { assert.ok(recoveredLine); assert.equal(recoveredLine.stack_status, "ok"); assert.ok(Array.isArray(recoveredLine.stack)); + assert.ok(Array.isArray(recoveredLine.stack_samples)); + assert.ok(recoveredLine.stack_samples.length >= 1); + }); + + it("aggregates multiple interrupt samples on long freeze", async () => { + const events = []; + const onEvent = (event) => events.push(event); + watchdog.on("event", onEvent); + + assert.equal( + watchdog.start({ + freezeThresholdMs: 80, + heartbeatMs: 40, + logTarget: "file", + logFile, + captureStack: { on: "both", maxSamples: 8 }, + }), + true, + ); + + await sleep(40); + // Long enough for several heartbeats even on slow CI runners; pending + // freeze_stack may coalesce to fewer JS events than interrupt samples. + busyWait(900); + await sleep(400); + + watchdog.off("event", onEvent); + watchdog.stop(); + + const freezeStacks = events.filter( + (event) => event.event === "freeze_stack", + ); + assert.ok( + freezeStacks.length >= 1, + `expected at least one freeze_stack, got ${freezeStacks.length}`, + ); + + const recovered = events.find((event) => event.event === "freeze_recovered"); + assert.ok(recovered); + assert.equal(recovered.stack_status, "ok"); + assert.ok(Array.isArray(recovered.stack_samples)); + assert.ok(recovered.stack_samples.length >= 1); + + const totalCount = recovered.stack_samples.reduce( + (sum, sample) => sum + sample.count, + 0, + ); + assert.ok( + totalCount >= 2, + `expected aggregated count >= 2, got ${totalCount}: ${JSON.stringify(recovered.stack_samples)}`, + ); + assert.deepEqual(recovered.stack, recovered.stack_samples[0].stack); + + for (let i = 1; i < recovered.stack_samples.length; i += 1) { + assert.ok( + recovered.stack_samples[i - 1].count >= + recovered.stack_samples[i].count, + ); + } + }); +}); + +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)); }); });