diff --git a/openspec/changes/sbmd-observability-instrumentation/.openspec.yaml b/openspec/changes/sbmd-observability-instrumentation/.openspec.yaml new file mode 100644 index 00000000..64105fc9 --- /dev/null +++ b/openspec/changes/sbmd-observability-instrumentation/.openspec.yaml @@ -0,0 +1,2 @@ +schema: spec-driven +created: 2026-07-14 diff --git a/openspec/changes/sbmd-observability-instrumentation/design.md b/openspec/changes/sbmd-observability-instrumentation/design.md new file mode 100644 index 00000000..88813676 --- /dev/null +++ b/openspec/changes/sbmd-observability-instrumentation/design.md @@ -0,0 +1,171 @@ +## Context + +SBMDv4 runs all device driver JavaScript through a single shared mquickjs context — a pre-allocated, fixed-size arena (configurable via `BARTON_CONFIG_MQUICKJS_MEMSIZE_BYTES`, default 1 MB) protected by a single mutex. Every resource read/write/execute, attribute report, and event goes through `SbmdHandlerInvoker::InvokeHandler`, which is called with this mutex already held by the caller. Because all drivers compete for the same runtime, the JS context is the primary resource bottleneck of the SBMD subsystem. + +The existing observability infrastructure (`core/src/observability/`) provides counter, gauge, and histogram instruments with a JSON dump API. The dump API (`observabilityDumpJson()`) is already called in production (e.g., `b_core_client_get_telemetry()`), but the metric-recording call sites — `observabilityCounterAdd`, `observabilityGaugeRecord`, `observabilityHistogramRecord` — have zero production callers today. + +This design covers how to wire the observability API into the SBMD runtime without modifying the observability infrastructure itself. + +## Goals / Non-Goals + +**Goals:** +- Instrument all meaningful SBMD runtime events using the existing observability API +- Each module instruments itself; metric handles live in the module that records them +- Provide a synchronous `ForceSnapshot()` API for on-demand telemetry and tests (usable without holding the JS mutex) +- Attribute per-driver and per-operation-type metrics using the `"driver"`, `"op_type"`, and `"resource_id"` attribute keys +- Test all metric wiring using the real mquickjs runtime (no mocking required) + +**Non-Goals:** +- Changes to `core/src/observability/` infrastructure +- Implicit or explicit GC tracking (follow-on) +- `deviceId` attribute (follow-on) +- Production/fleet identifier attributes + +## Decisions + +### Decision 1: Distributed metric ownership + +Metric handles (histograms, gauges, counters) are private static members of the module that records them. Each module provides `static void InitializeMetrics()` and `static void ShutdownMetrics()` functions. `SbmdFactory::RegisterDriversFromDirectory` calls `MQuickJsRuntime::InitializeMetrics()` **before** `MQuickJsRuntime::Initialize()` so that the `sbmd.js.exception` counter is live for init-phase exceptions; the remaining three `InitializeMetrics()` calls are made after `MQuickJsRuntime::Initialize()` succeeds. + +| Module | Metric handles owned | +|---|---| +| `MQuickJsRuntime` | `sbmd.js.heap.*`, `sbmd.js.mutex.wait_ms`, `sbmd.js.exception` | +| `SbmdHandlerInvoker` | `sbmd.handler.duration_ms`, `sbmd.handler.heap_delta_bytes`, `sbmd.handler.outcome` | +| `SbmdFactory` | `sbmd.driver.load.*`, `sbmd.driver.registered.count` | +| `SpecBasedMatterDeviceDriver` | `sbmd.deferred.*` | + +**Cross-module recording:** Two cases require cross-module calls: +- `sbmd.handler.outcome{outcome="error"}` is detected in `SpecBasedMatterDeviceDriver` after `InvokeHandler` returns, but the handle lives in `SbmdHandlerInvoker`. `SbmdHandlerInvoker` exposes `static void RecordOutcomeError(const char *driver, const char *opType, const char *resourceId)`. +- `sbmd.js.mutex.wait_ms` is measured at every mutex acquisition site in `SpecBasedMatterDeviceDriver` — `HandleResourceOp`, the attribute/event handler paths, and the deferred callback paths (`HandleDeferredCommandResponse`, `HandleDeferredCommandError`, `ContinueDeferredChain`). `sbmd.js.heap.*` pool health metrics are recorded from `SbmdHandlerInvoker::InvokeHandler`, and `sbmd.js.exception` is recorded from `SbmdLoader` and `SbmdBundleLoader`. All three sets of handles live in `MQuickJsRuntime`, which exposes `static void RecordMutexWait(double ms)`, `static void RecordJsException(const char *phase, const char *driver)`, and `static void RecordHeapSnapshot(const JSMemoryUsage &usage)` (requires caller to hold the JS mutex). + +**Why not create instruments inline at each call site?** Instrument creation has overhead and the observability spec requires a handle to persist for the lifetime of measurements. Handles are created once in `InitializeMetrics()` and persist until `ShutdownMetrics()`. + +### Decision 2: `SbmdHandlerInvoker::InvokeHandler` invocation context parameter + +`InvokeHandler` is extended with a single optional parameter: `const OperationContext *opCtx = nullptr`. `OperationContext` is a plain struct defined in `SbmdHandlerInvoker.h`: + +```cpp +struct OperationContext { + const char *driverName = nullptr; + const char *opType = nullptr; // originating op type (e.g., "write", "execute") + const char *resourceId = nullptr; // resource ID for resource ops; null for attribute/event handlers + std::chrono::steady_clock::time_point startTime; + // extensible: add fields here without touching InvokeHandler's signature again +}; +``` + +All existing callers compile unchanged (null default). **Two distinct calling patterns:** + +- **Synchronous ops** (`HandleResourceOp`): caller stack-allocates `OperationContext` with `driverName`, `opType`, `resourceId` (from `resource->id`), and `startTime = steady_clock::now()`, and passes `&opCtx`. Lifetime is that single call. +- **Deferred ops** (`HandleDeferredCommandResponse`, `HandleDeferredCommandError`, `ContinueDeferredChain`): caller passes `&pending.operationCtx` — the same object initialized when the `PendingOperation` was created and alive for the entire deferred chain. + +**Why a struct rather than individual parameters?** A single stable context slot avoids an ever-growing signature as requirements evolve. New fields are added to the struct without touching `InvokeHandler`'s signature or any call site. The context also carries natural operation-scope lifetime semantics: for deferred operations it is the same object from `ExecuteRequestCommand` through `CompletePendingOperation`, enabling `CompletePendingOperation` to read `startTime` from the same context that was active during every `InvokeHandler` call in the chain. + +**What is measured (window: immediately before `JS_PushArg` through immediately after `JS_Call` returns):** +- `steady_clock::now()` before `JS_PushArg` and after `JS_Call` → invocation duration histogram +- `JS_GetMemoryUsage` before `JS_PushArg` and after `JS_Call` → heap delta histogram (includes argument-marshalling allocations) +- Exception / timeout / stack overflow distinction → outcome counter + +### Decision 3: Hybrid sampling — in-activity captures + tickleable idle thread + +Pool health metrics (`sbmd.js.heap.*`) are recorded from two complementary paths: + +**In-activity path:** At the end of every `InvokeHandler` call, while the JS mutex is already held by the caller, `MQuickJsRuntime::RecordHeapSnapshot(const JSMemoryUsage &usage)` updates the pool health metrics (`sbmd.js.heap.used_bytes` histogram and `free_bytes`/`peak_bytes` gauges) using the `JSMemoryUsage` struct already captured by the post-`JS_Call` `JS_GetMemoryUsage` call — no additional JS engine call is needed. `InvokeHandler` then calls `MQuickJsRuntime::TickleSampler()` to notify the idle thread to reset its timer. + +**Idle background path:** A `std::thread` in `MQuickJsRuntime` waits on a condition variable with a `BARTON_CONFIG_SBMD_METRICS_SAMPLE_PERIOD_MS` timeout (set via `BCORE_SBMD_METRICS_SAMPLE_PERIOD_MS` CMake option). At the top of each loop iteration it checks `samplerShouldStop` and exits if set. It calls `ForceSnapshot()` only when the wait times out naturally — meaning no `InvokeHandler` activity has occurred for the full idle period. When `wait_until` returns before the deadline, it compares the current `tickleSeq` to the value recorded at the start of the wait. If they differ, a real tickle occurred: reset the timer and re-check `samplerShouldStop` without taking a snapshot. If they are equal, the wakeup was spurious: call `wait_until` again with the same absolute deadline (not a fresh `wait_for`) so that only the remaining time is consumed, not a full new period. This ensures spurious wakeups cannot indefinitely delay an idle-period snapshot. + +**Why two paths rather than either alone?** +- Periodic-only: on low-traffic systems (e.g., 20% active, 80% idle), most captures reflect idle-state heap; behavior during activity is sampled at most once per interval. +- In-activity-only: misses the idle baseline, which reveals slow leaks and steady-state overhead between bursts. +- Hybrid: busy systems capture pool health on every invocation and the background thread rarely fires; idle systems rely on the background timer for baseline captures. The tickle mechanism prevents the background thread from taking a redundant snapshot right after a burst of activity. + +**`MQuickJsRuntime::RecordHeapSnapshot(const JSMemoryUsage &usage)`** records the provided `JSMemoryUsage` data to the pool health instruments. Requires the caller to hold the JS mutex. Called from `InvokeHandler` with the `usage_after` struct already captured around `JS_Call`; called from `ForceSnapshot()` with a freshly read struct. + +**`MQuickJsRuntime::ForceSnapshot()`** is a public synchronous function that acquires the JS mutex, calls `RecordHeapSnapshot` (which advances `sbmd.js.heap.peak_bytes` only if the current value exceeds the recorded peak), releases the mutex, and calls `TickleSampler()`. It SHALL silently no-op — without acquiring the JS mutex — if `!jsContextReady`. `GetSharedContext()` MUST NOT be used for this check: calling it without the mutex held is a data race, and calling it with the mutex held defeats the purpose of a lock-free early-exit; instead, `jsContextReady` is a dedicated `std::atomic` set to `true` (with `memory_order_release`) at the end of `Initialize()` and cleared to `false` at the start of `Shutdown()`, providing a safe lock-free early-exit path. Used in unit tests and available for on-demand telemetry. Any snapshot from any path resets the idle timer. + +**`MQuickJsRuntime::TickleSampler()`** notifies the background thread's condition variable (`samplerCv`) to reset its idle timer. Atomically increments `tickleSeq` then calls `samplerCv.notify_one()` — both *without* acquiring `samplerCvMutex`. The atomic increment is the mechanism by which the idle thread distinguishes a real tickle from a spurious wakeup (see below); `notify_one()` without the lock is the standard C++ idiom since only the waiter needs it. Avoiding the lock in `TickleSampler()` also prevents a lock-ordering deadlock: the idle thread can hold `samplerCvMutex` while calling `ForceSnapshot()` (which acquires the JS mutex), so `TickleSampler()` — called while holding the JS mutex — must never acquire `samplerCvMutex`. Safe to call from any context including while holding the JS mutex. + +``` +InvokeHandler (JS mutex held by caller): Idle background thread: + → JS_Call loop: + → JS_GetMemoryUsage if samplerShouldStop: exit + → record sbmd.handler.* deadline = now() + std::chrono::milliseconds(BARTON_CONFIG_SBMD_METRICS_SAMPLE_PERIOD_MS) + → RecordHeapSnapshot(usage_after) ← pool health seq = tickleSeq + → TickleSampler() ← increments tickleSeq cv.wait_until(lock, deadline) + if timed_out: ForceSnapshot() + // real tickle (tickleSeq != seq): + // no snapshot, reset timer + // spurious (tickleSeq == seq): + // no snapshot, keep waiting +``` + +**Thread startup/shutdown:** The thread is started at the end of `MQuickJsRuntime::Initialize()`. In `Shutdown()`, `jsContextReady` is cleared to `false` first (so any concurrent `ForceSnapshot()` caller sees the flag cleared before the context is torn down), then `samplerShouldStop` is set to `true`, `TickleSampler()` is called to wake the thread immediately, and `periodicSamplerThread` is joined — guarded with `joinable()` to avoid `std::terminate` if `Initialize()` failed before the thread was started — before `JS_FreeContext` is called. + +### Decision 4: `PendingOperation` extended with `OperationContext` + +An `OperationContext operationCtx` field is added to `PendingOperation`. It is initialized in `ExecuteRequestCommand` alongside `overallDeadline` with the driver name, originating op type, resource ID, and `startTime = steady_clock::now()`. `CompletePendingOperation` — the single convergence point for all deferred op exits — reads `pending.operationCtx.startTime` to compute total duration and uses `pending.operationCtx.driverName`, `pending.operationCtx.opType`, and `pending.operationCtx.resourceId` as attributes on all deferred lifecycle metrics (`sbmd.deferred.duration_ms`, `sbmd.deferred.depth`, `sbmd.deferred.timeout`, `sbmd.deferred.max_depth`). + +**Why `CompletePendingOperation` rather than each individual exit site?** There are ~15 `CompletePendingOperation` call sites. Recording in the single callee avoids duplicating metric logic and ensures no exit path is missed. + +### Decision 5: Metric attributes + +| Attribute key | Value type | Used on | +|---|---|---| +| `"driver"` | driver name string (e.g., `"door-lock"`) | all per-driver metrics | +| `"op_type"` | `"read"` / `"write"` / `"execute"` / `"attribute_report"` / `"event"` | invocation, outcome, per-operation deferred metrics | +| `"resource_id"` | resource ID string (e.g., `"isOn"`); omitted for attribute/event handlers | `sbmd.handler.*`, `sbmd.deferred.duration_ms`, `sbmd.deferred.depth`, `sbmd.deferred.timeout`, `sbmd.deferred.max_depth` | +| `"outcome"` | `"success"` / `"exception"` / `"timeout"` / `"stack_overflow"` / `"error"` | outcome counter | +| `"reason"` | `"file_read"` / `"eval_failed"` / `"activation_failed"` | driver load failure counter | +| `"phase"` | `"init"` / `"loading"` | JS exception event counter | + +**Note on `"driver"` for `sbmd.js.exception`:** The attribute is omitted entirely for `"init"`-phase exceptions (no driver context); it is set to the filename stem for `"loading"`-phase exceptions. Empty string and placeholder values are not used. + +**Note on `"op_type"` for deferred invocations:** All `InvokeHandler` calls in a deferred chain — initial invocation and all callbacks — carry the same `opCtx->opType` from `pending.operationCtx`, which holds the originating operation type (e.g., `"write"` or `"execute"`). There are no `"deferred_response"` or `"deferred_error"` op type values; the originating type is used throughout, making it straightforward to aggregate total handler cost for a given operation type without joining separate deferred buckets. + +`deviceId` is explicitly deferred (see Non-Goals). The team consensus: include it in a follow-on when attribute indexing strategy for the backend is clearer. + +### Decision 6: Testing strategy + +**Unit tests** (`core/test/src/SbmdObservabilityTest.cpp`): The existing SBMD GTest suite already uses a real mquickjs runtime (`MQuickJsRuntime::Initialize(512 * 1024)` in `SetUpTestSuite`). The new test file follows the same pattern, calling `MQuickJsRuntime::InitializeMetrics()` first (before `MQuickJsRuntime::Initialize()`), then the remaining three `InitializeMetrics()` calls after `Initialize()` succeeds, per the Decision 1 ordering. Tests invoke handlers via `SbmdHandlerInvoker::InvokeHandler`, then call `observabilityDumpJson()` and parse the JSON to assert: +- Observation count increased (wiring is correct) +- Duration > 0 (timing is working) +- Heap delta is within a plausible range +- Outcome counter incremented for the expected outcome key + +**Integration tests** (`testing/test/`): Deferred operation metrics require real Matter command round-trips. A pytest test commissions a simulated device, triggers a write operation that exercises the deferred path, then calls `b_core_client_get_telemetry()` and asserts the expected deferred metrics appear. + +**Heap sampler in tests**: Tests call `MQuickJsRuntime::ForceSnapshot()` directly rather than waiting for the background thread. This avoids time-dependent test flakiness entirely. + +## Component diagram + +``` +core/deviceDrivers/matter/sbmd/ +│ +├── mquickjs/ +│ ├── MQuickJsRuntime.cpp ← heap metrics, ForceSnapshot(), RecordHeapSnapshot(const JSMemoryUsage &), +│ │ RecordMutexWait(), RecordJsException(), TickleSampler(); +│ │ in-activity + idle sampling +│ └── SbmdHandlerInvoker.cpp ← invocation/outcome metrics, RecordOutcomeError(); +│ InvokeHandler extended +│ +├── SbmdFactory.cpp ← driver load metrics +└── SpecBasedMatterDeviceDriver.cpp ← deferred op metrics; PendingOperation.operationCtx (OperationContext) +``` + +## Risks / Trade-offs + +- **In-activity heap snapshot overhead** → `RecordHeapSnapshot` is called at the end of every `InvokeHandler` invocation while the mutex is held. It reads the same `JS_GetMemoryUsage` struct already captured for the heap delta calculation — no additional JS engine work. Overhead is negligible. + +- **`JS_GetMemoryUsage` overhead inside `InvokeHandler`** → Called twice per invocation (before `JS_PushArg` and after `JS_Call` returns). `JS_MEMUSAGE_WALK_HEAP` is not set — the call is an O(1) struct read with no heap walk. As a consequence, `usage.heap_free_blocks` is always 0 (per the mquickjs patch implementation); `sbmd.js.heap.free_bytes` therefore maps to `usage.free_size` (the gap between heap top and stack bottom), not to `heap_free_blocks`. Overhead is negligible. + +- **Non-uniform sampling in `sbmd.js.heap.used_bytes`** → Observation rate is proportional to handler call rate plus one sample per idle period, so percentiles are activity-weighted rather than time-weighted. On a busy system, high percentiles reflect heap under load; on an idle system, most observations reflect the settled idle baseline. `sbmd.js.heap.peak_bytes` and the histogram's `min`/`max` fields are not skewed by sampling frequency the way percentiles are, but they still only reflect what was actually observed — heap spikes that occur between snapshots can be missed. Percentiles should be interpreted with the deployment's activity level in mind. + +- **Heap delta sign** → If implicit GC fires during an invocation, `heap_used` may drop. The delta will be negative, which is valid and informative. Negative values satisfy `value <= 0` on the first bucket comparison and are counted in the `le=0` bucket (the lowest bound in the histogram). This is expected behavior, not a bug. + +- **mquickjs changes conflict risk** → Another developer is actively modifying mquickjs. The `InvokeHandler` changes and `MQuickJsRuntime` sampler thread are in BartonCore C++, not mquickjs itself, so conflicts are unlikely. Coordination is only needed if the other dev changes `JSMemoryUsage` struct layout. + +## Open Questions + +- **Sample period default**: 30 s is a reasonable default but untested in production. Should `BCORE_SBMD_METRICS_SAMPLE_PERIOD_MS` be a runtime-configurable property instead of a compile-time CMake option? (Deferred — compile-time is fine for now.) +- **Integration test simulated device**: does the existing matter.js virtual device infrastructure support triggering a deferred command path deterministically? Needs verification during implementation. +- **`JS_MEMUSAGE_WALK_HEAP` in dev/Docker builds**: enabling this flag in the mquickjs dev build would give real `heap_free_blocks` data (currently always 0 without it). Walk overhead is unknown — a temporary `sbmd.js.memusage_walk_ms` histogram could be added in dev builds to measure it before deciding whether to enable it in production builds. Deferred pending investigation. diff --git a/openspec/changes/sbmd-observability-instrumentation/proposal.md b/openspec/changes/sbmd-observability-instrumentation/proposal.md new file mode 100644 index 00000000..2960eced --- /dev/null +++ b/openspec/changes/sbmd-observability-instrumentation/proposal.md @@ -0,0 +1,47 @@ +## Why + +The SBMDv4 JavaScript runtime (mquickjs) runs inside a fixed-size arena (configurable via `BARTON_CONFIG_MQUICKJS_MEMSIZE_BYTES`, default 1 MB) with a single shared JS context, making it a natural resource bottleneck. Today, nothing is measured: memory pressure, handler latency, GC activity, deferred operation health, and driver load cost are all invisible. Instrumenting the SBMD runtime with the existing observability API gives operators and developers the data needed to diagnose performance issues, detect failures, and understand system health. + +## What Changes + +- **Distributed metric instrumentation**: metric handles are owned by the module that records them. `MQuickJsRuntime` gains heap metrics and `ForceSnapshot()`; `SbmdHandlerInvoker` gains invocation and outcome metrics; `SbmdFactory` gains driver load metrics; `SpecBasedMatterDeviceDriver` gains deferred operation metrics. +- **Hybrid heap sampler** in `MQuickJsRuntime`: pool health metrics are captured in-activity (after every `InvokeHandler` call) and by a background thread that fires only after a configurable idle period with no handler activity. +- **Per-invocation instrumentation** in `SbmdHandlerInvoker::InvokeHandler`: measures duration, heap delta, and outcome for every JS handler call. Signature extended with a single optional `const OperationContext *opCtx = nullptr` parameter; the struct is extensible without further signature changes and carries natural operation-scope lifetime for deferred chains. +- **Driver load instrumentation** in `SbmdFactory::RegisterDriversFromDirectory`: measures memory cost and wall-clock time for loading and activating each `.sbmd.js` file. +- **Deferred operation instrumentation** in `SpecBasedMatterDeviceDriver`: tracks in-flight count, total duration (attributed by driver, originating op type, and resource ID), deferral depth, timeout events, and max-depth-exceeded events. Adds `OperationContext operationCtx` field to `PendingOperation` struct. +- **JS exception event counter** capturing exceptions during driver loading and runtime initialization phases. +- **Driver load failure counter** capturing all failure modes in the driver registration loop. +- **Unit tests** (GTest): exercise all metric wiring against the real mquickjs runtime using `observabilityDumpJson()` to assert observations. +- **Integration tests** (pytest): verify deferred operation metrics end-to-end via `b_core_client_get_telemetry()`. + +## Capabilities + +### New Capabilities + +- `sbmd-runtime-observability`: Defines the complete set of SBMD runtime metrics — their names, instrument types, attributes, sampling strategy, and testing requirements. Covers JS heap health, handler invocation timing and outcomes, driver load cost, deferred operation lifecycle, driver load failures, and JS exception events. + +### Modified Capabilities + + + +## Impact + +- **Affected code**: `core/deviceDrivers/matter/sbmd/` (SbmdHandlerInvoker, SbmdFactory, SpecBasedMatterDeviceDriver, MQuickJsRuntime) +- **New files**: `core/test/src/SbmdObservabilityTest.cpp` (GTest unit tests); new pytest test in `testing/test/`. Metric handles and initialization are added to existing production modules — no new production source files. +- **Struct change**: `PendingOperation` gains `OperationContext operationCtx` field (carries driver name, originating op type, resource ID, and start time) +- **API change**: `SbmdHandlerInvoker::InvokeHandler` gains a single optional `const OperationContext *opCtx = nullptr` parameter; new `OperationContext` struct defined in `SbmdHandlerInvoker.h` (backwards-compatible) +- **CMake flag**: `BCORE_OBSERVABILITY_BACKEND` must be `memory` (default) for metrics to be recorded; `none` backend silently no-ops all calls — no conditional compilation required at call sites +- **CMake option**: new `BCORE_SBMD_METRICS_SAMPLE_PERIOD_MS` option (default 30000, compiled as `BARTON_CONFIG_SBMD_METRICS_SAMPLE_PERIOD_MS`) controlling the hybrid heap sampler idle period +- **Dependencies**: existing `observabilityMetrics.h` API; no new external dependencies +- **Tests**: new GTest file `core/test/src/SbmdObservabilityTest.cpp`; new pytest test in `testing/test/` + +## Non-Goals + +- **Implicit GC count + duration**: requires an additional mquickjs patch (GC callback mechanism). Deferred to follow-on change pending coordination with ongoing mquickjs work. +- **GC root list size gauge** (`sbmd.js.gc_roots`): requires a mquickjs patch to expose the internal GC root list count (e.g., `JS_GetGCRootCount`). Measures engine-level root list growth from any source — not just `SafeJSValue` misuse — making it a more complete leak signal than a BartonCore-side counter. Deferred to follow-on pending the mquickjs patch. +- **Explicit GC tracking** (`gc()` call sites): no call sites currently exist in production code. Deferred to follow-on. +- **`deviceId` attribute on metrics**: useful for isolating per-device failures but adds unbounded cardinality. Deferred to follow-on when attribute indexing strategy is clearer. +- **Per-device-instance heap cost**: not tractable — the JS arena has no per-device partitioning. Deferred to follow-on for further investigation. +- **Intra-invocation peak heap**: `JS_GetMemoryUsage` provides only a global watermark, not a per-call peak. Approximation is unreliable. Deferred to follow-on. +- **Production/fleet attributes** (e.g., `accountId`): out of scope until a backend storage strategy is defined. +- **Observability infrastructure changes**: the counter/gauge/histogram implementation in `core/src/observability/` is not modified by this change. diff --git a/openspec/changes/sbmd-observability-instrumentation/specs/sbmd-runtime-observability/spec.md b/openspec/changes/sbmd-observability-instrumentation/specs/sbmd-runtime-observability/spec.md new file mode 100644 index 00000000..5b93929a --- /dev/null +++ b/openspec/changes/sbmd-observability-instrumentation/specs/sbmd-runtime-observability/spec.md @@ -0,0 +1,180 @@ +## ADDED Requirements + +### Requirement: JS heap pool utilization tracking +The SBMD runtime SHALL record mquickjs heap pool utilization as a histogram named `sbmd.js.heap.used_bytes` using a hybrid sampling strategy: (1) in-activity captures from `SbmdHandlerInvoker::InvokeHandler` after each `JS_Call` while the JS mutex is held, and (2) idle background captures from a thread that fires only when no handler activity has occurred for `BARTON_CONFIG_SBMD_METRICS_SAMPLE_PERIOD_MS` milliseconds (set via `BCORE_SBMD_METRICS_SAMPLE_PERIOD_MS` CMake option, default 30000 ms). The runtime SHALL also record the fixed arena size once at initialization as a gauge named `sbmd.js.heap.arena_bytes`, and SHALL maintain a gauge named `sbmd.js.heap.free_bytes` (sourced from `usage.free_size` — the gap between the heap top and the stack bottom) updated with each snapshot. + +#### Scenario: Heap utilization captured during handler invocation +- **WHEN** a JS handler is invoked via `InvokeHandler` +- **THEN** `sbmd.js.heap.used_bytes` histogram gains one observation of the current heap utilization + +#### Scenario: Heap utilization captured during idle period +- **WHEN** no handler invocations have occurred for `BARTON_CONFIG_SBMD_METRICS_SAMPLE_PERIOD_MS` milliseconds +- **THEN** the idle background thread records one observation to `sbmd.js.heap.used_bytes` + +#### Scenario: Arena size recorded at initialization +- **WHEN** `MQuickJsRuntime::Initialize(N)` is called +- **THEN** the `sbmd.js.heap.arena_bytes` gauge records the value `N` + +#### Scenario: Free bytes reflects remaining capacity +- **WHEN** a heap snapshot is taken (via `InvokeHandler` or `ForceSnapshot()`) +- **THEN** `sbmd.js.heap.free_bytes` gauge records the current `usage.free_size` value (gap between heap top and stack bottom) + +### Requirement: Peak heap watermark gauge +The SBMD runtime SHALL maintain a gauge named `sbmd.js.heap.peak_bytes` recording the highest value of `usage.heap_used` observed since `MQuickJsRuntime::Initialize()`. (`JS_MEMUSAGE_WALK_HEAP` is not set, so `usage.heap_free_blocks` is always 0; `heap_used` is used directly as the high-water mark of heap expansion.) The gauge SHALL be updated with each heap snapshot. + +#### Scenario: Peak watermark monotonically increases +- **WHEN** successive JS handler invocations allocate progressively more memory +- **THEN** `sbmd.js.heap.peak_bytes` reflects the highest value observed, never decreasing + +### Requirement: Force snapshot API +The system SHALL provide a `MQuickJsRuntime::ForceSnapshot()` public static function that synchronously samples heap stats, adds one observation to the `sbmd.js.heap.used_bytes` histogram, updates `sbmd.js.heap.free_bytes` with the current `usage.free_size`, advances `sbmd.js.heap.peak_bytes` only if the current `usage.heap_used` exceeds the previously recorded peak (maintaining the high-water mark guarantee), and calls `TickleSampler()` to reset the idle thread's timer. This function SHALL be callable without holding the JS mutex (it acquires it internally). `ForceSnapshot()` SHALL silently no-op — without acquiring the JS mutex or calling `JS_GetMemoryUsage` — if called before `MQuickJsRuntime::Initialize()` has succeeded. This check MUST be thread-safe: implementations SHALL use a dedicated `std::atomic jsContextReady` flag (set to `true` with `memory_order_release` at the end of `Initialize()` and cleared to `false` at the start of `Shutdown()`) rather than calling `GetSharedContext()`, which requires the JS mutex to already be held and therefore cannot be used for a lock-free early-exit guard. The system SHALL also provide `MQuickJsRuntime::TickleSampler()`, which notifies the idle background thread to reset its sleep timer without taking a snapshot. The idle background thread SHALL use `ForceSnapshot()` when its idle timer expires. + +#### Scenario: ForceSnapshot produces an immediate observation +- **WHEN** `MQuickJsRuntime::ForceSnapshot()` is called +- **THEN** `sbmd.js.heap.used_bytes` observation count increases by one + +### Requirement: Per-invocation heap delta tracking +The SBMD runtime SHALL record the net heap allocation of each JS handler invocation as a histogram named `sbmd.handler.heap_delta_bytes`. The delta SHALL be computed as `heap_used_after - heap_used_before`, measured from immediately before `JS_PushArg` through immediately after `JS_Call` returns in `SbmdHandlerInvoker::InvokeHandler` (the same window as `sbmd.handler.duration_ms`), so that argument-marshalling allocations are included. The histogram SHALL support `"driver"`, `"op_type"`, and `"resource_id"` attributes; `"resource_id"` is omitted for attribute/event handler invocations. + +#### Scenario: Heap delta recorded per invocation +- **WHEN** a JS handler is invoked via `InvokeHandler` with a `driverName` and `opType` +- **THEN** `sbmd.handler.heap_delta_bytes` contains one new observation attributed to that driver and op type + +#### Scenario: Heap delta may be negative +- **WHEN** a JS handler invocation triggers implicit GC (allocation pressure) +- **THEN** `sbmd.handler.heap_delta_bytes` records a negative value, which is valid + +### Requirement: Handler invocation duration tracking +The SBMD runtime SHALL record the wall-clock duration of each JS handler invocation as a histogram named `sbmd.handler.duration_ms`. Duration SHALL be measured from immediately before `JS_PushArg` to immediately after `JS_Call` returns in `SbmdHandlerInvoker::InvokeHandler`. The histogram SHALL support `"driver"`, `"op_type"`, and `"resource_id"` attributes; `"resource_id"` is omitted for attribute/event handler invocations. + +#### Scenario: Duration recorded for each invocation +- **WHEN** a JS handler is invoked with a driver name and op type +- **THEN** `sbmd.handler.duration_ms` gains one observation greater than zero + +#### Scenario: Timeout invocations are recorded +- **WHEN** a JS handler exceeds the `BARTON_CONFIG_SBMD_SCRIPT_TIMEOUT_MS` execution deadline and is interrupted +- **THEN** `sbmd.handler.duration_ms` still records the elapsed duration for that invocation + +### Requirement: Handler invocation outcome tracking +The SBMD runtime SHALL count handler invocation outcomes using a counter named `sbmd.handler.outcome` with attributes `"driver"`, `"op_type"`, `"resource_id"` (omitted for attribute/event handler invocations), and `"outcome"`. Valid outcome values are: `"success"` (handler returned a valid result), `"exception"` (JS exception thrown, not a timeout), `"timeout"` (script execution deadline exceeded), `"stack_overflow"` (JS_StackCheck failed before call), and `"error"` (handler returned a ResultTerminal::Error). The counter SHALL be incremented in `SbmdHandlerInvoker::InvokeHandler` for the first four outcomes; `"error"` SHALL be incremented at the `ResultTerminal::Error` handling site. + +#### Scenario: Success outcome counted +- **WHEN** a JS handler invocation returns a success terminal +- **THEN** `sbmd.handler.outcome` counter for `outcome="success"` increments by one + +#### Scenario: Exception outcome counted +- **WHEN** a JS handler throws a JS exception (not a timeout) +- **THEN** `sbmd.handler.outcome` counter for `outcome="exception"` increments by one + +#### Scenario: Timeout outcome counted +- **WHEN** a JS handler exceeds the `BARTON_CONFIG_SBMD_SCRIPT_TIMEOUT_MS` deadline and the interrupt handler fires +- **THEN** `sbmd.handler.outcome` counter for `outcome="timeout"` increments by one + +#### Scenario: Stack overflow outcome counted +- **WHEN** `JS_StackCheck` returns nonzero before a handler call +- **THEN** `sbmd.handler.outcome` counter for `outcome="stack_overflow"` increments by one + +#### Scenario: Error outcome counted +- **WHEN** a JS handler returns a `ResultTerminal::Error` +- **THEN** `sbmd.handler.outcome` counter for `outcome="error"` increments by one + +### Requirement: JS mutex wait time tracking +The SBMD runtime SHALL record the time a request spends waiting to acquire the JS runtime mutex as a histogram named `sbmd.js.mutex.wait_ms`. This SHALL be measured from the point a call to `std::lock_guard(MQuickJsRuntime::GetMutex())` begins until the mutex is acquired, in all code paths that acquire the mutex for handler invocation. + +#### Scenario: Mutex wait recorded on contention +- **WHEN** two threads attempt to invoke SBMD handlers concurrently +- **THEN** the waiting thread records a non-zero observation in `sbmd.js.mutex.wait_ms` + +#### Scenario: Mutex wait near zero when uncontested +- **WHEN** a handler invocation acquires the JS mutex without contention +- **THEN** `sbmd.js.mutex.wait_ms` records an observation close to zero + +### Requirement: Driver load cost tracking +The SBMD runtime SHALL record, for each successfully loaded driver: the wall-clock time to evaluate and activate its `.sbmd.js` file as a histogram named `sbmd.driver.load.duration_ms` with attribute `"driver"`, and the net heap bytes consumed during load and activation as a histogram named `sbmd.driver.load.heap_bytes` with attribute `"driver"`. Both SHALL be recorded once per driver at startup in `SbmdFactory::RegisterDriversFromDirectory`. + +#### Scenario: Load duration recorded per driver +- **WHEN** a `.sbmd.js` file is successfully loaded and activated +- **THEN** `sbmd.driver.load.duration_ms` contains one observation attributed to that driver's name + +#### Scenario: Load heap cost recorded per driver +- **WHEN** a `.sbmd.js` file is successfully loaded and activated +- **THEN** `sbmd.driver.load.heap_bytes` contains one observation reflecting the heap consumed + +### Requirement: Registered driver count tracking +The SBMD runtime SHALL record the total number of successfully registered drivers as a gauge named `sbmd.driver.registered.count` once after all drivers have been loaded in `SbmdFactory::RegisterDriversFromDirectory`. + +#### Scenario: Driver count reflects successful loads +- **WHEN** N drivers are successfully loaded and one fails +- **THEN** `sbmd.driver.registered.count` gauge records N + +### Requirement: Driver load failure tracking +The SBMD runtime SHALL count driver load failures using a counter named `sbmd.driver.load.failure` with attributes `"driver"` (filename stem) and `"reason"`. Valid reason values are: `"file_read"` (file could not be opened or read), `"eval_failed"` (JS evaluation failed), `"activation_failed"` (driver Activate() failed). + +#### Scenario: Evaluation failure counted +- **WHEN** `SbmdLoader::LoadDriver` fails due to a JS evaluation error +- **THEN** `sbmd.driver.load.failure` counter for `reason="eval_failed"` increments for that driver + +#### Scenario: Activation failure counted +- **WHEN** `SbmdDriver::Activate` fails +- **THEN** `sbmd.driver.load.failure` counter for `reason="activation_failed"` increments for that driver + +### Requirement: JS exception event tracking +The SBMD runtime SHALL count JS exception events during lifecycle phases using a counter named `sbmd.js.exception` with attributes `"driver"` and `"phase"`. The `"driver"` attribute SHALL be set to the driver's filename stem when known (loading phase) and SHALL be omitted entirely when not known (init phase); implementations MUST NOT record an empty string or placeholder value. Valid phase values are: `"init"` (exception during runtime/polyfill initialization) and `"loading"` (exception during driver script evaluation). Handler-phase exceptions are captured by `sbmd.handler.outcome{outcome="exception"}` and are not recorded here. + +#### Scenario: Loading phase exception counted +- **WHEN** a driver's `.sbmd.js` evaluation throws a JS exception +- **THEN** `sbmd.js.exception` counter for `phase="loading"` increments with the driver's filename stem + +### Requirement: Deferred operation in-flight count +The SBMD runtime SHALL maintain a gauge named `sbmd.deferred.in_flight` representing the number of `requestCommand` operations currently parked waiting for a device response. The gauge SHALL be incremented when a `PendingOperation` is added to `pendingOperations` in `ExecuteRequestCommand` and decremented in `CompletePendingOperation`. + +#### Scenario: In-flight count reflects active deferred ops +- **WHEN** a deferred operation is started and not yet resolved +- **THEN** `sbmd.deferred.in_flight` gauge is greater than zero + +#### Scenario: In-flight count decrements on completion +- **WHEN** a deferred operation completes (success, error, or timeout) +- **THEN** `sbmd.deferred.in_flight` gauge decrements back toward zero + +### Requirement: Deferred operation total duration tracking +The SBMD runtime SHALL record the total wall-clock duration of each deferred operation — from initial `ExecuteRequestCommand` to `CompletePendingOperation` — as a histogram named `sbmd.deferred.duration_ms` with attributes `"driver"`, `"op_type"` (the originating operation type from `pending.operationCtx.opType`), and `"resource_id"` (the originating resource from `pending.operationCtx.resourceId`). Duration includes device round-trip time. + +#### Scenario: Total duration includes device round-trip +- **WHEN** a deferred operation completes after a device response +- **THEN** `sbmd.deferred.duration_ms` records a value greater than the JS execution time alone + +### Requirement: Deferral depth distribution tracking +The SBMD runtime SHALL record the deferral depth at completion of each deferred operation as a histogram named `sbmd.deferred.depth` with attributes `"driver"`, `"op_type"`, and `"resource_id"`. Depth 0 means the operation resolved after one round-trip; depth N means the operation re-armed N times. + +#### Scenario: Single round-trip records depth zero +- **WHEN** a deferred operation resolves after one device response +- **THEN** `sbmd.deferred.depth` records 0 for that driver + +#### Scenario: Re-armed operation records correct depth +- **WHEN** a deferred operation re-arms twice before resolving +- **THEN** `sbmd.deferred.depth` records 2 for that driver + +### Requirement: Deferred operation timeout counting +The SBMD runtime SHALL count deferred operations that exceed their configured `overallDeadline` using a counter named `sbmd.deferred.timeout` with attributes `"driver"`, `"op_type"`, and `"resource_id"`. The deadline is set at operation start from `cmd.timeoutMs` if present, otherwise `driver.defaultTimeoutMs` if set, otherwise `PendingOperation::DEFAULT_OVERALL_TIMEOUT_MS` (30 s). + +#### Scenario: Timeout counted when deadline exceeded +- **WHEN** a deferred operation's `overallDeadline` is exceeded before a device response arrives +- **THEN** `sbmd.deferred.timeout` counter increments for that driver + +### Requirement: Deferred operation max-depth-exceeded counting +The SBMD runtime SHALL count deferred operations terminated because they reached `MAX_DEFERRAL_DEPTH` (10) using a counter named `sbmd.deferred.max_depth` with attributes `"driver"`, `"op_type"`, and `"resource_id"`. + +#### Scenario: Max depth counter increments on depth limit +- **WHEN** a deferred operation re-arms 10 times and `ContinueDeferredChain` rejects the next re-arm +- **THEN** `sbmd.deferred.max_depth` counter increments for that driver + +### Requirement: Subsystem metrics initialization +Each instrumented module (`MQuickJsRuntime`, `SbmdHandlerInvoker`, `SbmdFactory`, `SpecBasedMatterDeviceDriver`) SHALL provide `static void InitializeMetrics()` and `static void ShutdownMetrics()` functions. `MQuickJsRuntime::InitializeMetrics()` SHALL be called by `SbmdFactory::RegisterDriversFromDirectory` before `MQuickJsRuntime::Initialize()`, so that the `sbmd.js.exception{phase="init"}` counter is live for exceptions that occur during initialization. The remaining three `InitializeMetrics()` calls (`SbmdHandlerInvoker`, `SbmdFactory`, `SpecBasedMatterDeviceDriver`) SHALL be made after `MQuickJsRuntime::Initialize()` succeeds. The corresponding `ShutdownMetrics()` calls SHALL be made in the subsystem shutdown path. + +#### Scenario: Metrics available after initialization +- **WHEN** all four `InitializeMetrics()` calls complete +- **THEN** `MQuickJsRuntime::ForceSnapshot()` and all recording functions operate without error + +#### Scenario: Recording before initialization is safe +- **WHEN** a recording function is called before its module's `InitializeMetrics()` +- **THEN** the call is silently ignored without crashing diff --git a/openspec/changes/sbmd-observability-instrumentation/tasks.md b/openspec/changes/sbmd-observability-instrumentation/tasks.md new file mode 100644 index 00000000..8d279021 --- /dev/null +++ b/openspec/changes/sbmd-observability-instrumentation/tasks.md @@ -0,0 +1,72 @@ +## 1. Startup and shutdown wiring + +- [ ] 1.1 Add CMake option `BCORE_SBMD_METRICS_SAMPLE_PERIOD_MS` (default 30000, compiled definition `BARTON_CONFIG_SBMD_METRICS_SAMPLE_PERIOD_MS`) to `config/cmake/options.cmake` +- [ ] 1.2 In `SbmdFactory::RegisterDriversFromDirectory`, call `MQuickJsRuntime::InitializeMetrics()` **before** `MQuickJsRuntime::Initialize()` so the `sbmd.js.exception` handle is live for init-phase exceptions; after `MQuickJsRuntime::Initialize()` succeeds, call `SbmdHandlerInvoker::InitializeMetrics()`, `SbmdFactory::InitializeMetrics()`, and `SpecBasedMatterDeviceDriver::InitializeMetrics()` (these functions are added in tasks 3.0, 4.0, and 5.0 respectively) +- [ ] 1.3 Wire the corresponding `ShutdownMetrics()` calls into the subsystem shutdown path that already calls `MQuickJsRuntime::Shutdown()`; identify the correct call site during implementation + +## 2. MQuickJsRuntime — hybrid heap sampler + +- [ ] 2.0 Add heap metric handles (`sbmd.js.heap.used_bytes`, `sbmd.js.heap.arena_bytes`, `sbmd.js.heap.free_bytes`, `sbmd.js.heap.peak_bytes`), `sbmd.js.mutex.wait_ms`, and `sbmd.js.exception` as private static members of `MQuickJsRuntime`; add public static functions `static void InitializeMetrics()`, `static void ShutdownMetrics()`, `static void ForceSnapshot()`, `static void TickleSampler()`, `static void RecordHeapSnapshot(const JSMemoryUsage &usage)`, `static void RecordMutexWait(double ms)`, and `static void RecordJsException(const char *phase, const char *driver)` — when `driver == nullptr`, `RecordJsException` MUST omit the `"driver"` attribute entirely (not record an empty string); `ForceSnapshot` MUST check the `jsContextReady` atomic flag (in addition to the metric handle null-check) and silently no-op without acquiring the JS mutex if `!jsContextReady`; `GetSharedContext()` MUST NOT be used for this guard: calling it without the mutex held is a data race, and calling it with the mutex held defeats the purpose of a lock-free early-exit; `jsContextReady` is set to `true` at the end of `Initialize()` (task 2.4) and cleared to `false` at the start of `Shutdown()` (task 2.3); the remaining recording functions (`RecordHeapSnapshot`, `RecordMutexWait`, `RecordJsException`) must null-check their handles and return silently if called before `InitializeMetrics()` +- [ ] 2.1 Add `static std::thread periodicSamplerThread`, `static std::atomic samplerShouldStop`, `static std::atomic jsContextReady`, `static std::atomic tickleSeq`, `static std::condition_variable samplerCv`, and `static std::mutex samplerCvMutex` to `MQuickJsRuntime` +- [ ] 2.2 Start idle sampler thread at end of `MQuickJsRuntime::Initialize()`: outer loop checks `samplerShouldStop` and exits if set; otherwise computes an absolute `deadline = steady_clock::now() + std::chrono::milliseconds(BARTON_CONFIG_SBMD_METRICS_SAMPLE_PERIOD_MS)` and records the current `tickleSeq`; inner loop calls `samplerCv.wait_until(lock, deadline)` — on `cv_status::timeout` calls `ForceSnapshot()` and breaks to outer loop; on early return compares current `tickleSeq` to the recorded value: if changed (real tickle) breaks to outer loop to re-check `samplerShouldStop` and compute a fresh deadline; if unchanged (spurious) loops back to `wait_until` with the same `deadline`, consuming only the remaining time rather than restarting a full `BARTON_CONFIG_SBMD_METRICS_SAMPLE_PERIOD_MS` wait +- [ ] 2.3 In `MQuickJsRuntime::Shutdown()`, set `jsContextReady = false` first (so any concurrent `ForceSnapshot()` caller sees the flag cleared before the JS mutex is released), then set `samplerShouldStop = true`, call `TickleSampler()` to wake the thread immediately, then join `periodicSamplerThread` before `JS_FreeContext`; guard the join with `periodicSamplerThread.joinable()` to avoid `std::terminate` if `Initialize()` failed before the thread was started +- [ ] 2.4 After context is created at end of `MQuickJsRuntime::Initialize()`: record `sbmd.js.heap.arena_bytes` gauge once, then set `jsContextReady = true` (using `std::memory_order_release` so the flag is visible to any thread that reads it after the JS context is fully set up) + +## 3. SbmdHandlerInvoker — per-invocation instrumentation + +- [ ] 3.0 Add `sbmd.handler.duration_ms`, `sbmd.handler.heap_delta_bytes`, and `sbmd.handler.outcome` metric handles as private static members of `SbmdHandlerInvoker`; add `static void InitializeMetrics()`, `static void ShutdownMetrics()`, and `static void RecordOutcomeError(const char *driver, const char *opType, const char *resourceId)`; `RecordOutcomeError` must null-check its handle and return silently if called before `InitializeMetrics()` +- [ ] 3.1 Define `OperationContext` struct in `SbmdHandlerInvoker.h` with fields `const char *driverName = nullptr`, `const char *opType = nullptr`, `const char *resourceId = nullptr`, and `std::chrono::steady_clock::time_point startTime`; extend `SbmdHandlerInvoker::InvokeHandler` with `const OperationContext *opCtx = nullptr` (backwards-compatible) +- [ ] 3.2 Capture `heap_used` from `JS_GetMemoryUsage` and `steady_clock::now()` immediately before `JS_PushArg` / `JS_Call` +- [ ] 3.3 Capture end time and `heap_used` after `JS_Call` returns; record `durationMs` and `heapDelta` to `SbmdHandlerInvoker`'s histogram handles; increment the `sbmd.handler.outcome` counter with the resolved outcome value; call `MQuickJsRuntime::RecordHeapSnapshot(usageAfter)` — passing the already-captured post-`JS_Call` `JSMemoryUsage` struct — to update pool health metrics (`sbmd.js.heap.used_bytes` histogram and `sbmd.js.heap.free_bytes`/`peak_bytes` gauges) while the JS mutex is still held; then call `MQuickJsRuntime::TickleSampler()` to notify the idle thread +- [ ] 3.4 Distinguish timeout from exception in outcome: check if `steady_clock::now() > MQuickJsRuntime::GetDeadline()` (or use a flag set before `MQuickJsRuntime::ClearDeadline()`) to emit `"timeout"` vs `"exception"` +- [ ] 3.5 Update `InvokeHandler` call sites in `SpecBasedMatterDeviceDriver`: synchronous paths (`HandleResourceOp`) stack-allocate `OperationContext` with `driverName`, `opType`, `resourceId` (from `resource->id`), and `startTime = steady_clock::now()`, then pass `&opCtx`; deferred callback paths (`HandleDeferredCommandResponse`, `HandleDeferredCommandError`, `ContinueDeferredChain`) pass `&pending.operationCtx` (the persistent context initialized in task 5.2) +- [ ] 3.6 Add mutex wait timing to `HandleResourceOp`, the attribute/event handler paths, and all deferred callback paths (`HandleDeferredCommandResponse`, `HandleDeferredCommandError`, `ContinueDeferredChain`): `auto t0 = steady_clock::now()` before `std::lock_guard`, call `MQuickJsRuntime::RecordMutexWait(elapsed(t0))` after lock acquired +- [ ] 3.7 At each `ResultTerminal::Error` handling site in `SpecBasedMatterDeviceDriver::ExecuteTerminal` and `ContinueDeferredChain`, call `SbmdHandlerInvoker::RecordOutcomeError(driverName, opType, resourceId)` to emit `sbmd.handler.outcome{outcome="error"}` + +## 4. SbmdFactory — driver load instrumentation + +- [ ] 4.0 Add `sbmd.driver.load.duration_ms`, `sbmd.driver.load.heap_bytes`, `sbmd.driver.load.failure`, and `sbmd.driver.registered.count` metric handles as private static members of `SbmdFactory`; add `static void InitializeMetrics()` and `static void ShutdownMetrics()` +- [ ] 4.1 In `RegisterDriversFromDirectory`, capture `heap_used` and `steady_clock::now()` before `SbmdLoader::LoadDriver` call (inside existing `lock_guard`) +- [ ] 4.2 Capture end time and `heap_used` after `sbmdDriver->Activate(ctx)` succeeds; record `durationMs` and `heapDelta` to `SbmdFactory`'s `sbmd.driver.load.duration_ms` and `sbmd.driver.load.heap_bytes` handles with the `"driver"` attribute +- [ ] 4.3 `SbmdFactory::InitializeMetrics()` is called as part of the startup sequence in task 1.2; ensure it runs before the driver load loop begins +- [ ] 4.4 At each `allRegistered = false; continue` branch, increment `SbmdFactory`'s `sbmd.driver.load.failure` counter with `stem` as the `"driver"` attribute and the appropriate `"reason"` string +- [ ] 4.5 After the loading loop, record `count` to `SbmdFactory`'s `sbmd.driver.registered.count` gauge + +## 5. SpecBasedMatterDeviceDriver — deferred operation instrumentation + +- [ ] 5.0 Add `sbmd.deferred.in_flight`, `sbmd.deferred.duration_ms`, `sbmd.deferred.depth`, `sbmd.deferred.timeout`, and `sbmd.deferred.max_depth` metric handles as private static members of `SpecBasedMatterDeviceDriver`; add `static void InitializeMetrics()` and `static void ShutdownMetrics()` +- [ ] 5.1 Add `OperationContext operationCtx` field to `PendingOperation` struct +- [ ] 5.2 Initialize `pending.operationCtx` in `ExecuteRequestCommand` alongside `overallDeadline`: set `operationCtx.driverName`, `operationCtx.opType` (the originating op, e.g., `"write"`), `operationCtx.resourceId` (from `resource->id`), and `operationCtx.startTime = steady_clock::now()` +- [ ] 5.3 Increment `sbmd.deferred.in_flight` gauge in `ExecuteRequestCommand` after `pendingOperations.emplace` succeeds +- [ ] 5.4 In `CompletePendingOperation`, compute `elapsed(pending.operationCtx.startTime)` and record `durationMs` and `depth` to `SpecBasedMatterDeviceDriver`'s deferred histogram handles with `pending.operationCtx.driverName`, `pending.operationCtx.opType`, and `pending.operationCtx.resourceId` attributes; decrement `sbmd.deferred.in_flight` — all before erasing from map +- [ ] 5.5 In `HandleDeferredCommandResponse` at the `now() > overallDeadline` branch, increment `SpecBasedMatterDeviceDriver`'s `sbmd.deferred.timeout` counter with `pending.operationCtx.driverName`, `pending.operationCtx.opType`, and `pending.operationCtx.resourceId` attributes before calling `CompletePendingOperation` +- [ ] 5.6 In `ContinueDeferredChain` at the `deferralDepth >= MAX_DEFERRAL_DEPTH` branch, increment `SpecBasedMatterDeviceDriver`'s `sbmd.deferred.max_depth` counter with `pending.operationCtx.driverName`, `pending.operationCtx.opType`, and `pending.operationCtx.resourceId` attributes before calling `CompletePendingOperation` + +## 6. JS exception event tracking + +- [ ] 6.1 Call `MQuickJsRuntime::RecordJsException("loading", driverStem)` at the JS evaluation failure site in `SbmdLoader::LoadDriver` +- [ ] 6.2 Call `MQuickJsRuntime::RecordJsException("init", nullptr)` at the polyfill/bundle failure sites in `MQuickJsRuntime::Initialize` and `SbmdBundleLoader` +- [ ] 6.3 No handler-phase recording here — handler exceptions are fully captured by `sbmd.handler.outcome{outcome="exception"}` (task 3.3); `sbmd.js.exception` covers only `"init"` and `"loading"` phases + +## 7. Unit tests — SbmdObservabilityTest.cpp + +- [ ] 7.1 Create `core/test/src/SbmdObservabilityTest.cpp` with `SetUpTestSuite` calling `MQuickJsRuntime::InitializeMetrics()` first, then `MQuickJsRuntime::Initialize(512*1024)`, then `SbmdHandlerInvoker::InitializeMetrics()`, `SbmdFactory::InitializeMetrics()`, and `SpecBasedMatterDeviceDriver::InitializeMetrics()` (per task 1.2 ordering), then `SbmdBundleLoader::LoadBundle` and `SbmdLoader::InjectCaptureFunction` +- [ ] 7.2 Write a minimal test driver JS string (inline, no file) and load it via `SbmdLoader::LoadDriver` for use across tests +- [ ] 7.3 Test: `ForceSnapshot` produces pool health histogram observation — call `MQuickJsRuntime::ForceSnapshot()`, parse `observabilityDumpJson()`, assert `sbmd.js.heap.used_bytes` count >= 1 +- [ ] 7.4 Test: arena size gauge recorded at init — assert `sbmd.js.heap.arena_bytes` value equals 512*1024 +- [ ] 7.5 Test: handler duration histogram populated — invoke a handler, assert `sbmd.handler.duration_ms` count increased and sum > 0 +- [ ] 7.6 Test: heap delta histogram populated — invoke a handler, assert `sbmd.handler.heap_delta_bytes` count increased +- [ ] 7.7 Test: success outcome counter increments on happy path +- [ ] 7.8 Test: exception outcome counter increments when handler throws +- [ ] 7.9 Test: driver load cost metrics populated — call `SbmdFactory::RegisterDriversFromDirectory` with a temp directory containing a minimal valid `.sbmd.js` test file; assert `sbmd.driver.load.duration_ms` and `sbmd.driver.load.heap_bytes` each have at least one observation (direct calls to `SbmdLoader::LoadDriver` bypass the factory instrumentation at tasks 4.1–4.2) +- [ ] 7.10 Test: driver load failure counter increments — call `SbmdFactory::RegisterDriversFromDirectory` with a directory containing a `.sbmd.js` file whose content is syntactically invalid JS; assert `sbmd.driver.load.failure{reason="eval_failed"}` increments by one (task 4.4 records the counter inside `RegisterDriversFromDirectory`, not inside `SbmdLoader::LoadDriver`) +- [ ] 7.11 Add `SbmdObservabilityTest.cpp` to `core/CMakeLists.txt` test target +- [ ] 7.12 Test: mutex wait histogram populated — have a second thread acquire and hold `MQuickJsRuntime::GetMutex()`, then on the main thread trigger a handler invocation through the normal path that takes `std::lock_guard(MQuickJsRuntime::GetMutex())` before calling `InvokeHandler` (e.g., drive it through `SpecBasedMatterDeviceDriver`'s handler path or a test helper that mirrors it); once the second thread releases the lock the main thread acquires it, calls `InvokeHandler`, and `RecordMutexWait` records the wait; assert `sbmd.js.mutex.wait_ms` has at least one non-zero observation +- [ ] 7.13 Test: loading-phase exception counter increments — call `SbmdLoader::LoadDriver` with syntactically invalid JS; assert `sbmd.js.exception{phase="loading"}` increments by one +- [ ] 7.14 Test: registered driver count gauge records correct value — call `SbmdFactory::RegisterDriversFromDirectory` with a temp directory containing N valid `.sbmd.js` test files; assert `sbmd.driver.registered.count` gauge equals N (task 4.5 records this gauge inside `RegisterDriversFromDirectory`, not inside `SbmdLoader::LoadDriver`) + +## 8. Integration tests — deferred operation metrics + +- [ ] 8.1 Verify the matter.js virtual device framework supports triggering a deferred command path (a write or execute that returns `requestCommand`) deterministically with a simulated device +- [ ] 8.2 Write pytest test: commission simulated device, trigger one deferred operation, call `b_core_client_get_telemetry()`, parse JSON, assert `sbmd.deferred.in_flight` was nonzero during op and `sbmd.deferred.duration_ms` has one observation after completion +- [ ] 8.3 Write pytest test: assert `sbmd.deferred.depth` records 0 for a single-round-trip operation