From e749264c8ae3ee2d01adc439d9b496e192fb78a5 Mon Sep 17 00:00:00 2001 From: Anton Date: Thu, 23 Jul 2026 18:34:10 +0300 Subject: [PATCH 1/3] feat: aggregate interrupt stack samples per freeze Default captureStack on to both; attach stack_samples on recovered. --- ARCHITECTURE.md | 13 ++++- COMPATIBILITY.md | 9 +++- README.md | 15 ++++-- examples/log-max-bytes.js | 8 ++- native/addon.cpp | 35 +++++++++++++ native/logger.cpp | 18 +++++++ native/watchdog.cpp | 59 +++++++++++++++++---- native/watchdog.h | 28 +++++++++- src/config.js | 23 ++++++++- src/index.d.ts | 24 ++++++++- src/index.js | 3 ++ test/stack.integration.test.js | 93 ++++++++++++++++++++++++++++++++-- 12 files changed, 303 insertions(+), 25 deletions(-) diff --git a/ARCHITECTURE.md b/ARCHITECTURE.md index 7cb5528..73596ca 100644 --- a/ARCHITECTURE.md +++ b/ARCHITECTURE.md @@ -81,8 +81,15 @@ 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. +- 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. - Implemented in-core (experimental); not a separate package. @@ -137,6 +144,8 @@ Optional (experimental, when `captureStack` is enabled): - `stack_status` — `"ok"` \| `"unavailable"` - `stack_mode` — `"interrupt"` - `stack` — string frames; present only when `stack_status` is `"ok"` + (on recovered: most frequent sample) +- `stack_samples` — on recovered: `[{ count, stack }, ...]` sorted by count descending ## Error Handling and Safety diff --git a/COMPATIBILITY.md b/COMPATIBILITY.md index 877fc90..af05d33 100644 --- a/COMPATIBILITY.md +++ b/COMPATIBILITY.md @@ -40,16 +40,21 @@ 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`; + - 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"`); - - uses V8 `RequestInterrupt` (JS busy-loop stacks; sync I/O / native blocks may yield `unavailable`); + - 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); - 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 1017d32..e9c9b58 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): @@ -106,18 +106,22 @@ node examples/log-max-bytes.js 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"`. +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. + 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. +A future experimental CPU-profile mode (V8 `CpuProfiler` over the freeze window) is planned for stronger attribution; not available yet. + | 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"` only; `on`: `"started"` \| `"heartbeat"` \| `"both"`; `maxFrames`: `1..256`; `maxSamples`: `1..32` unique shapes retained per freeze | 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"` +- 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 - frames often contain absolute paths — keep logs access-controlled when capture is on ### Event payload @@ -141,6 +145,8 @@ When enabled, native logs / JS events may include: // stack_status: "ok" | "unavailable", // stack_mode: "interrupt", // stack: ["at busyWait (test.js:12:5)", ...], // omitted when unavailable + // on freeze_recovered when samples exist: + // stack_samples: [{ count: 3, stack: ["at busyWait ..."] }, ...], } ``` @@ -155,6 +161,7 @@ When enabled, native logs / JS events may include: | 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 | | `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..0e00575 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; @@ -321,6 +347,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/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..266182d 100644 --- a/native/watchdog.cpp +++ b/native/watchdog.cpp @@ -1,5 +1,6 @@ #include "watchdog.h" +#include #include #include "logger.h" @@ -92,6 +93,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; @@ -110,9 +113,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(); } { @@ -198,9 +199,7 @@ void Watchdog::OnStackInterrupt(v8::Isolate* isolate, uint64_t freeze_id, { std::lock_guard lock(stack_mutex_); - stacked_freeze_id_ = freeze_id; - stacked_status_ = StackStatus::Ok; - stacked_frames_ = frames; + RecordStackSampleLocked(freeze_id, frames); } const uint64_t now = NowMs(); @@ -225,6 +224,39 @@ void Watchdog::OnStackInterrupt(v8::Isolate* isolate, uint64_t freeze_id, } } +void Watchdog::ClearStackAggregationLocked() { + stacked_freeze_id_ = 0; + stacked_status_ = StackStatus::None; + stacked_frames_.clear(); + stacked_samples_.clear(); +} + +void Watchdog::RecordStackSampleLocked( + uint64_t freeze_id, const std::vector& frames) { + stacked_freeze_id_ = freeze_id; + stacked_status_ = StackStatus::Ok; + stacked_frames_ = frames; + + for (StackSample& sample : stacked_samples_) { + if (sample.stack == frames) { + sample.count += 1; + return; + } + } + + 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() { Event event; { @@ -247,14 +279,23 @@ void Watchdog::AttachRecoveredStack(Event* event, uint64_t freeze_id) { std::lock_guard lock(stack_mutex_); 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) { @@ -338,9 +379,9 @@ 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(); } { std::lock_guard lock(pending_stack_mutex_); diff --git a/native/watchdog.h b/native/watchdog.h index 3d5a3ca..d5ec4c9 100644 --- a/native/watchdog.h +++ b/native/watchdog.h @@ -42,13 +42,16 @@ 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; + 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 +63,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 +86,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 +106,8 @@ struct Event { StackStatus stack_status = StackStatus::None; std::string stack_mode; std::vector stack; + // Aggregated unique stacks for this freeze (recovered only); empty otherwise. + std::vector stack_samples; }; using EventCallback = std::function; @@ -145,6 +165,11 @@ class Watchdog { void AttachRecoveredStack(Event* event, 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(); Config config_{}; EventCallback on_event_; @@ -171,6 +196,7 @@ class Watchdog { uint64_t stacked_freeze_id_ = 0; StackStatus stacked_status_ = StackStatus::None; std::vector stacked_frames_; + std::vector stacked_samples_; // Set on isolate thread inside RequestInterrupt; drained on monitor thread. // Never call N-API / TSFN / logger from the interrupt callback. diff --git a/src/config.js b/src/config.js index 960b3b3..6da59d6 100644 --- a/src/config.js +++ b/src/config.js @@ -5,8 +5,9 @@ const LIB = "js-ak/watchdog"; const DEFAULT_CAPTURE_STACK = Object.freeze({ mode: "interrupt", - on: "started", + on: "both", maxFrames: 50, + maxSamples: 8, }); const DEFAULTS = Object.freeze({ @@ -26,6 +27,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; @@ -107,10 +110,26 @@ 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}`, + ); + } + return Object.freeze({ mode, on, maxFrames, + maxSamples, }); } @@ -200,6 +219,8 @@ module.exports = { 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..b283157 100644 --- a/src/index.d.ts +++ b/src/index.d.ts @@ -4,10 +4,15 @@ declare namespace watchdog { export interface CaptureStackConfig { /** Capture strategy. Currently only V8 RequestInterrupt. Default: "interrupt". */ mode?: "interrupt"; - /** When to request a stack sample. Default: "started". */ + /** When to request a stack sample. Default: "both". */ on?: CaptureStackOn; /** Max JS frames to capture. Default: 50. Range: 1..256. */ maxFrames?: number; + /** + * Max unique stack shapes retained per freeze for aggregation on recovered. + * Default: 8. Range: 1..32. + */ + maxSamples?: number; } export interface WatchdogConfig { @@ -50,6 +55,13 @@ declare namespace watchdog { export type StackStatus = "ok" | "unavailable"; + export interface StackSample { + /** How many interrupt samples matched this stack shape during the freeze. */ + 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. @@ -82,8 +94,16 @@ declare namespace watchdog { stack_status?: StackStatus; /** Capture mode used for this stack sample. */ stack_mode?: "interrupt"; - /** Captured JS frames (`at ...`); omitted when `stack_status` is not `"ok"`. */ + /** + * Captured JS frames (`at ...`); omitted when `stack_status` is not `"ok"`. + * On `freeze_recovered`, the most frequent sample across the freeze. + */ stack?: string[]; + /** + * Unique stacks sampled during the freeze, 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/stack.integration.test.js b/test/stack.integration.test.js index d25cf30..4312d75 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,31 @@ 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, + ); }); }); @@ -54,7 +80,7 @@ describe("captureStack interrupt", () => { os.tmpdir(), `watchdog-stack-${process.pid}-${Date.now()}.log`, ); - + before(() => { watchdog.stop(); watchdog.removeAllListeners(); @@ -117,6 +143,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 +161,62 @@ 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: 50, + logTarget: "file", + logFile, + captureStack: { on: "both", maxSamples: 8 }, + }), + true, + ); + + await sleep(40); + busyWait(450); + await sleep(350); + + watchdog.off("event", onEvent); + watchdog.stop(); + + const freezeStacks = events.filter( + (event) => event.event === "freeze_stack", + ); + assert.ok( + freezeStacks.length >= 2, + `expected multiple 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, + ); + } }); }); From 8a16bb8005684665daccce6acd3db36c42167285 Mon Sep 17 00:00:00 2001 From: Anton Date: Thu, 23 Jul 2026 19:13:24 +0300 Subject: [PATCH 2/3] test: harden freeze timing on slow CI runners --- test/hardening.test.js | 15 ++++++++++----- test/stack.integration.test.js | 12 +++++++----- 2 files changed, 17 insertions(+), 10 deletions(-) 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 4312d75..86aa81b 100644 --- a/test/stack.integration.test.js +++ b/test/stack.integration.test.js @@ -173,7 +173,7 @@ describe("captureStack interrupt", () => { assert.equal( watchdog.start({ freezeThresholdMs: 80, - heartbeatMs: 50, + heartbeatMs: 40, logTarget: "file", logFile, captureStack: { on: "both", maxSamples: 8 }, @@ -182,8 +182,10 @@ describe("captureStack interrupt", () => { ); await sleep(40); - busyWait(450); - await sleep(350); + // 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(); @@ -192,8 +194,8 @@ describe("captureStack interrupt", () => { (event) => event.event === "freeze_stack", ); assert.ok( - freezeStacks.length >= 2, - `expected multiple freeze_stack, got ${freezeStacks.length}`, + freezeStacks.length >= 1, + `expected at least one freeze_stack, got ${freezeStacks.length}`, ); const recovered = events.find((event) => event.event === "freeze_recovered"); From d163152678a62eda0320a18206bf5e6952faf27d Mon Sep 17 00:00:00 2001 From: Anton Date: Thu, 23 Jul 2026 21:10:03 +0300 Subject: [PATCH 3/3] 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)); + }); +});