From c769264a4fccd2b933b35b254c2e449300f0a31f Mon Sep 17 00:00:00 2001 From: rchowdcmcsa Date: Tue, 14 Jul 2026 17:30:47 +0000 Subject: [PATCH 01/24] openspec: propose SBMD runtime observability instrumentation Add change proposal, design, spec, and task list for wiring the existing observability API into the SBMDv4 JS runtime. Metrics defined: - JS heap pool health (used, free, arena, peak, free blocks) via periodic background sampler in MQuickJsRuntime - Per-invocation handler duration, heap delta, and outcome (success/exception/timeout/stack_overflow/error) via SbmdHandlerInvoker::InvokeHandler - JS mutex wait time per handler invocation path - Driver load cost (duration, heap bytes) and failure counts per driver and failure reason - Registered driver count at startup - Deferred operation lifecycle: in-flight gauge, total duration, deferral depth, timeout count, max-depth-exceeded count; all attributed by driver and originating op type via new origOpType field on PendingOperation - JS exception events (init and loading phases only) All metrics are centralized in a new SbmdMetrics class. GC tracking is deferred to a follow-on change. --- .../.openspec.yaml | 2 + .../design.md | 134 +++++++++++++ .../proposal.md | 46 +++++ .../specs/sbmd-runtime-observability/spec.md | 176 ++++++++++++++++++ .../tasks.md | 71 +++++++ 5 files changed, 429 insertions(+) create mode 100644 openspec/changes/sbmd-observability-instrumentation/.openspec.yaml create mode 100644 openspec/changes/sbmd-observability-instrumentation/design.md create mode 100644 openspec/changes/sbmd-observability-instrumentation/proposal.md create mode 100644 openspec/changes/sbmd-observability-instrumentation/specs/sbmd-runtime-observability/spec.md create mode 100644 openspec/changes/sbmd-observability-instrumentation/tasks.md 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..c4e26d48 --- /dev/null +++ b/openspec/changes/sbmd-observability-instrumentation/design.md @@ -0,0 +1,134 @@ +## Context + +SBMDv4 runs all device driver JavaScript through a single shared mquickjs context — a pre-allocated, fixed-size arena (default 1 MB) protected by a single mutex. Every resource read/write/execute, attribute report, and event goes through `SbmdHandlerInvoker::InvokeHandler`, which acquires this mutex and calls `JS_Call`. 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. It is fully implemented but has zero call sites in production code 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 +- Centralize all SBMD metric handles in a single `SbmdMetrics` class +- Provide a synchronous `ForceSnapshot()` API for the periodic heap sampler (usable in tests and on-demand telemetry) +- Attribute per-driver and per-operation-type metrics using the `"driver"` and `"op_type"` 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: Centralized `SbmdMetrics` class + +All metric handles (histograms, gauges, counters) live as static members of a new `SbmdMetrics` class in `core/deviceDrivers/matter/sbmd/SbmdMetrics.h/.cpp`. Recording functions (`RecordHandlerInvocation`, `RecordDriverLoad`, `RecordDeferredOpComplete`, etc.) are called from the existing code paths. + +**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. Centralizing in `SbmdMetrics` mirrors the `MQuickJsRuntime` singleton pattern already established in this subsystem. + +### Decision 2: `SbmdHandlerInvoker::InvokeHandler` signature extension + +`InvokeHandler` is extended with two optional parameters: `const char *driverName = nullptr, const char *opType = nullptr`. All existing callers compile unchanged (default nulls suppress attribution). Callers that know both values (`HandleResourceOp`, `HandleDeferredCommandResponse`, `HandleDeferredCommandError`, `ContinueDeferredChain`) pass them through. + +**Why not wrap `InvokeHandler` in a separate metered function?** The parameters are optional with safe defaults — this avoids a parallel API surface and keeps the call graph simple. + +**What is measured around `JS_Call`:** +- `steady_clock::now()` before and after → invocation duration histogram +- `JS_GetMemoryUsage` before and after → heap delta histogram +- Exception / timeout / stack overflow distinction → outcome counter + +### Decision 3: Periodic heap sampler as a background thread in `MQuickJsRuntime` + +A `std::thread` is started at the end of `MQuickJsRuntime::Initialize()` and stopped in `Shutdown()`. The thread calls `SbmdMetrics::ForceSnapshot()` in a loop, sleeping for `BCORE_SBMD_METRICS_SAMPLE_PERIOD_MS` (default 30000 ms, configurable at CMake time) between calls. `ForceSnapshot()` handles all mutex management internally. + +**Why a background thread rather than sampling only on invocations?** Post-invocation sampling misses idle-state heap trends and slow leaks between bursts of activity. Pool utilization between invocations is a meaningful signal. + +**`SbmdMetrics::ForceSnapshot()`** is a public synchronous function that performs the same snapshot operation without sleeping. Used in unit tests and available for on-demand telemetry refresh. The thread simply calls this function in its loop. + +``` +MQuickJsRuntime::Initialize() + │ + ├── JS_NewContext(memBuffer, memSize) + ├── SbmdBundleLoader + SbmdLoader injection + └── starts periodicSamplerThread + │ + └── loop: + SbmdMetrics::ForceSnapshot() ← acquires mutex internally + sleep(SAMPLE_PERIOD_MS) +``` + +**Thread safety:** `ForceSnapshot()` acquires `MQuickJsRuntime::GetMutex()` before calling `JS_GetMemoryUsage`, the same mutex held during all JS execution. This prevents concurrent access to the JSContext. + +### Decision 4: `PendingOperation` extended with `startTime` + +A `std::chrono::steady_clock::time_point startTime` field is added to `PendingOperation`. It is set alongside `overallDeadline` in `ExecuteRequestCommand`. `CompletePendingOperation` — the single convergence point for all deferred op exits — reads it to compute total duration. + +**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. + +`origOpType` (e.g., `"write"` or `"execute"`) is also added to `PendingOperation` so that the deferred metrics carry the originating operation type through the full chain. It is used as the `"op_type"` attribute on `sbmd.deferred.duration_ms`, `sbmd.deferred.depth`, `sbmd.deferred.timeout`, and `sbmd.deferred.max_depth`. + +### 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"` / `"deferred_response"` / `"deferred_error"` | invocation, outcome, deferred | +| `"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 `"op_type"` for deferred lifecycle metrics:** For handler callback invocations going through `InvokeHandler` (op_type `"deferred_response"` / `"deferred_error"`), `"op_type"` reflects the callback type. For deferred lifecycle metrics (`sbmd.deferred.duration_ms`, `sbmd.deferred.depth`, `sbmd.deferred.timeout`, `sbmd.deferred.max_depth`), `"op_type"` uses `pending.origOpType` — the originating operation type (e.g., `"write"` or `"execute"`) captured when the `PendingOperation` was created. + +`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/SbmdMetricsTest.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, adding `SbmdMetrics::Initialize()` to the setup. 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. + +**Periodic sampler in tests**: Tests call `SbmdMetrics::ForceSnapshot()` directly rather than waiting for the background thread. This avoids time-dependent test flakiness entirely. + +## Component diagram + +``` +core/deviceDrivers/matter/sbmd/ +│ +├── SbmdMetrics.h / SbmdMetrics.cpp ← NEW: owns all metric handles +│ ├── Initialize() / Shutdown() +│ ├── ForceSnapshot() ← synchronous heap snapshot +│ ├── RecordHandlerInvocation(...) +│ ├── RecordDriverLoad(...) +│ ├── RecordMemorySnapshot(...) +│ └── RecordDeferredOpComplete(...) +│ +├── mquickjs/ +│ ├── MQuickJsRuntime.cpp ← adds periodicSamplerThread +│ └── SbmdHandlerInvoker.cpp ← InvokeHandler extended +│ +├── SbmdFactory.cpp ← driver load cost metrics +└── SpecBasedMatterDeviceDriver.cpp ← deferred op metrics; PendingOperation.startTime + origOpType + mutex wait timing +``` + +## Risks / Trade-offs + +- **Mutex contention from sampler thread** → The periodic sampler acquires the JS mutex briefly to call `JS_GetMemoryUsage`. At 30 s intervals this is negligible. If sample period is lowered significantly (e.g., for tests), brief extra mutex contention is introduced. `ForceSnapshot()` mitigates this in tests by making the thread unnecessary. + +- **`JS_GetMemoryUsage` overhead inside `InvokeHandler`** → Called twice per invocation (before + after `JS_Call`). The mquickjs implementation is an O(1) struct read (no heap walk; the `JS_MEMUSAGE_WALK_HEAP` flag is not set). Overhead is negligible. + +- **Heap delta sign** → If implicit GC fires during an invocation, `heap_used` may drop. The delta will be negative, which is valid and informative. Histograms accept negative values (the OTel SDK default buckets go below zero). 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. diff --git a/openspec/changes/sbmd-observability-instrumentation/proposal.md b/openspec/changes/sbmd-observability-instrumentation/proposal.md new file mode 100644 index 00000000..060b56f8 --- /dev/null +++ b/openspec/changes/sbmd-observability-instrumentation/proposal.md @@ -0,0 +1,46 @@ +## Why + +The SBMDv4 JavaScript runtime (mquickjs) runs inside a fixed 1 MB arena 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 + +- **New `SbmdMetrics` class** (`core/deviceDrivers/matter/sbmd/SbmdMetrics.h/.cpp`): owns all SBMD metric handles and provides a `ForceSnapshot()` API. +- **Periodic memory sampler** in `MQuickJsRuntime`: a background thread snapshots heap stats at a configurable interval. +- **Per-invocation instrumentation** in `SbmdHandlerInvoker::InvokeHandler`: measures duration, heap delta, and outcome for every JS handler call. Signature extended with optional `driverName` / `opType` attribution parameters (backwards-compatible defaults). +- **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 and originating op type), deferral depth, timeout events, and max-depth-exceeded events. Adds `startTime` and `origOpType` fields 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 file**: `SbmdMetrics.h` / `SbmdMetrics.cpp` +- **Struct change**: `PendingOperation` gains `startTime` and `origOpType` fields +- **API change**: `SbmdHandlerInvoker::InvokeHandler` signature extended (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) controlling the periodic heap sampler interval +- **Dependencies**: existing `observabilityMetrics.h` API; no new external dependencies +- **Tests**: new GTest file `core/test/src/SbmdMetricsTest.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. +- **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..70d91aa2 --- /dev/null +++ b/openspec/changes/sbmd-observability-instrumentation/specs/sbmd-runtime-observability/spec.md @@ -0,0 +1,176 @@ +## ADDED Requirements + +### Requirement: JS heap pool utilization tracking +The SBMD runtime SHALL periodically sample the mquickjs heap and record pool utilization as a histogram named `sbmd.js.heap.used_bytes`. The sample period SHALL be configurable at CMake time via `BCORE_SBMD_METRICS_SAMPLE_PERIOD_MS` (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 gauges for current free bytes (`sbmd.js.heap.free_bytes`) and free block count (`sbmd.js.heap.free_blocks`) updated with each sample. + +#### Scenario: Heap utilization sampled periodically +- **WHEN** the mquickjs runtime is initialized and drivers are loaded +- **THEN** `sbmd.js.heap.used_bytes` histogram contains at least one observation after `SbmdMetrics::ForceSnapshot()` is called + +#### 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 block count reflects fragmentation +- **WHEN** `SbmdMetrics::ForceSnapshot()` is called after JS handler invocations +- **THEN** `sbmd.js.heap.free_blocks` gauge is updated with the current free block count from `JS_GetMemoryUsage` + +### Requirement: Peak heap watermark gauge +The SBMD runtime SHALL maintain a gauge named `sbmd.js.heap.peak_bytes` recording the highest net heap utilization (`heap_used - heap_free_blocks`) observed since `MQuickJsRuntime::Initialize()`. The gauge SHALL be updated whenever `MQuickJsRuntime::LogMemoryUsage` updates the internal `peakHeapUsed` tracking. + +#### 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 `SbmdMetrics::ForceSnapshot()` public static function that synchronously samples heap stats and records one observation to each pool health metric. This function SHALL be callable without holding the JS mutex (it acquires it internally). The periodic sampler thread SHALL use this function for its loop body. + +#### Scenario: ForceSnapshot produces an immediate observation +- **WHEN** `SbmdMetrics::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` around the `JS_Call` in `SbmdHandlerInvoker::InvokeHandler`. The histogram SHALL support `"driver"` and `"op_type"` attributes. + +#### 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"` and `"op_type"` attributes. + +#### 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 5000 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"`, 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 5000 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 `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 gauge named `sbmd.driver.load.duration_ms` with attribute `"driver"`, and the net heap bytes consumed during load and activation as a gauge 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"` (if known) and `"phase"`. 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"` and `"op_type"` (the originating operation type from `PendingOperation.origOpType`). 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"` and `"op_type"`. 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 the 30 s overall deadline using a counter named `sbmd.deferred.timeout` with attributes `"driver"` and `"op_type"`. + +#### 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"` and `"op_type"`. + +#### 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: SbmdMetrics lifecycle +The `SbmdMetrics` class SHALL provide `Initialize()` and `Shutdown()` static functions. `Initialize()` SHALL create all metric instruments. `Shutdown()` SHALL release all metric handles. `SbmdMetrics::Initialize()` SHALL be called by `SbmdFactory::RegisterDriversFromDirectory` after `MQuickJsRuntime::Initialize()` succeeds. `SbmdMetrics::Shutdown()` SHALL be called by `SbmdFactory` or the subsystem shutdown path. + +#### Scenario: Metrics available after initialization +- **WHEN** `SbmdMetrics::Initialize()` is called +- **THEN** `SbmdMetrics::ForceSnapshot()` and all recording functions operate without error + +#### Scenario: Recording before initialization is safe +- **WHEN** a recording function is called before `SbmdMetrics::Initialize()` +- **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..83016c35 --- /dev/null +++ b/openspec/changes/sbmd-observability-instrumentation/tasks.md @@ -0,0 +1,71 @@ +## 1. SbmdMetrics class scaffold + +- [ ] 1.1 Create `SbmdMetrics.h` declaring all metric handles as private static members and all recording functions as public static functions +- [ ] 1.2 Create `SbmdMetrics.cpp` with `Initialize()` creating all instruments via `observabilityHistogramCreate` / `observabilityGaugeCreate` / `observabilityCounterCreate`, and `Shutdown()` releasing handles +- [ ] 1.3 Implement `SbmdMetrics::ForceSnapshot()`: acquires `MQuickJsRuntime::GetMutex()`, calls `JS_GetMemoryUsage`, records to pool health metrics, releases lock +- [ ] 1.4 Add `SbmdMetrics.cpp` to `core/CMakeLists.txt` SBMD source list +- [ ] 1.5 Add CMake option `BCORE_SBMD_METRICS_SAMPLE_PERIOD_MS` (default 30000) to `config/cmake/options.cmake` +- [ ] 1.6 Wire `SbmdMetrics::Shutdown()` into `SbmdFactory` or the subsystem shutdown path that already calls `MQuickJsRuntime::Shutdown()`; identify the correct call site during implementation + +## 2. MQuickJsRuntime — periodic sampler + +- [ ] 2.1 Add `static std::thread periodicSamplerThread` and `static std::atomic periodicSamplerRunning` to `MQuickJsRuntime` +- [ ] 2.2 Start sampler thread at end of `MQuickJsRuntime::Initialize()`: loop calls `SbmdMetrics::ForceSnapshot()`, sleeps `BCORE_SBMD_METRICS_SAMPLE_PERIOD_MS` ms, exits when `periodicSamplerRunning` is false +- [ ] 2.3 Stop and join thread in `MQuickJsRuntime::Shutdown()` before `JS_FreeContext` +- [ ] 2.4 Record `sbmd.js.heap.arena_bytes` gauge once at end of `MQuickJsRuntime::Initialize()` after context is created + +## 3. SbmdHandlerInvoker — per-invocation instrumentation + +- [ ] 3.1 Extend `SbmdHandlerInvoker::InvokeHandler` signature with `const char *driverName = nullptr, const char *opType = 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; call `SbmdMetrics::RecordHandlerInvocation(driverName, opType, durationMs, heapDelta, outcome)` +- [ ] 3.4 Distinguish timeout from exception in outcome: check if `steady_clock::now() > GetDeadline()` (or use a flag set before `ClearDeadline()`) to emit `"timeout"` vs `"exception"` +- [ ] 3.5 Update all `InvokeHandler` call sites in `SpecBasedMatterDeviceDriver` to pass `driver->GetRegistration().name.c_str()` and the appropriate `opType` string +- [ ] 3.6 Add mutex wait timing to `HandleResourceOp` and the attribute/event handler paths: `auto t0 = steady_clock::now()` before `lock_guard`, record `elapsed(t0)` to `SbmdMetrics::RecordMutexWait` after lock acquired +- [ ] 3.7 At each `ResultTerminal::Error` handling site in `SpecBasedMatterDeviceDriver::ExecuteTerminal` and `ContinueDeferredChain`, call `SbmdMetrics::RecordHandlerOutcomeError(driverName, opType)` to emit `sbmd.handler.outcome{outcome="error"}` + +## 4. SbmdFactory — driver load instrumentation + +- [ ] 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; call `SbmdMetrics::RecordDriverLoad(name, durationMs, heapDelta)` +- [ ] 4.3 Add `SbmdMetrics::Initialize()` call immediately after `MQuickJsRuntime::Initialize()` succeeds in `RegisterDriversFromDirectory` +- [ ] 4.4 At each `allRegistered = false; continue` branch, call `SbmdMetrics::RecordDriverLoadFailure(stem, reason)` with appropriate reason string +- [ ] 4.5 After the loading loop, call `SbmdMetrics::RecordRegisteredDriverCount(count)` with the total successful count + +## 5. SpecBasedMatterDeviceDriver — deferred operation instrumentation + +- [ ] 5.1 Add `std::chrono::steady_clock::time_point startTime` and `std::string origOpType` fields to `PendingOperation` struct +- [ ] 5.2 Set `pending.startTime = steady_clock::now()` and `pending.origOpType = opType` in `ExecuteRequestCommand` alongside `overallDeadline` +- [ ] 5.3 Increment `sbmd.deferred.in_flight` gauge in `ExecuteRequestCommand` after `pendingOperations.emplace` succeeds +- [ ] 5.4 In `CompletePendingOperation`, compute `elapsed(pending.startTime)` and call `SbmdMetrics::RecordDeferredOpComplete(driverName, pending.origOpType, durationMs, depth, success)` before erasing from map; decrement `sbmd.deferred.in_flight` +- [ ] 5.5 In `HandleDeferredCommandResponse` at the `now() > overallDeadline` branch, call `SbmdMetrics::RecordDeferredTimeout(driverName, pending.origOpType)` before calling `CompletePendingOperation` +- [ ] 5.6 In `ContinueDeferredChain` at the `deferralDepth >= MAX_DEFERRAL_DEPTH` branch, call `SbmdMetrics::RecordDeferredMaxDepth(driverName, pending.origOpType)` before calling `CompletePendingOperation` + +## 6. JS exception event tracking + +- [ ] 6.1 Call `SbmdMetrics::RecordJsException("loading", driverStem)` at the JS evaluation failure site in `SbmdLoader::LoadDriver` +- [ ] 6.2 Call `SbmdMetrics::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 — SbmdMetricsTest.cpp + +- [ ] 7.1 Create `core/test/src/SbmdMetricsTest.cpp` with `SetUpTestSuite` calling `MQuickJsRuntime::Initialize(512*1024)`, `SbmdBundleLoader::LoadBundle`, `SbmdLoader::InjectCaptureFunction`, and `SbmdMetrics::Initialize()` +- [ ] 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 `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 value > 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 — assert `sbmd.driver.load.duration_ms` and `sbmd.driver.load.heap_bytes` have observations after `SbmdLoader::LoadDriver` +- [ ] 7.10 Test: driver load failure counter increments when `LoadDriver` is called with invalid JS +- [ ] 7.11 Add `SbmdMetricsTest.cpp` to `core/CMakeLists.txt` test target +- [ ] 7.12 Test: mutex wait histogram populated — hold the JS mutex from a second thread while calling `InvokeHandler` from the main thread to create contention; assert `sbmd.js.mutex.wait_ms` records 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 — load N test drivers; assert `sbmd.driver.registered.count` gauge equals N + +## 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 From c360d3aa552068ab04ba476677dc8a6b8f27cd5c Mon Sep 17 00:00:00 2001 From: rchowdcmcsa Date: Tue, 14 Jul 2026 19:34:51 +0000 Subject: [PATCH 02/24] some review comments --- .../design.md | 114 +++++++++++------- .../proposal.md | 14 +-- .../specs/sbmd-runtime-observability/spec.md | 30 +++-- .../tasks.md | 63 +++++----- 4 files changed, 126 insertions(+), 95 deletions(-) diff --git a/openspec/changes/sbmd-observability-instrumentation/design.md b/openspec/changes/sbmd-observability-instrumentation/design.md index c4e26d48..584b895f 100644 --- a/openspec/changes/sbmd-observability-instrumentation/design.md +++ b/openspec/changes/sbmd-observability-instrumentation/design.md @@ -10,8 +10,8 @@ This design covers how to wire the observability API into the SBMD runtime witho **Goals:** - Instrument all meaningful SBMD runtime events using the existing observability API -- Centralize all SBMD metric handles in a single `SbmdMetrics` class -- Provide a synchronous `ForceSnapshot()` API for the periodic heap sampler (usable in tests and on-demand telemetry) +- 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"` and `"op_type"` attribute keys - Test all metric wiring using the real mquickjs runtime (no mocking required) @@ -23,70 +23,102 @@ This design covers how to wire the observability API into the SBMD runtime witho ## Decisions -### Decision 1: Centralized `SbmdMetrics` class +### Decision 1: Distributed metric ownership -All metric handles (histograms, gauges, counters) live as static members of a new `SbmdMetrics` class in `core/deviceDrivers/matter/sbmd/SbmdMetrics.h/.cpp`. Recording functions (`RecordHandlerInvocation`, `RecordDriverLoad`, `RecordDeferredOpComplete`, etc.) are called from the existing code paths. +Metric handles (histograms, gauges, counters) are private static members of the module that records them. Each module provides `static void InitializeMetrics()` and `ShutdownMetrics()` functions. `SbmdFactory::RegisterDriversFromDirectory` calls all four `InitializeMetrics()` functions after `MQuickJsRuntime::Initialize()` succeeds. -**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. Centralizing in `SbmdMetrics` mirrors the `MQuickJsRuntime` singleton pattern already established in this subsystem. +| Module | Metric handles owned | +|---|---| +| `MQuickJsRuntime` | `sbmd.js.heap.*`, `sbmd.js.heap.peak_bytes`, `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.*` | -### Decision 2: `SbmdHandlerInvoker::InvokeHandler` signature extension +**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)`. +- `sbmd.js.mutex.wait_ms` is measured in `HandleResourceOp` (`SpecBasedMatterDeviceDriver`), `sbmd.js.heap.*` pool health gauges 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(JSContext *ctx)` (requires caller to hold the JS mutex). -`InvokeHandler` is extended with two optional parameters: `const char *driverName = nullptr, const char *opType = nullptr`. All existing callers compile unchanged (default nulls suppress attribution). Callers that know both values (`HandleResourceOp`, `HandleDeferredCommandResponse`, `HandleDeferredCommandError`, `ContinueDeferredChain`) pass them through. +**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()`. -**Why not wrap `InvokeHandler` in a separate metered function?** The parameters are optional with safe defaults — this avoids a parallel API surface and keeps the call graph simple. +### Decision 2: `SbmdHandlerInvoker::InvokeHandler` invocation context parameter + +`InvokeHandler` is extended with a single optional parameter: `const SbmdOperationContext *opCtx = nullptr`. `SbmdOperationContext` is a plain struct defined in `SbmdHandlerInvoker.h`: + +```cpp +struct SbmdOperationContext { + const char *driverName = nullptr; + const char *opType = nullptr; // originating op type (e.g., "write", "execute") + 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 `SbmdOperationContext{driver, opType, 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 around `JS_Call`:** - `steady_clock::now()` before and after → invocation duration histogram - `JS_GetMemoryUsage` before and after → heap delta histogram - Exception / timeout / stack overflow distinction → outcome counter -### Decision 3: Periodic heap sampler as a background thread in `MQuickJsRuntime` +### Decision 3: Hybrid sampling — in-activity captures + tickleable idle thread -A `std::thread` is started at the end of `MQuickJsRuntime::Initialize()` and stopped in `Shutdown()`. The thread calls `SbmdMetrics::ForceSnapshot()` in a loop, sleeping for `BCORE_SBMD_METRICS_SAMPLE_PERIOD_MS` (default 30000 ms, configurable at CMake time) between calls. `ForceSnapshot()` handles all mutex management internally. +Pool health metrics (`sbmd.js.heap.*`) are recorded from two complementary paths: -**Why a background thread rather than sampling only on invocations?** Post-invocation sampling misses idle-state heap trends and slow leaks between bursts of activity. Pool utilization between invocations is a meaningful signal. +**In-activity path:** At the end of every `InvokeHandler` call, while the JS mutex is already held by the caller, `MQuickJsRuntime::RecordHeapSnapshot(ctx)` updates the pool health gauges using the same `JS_GetMemoryUsage` data already captured for the heap delta histogram. `InvokeHandler` then calls `MQuickJsRuntime::TickleSampler()` to notify the idle thread to reset its timer. -**`SbmdMetrics::ForceSnapshot()`** is a public synchronous function that performs the same snapshot operation without sleeping. Used in unit tests and available for on-demand telemetry refresh. The thread simply calls this function in its loop. +**Idle background path:** A `std::thread` in `MQuickJsRuntime` waits on a condition variable with a `BCORE_SBMD_METRICS_SAMPLE_PERIOD_MS` timeout. It calls `ForceSnapshot()` only when the wait times out naturally — meaning no `InvokeHandler` activity has occurred for the full idle period. When woken early by `TickleSampler()`, it resets the timer and waits again without taking a 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(JSContext *ctx)`** records the current `JS_GetMemoryUsage` output to the pool health instruments. Requires the caller to hold the JS mutex. Called from `InvokeHandler`. + +**`MQuickJsRuntime::ForceSnapshot()`** is a public synchronous function that acquires the JS mutex, calls `RecordHeapSnapshot`, releases the mutex, and calls `TickleSampler()`. 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. Calls `samplerCv.notify_one()` *without* acquiring `samplerCvMutex` — the standard C++ idiom; only the waiter needs the lock. Safe to call from any context including while holding the JS mutex. ``` -MQuickJsRuntime::Initialize() - │ - ├── JS_NewContext(memBuffer, memSize) - ├── SbmdBundleLoader + SbmdLoader injection - └── starts periodicSamplerThread - │ - └── loop: - SbmdMetrics::ForceSnapshot() ← acquires mutex internally - sleep(SAMPLE_PERIOD_MS) +InvokeHandler (JS mutex held by caller): Idle background thread: + → JS_Call loop: + → JS_GetMemoryUsage cv.wait_for(SAMPLE_PERIOD_MS) + → record sbmd.handler.* if timed_out (true idle): + → RecordHeapSnapshot(ctx) ← pool health ForceSnapshot() + → TickleSampler() ← reset idle timer // woken early by TickleSampler: + // no snapshot, reset and wait ``` -**Thread safety:** `ForceSnapshot()` acquires `MQuickJsRuntime::GetMutex()` before calling `JS_GetMemoryUsage`, the same mutex held during all JS execution. This prevents concurrent access to the JSContext. +**Thread startup/shutdown:** The thread is started at the end of `MQuickJsRuntime::Initialize()`. In `Shutdown()`, `samplerShouldStop` is set to `true` and `TickleSampler()` is called to wake the thread immediately before joining. -### Decision 4: `PendingOperation` extended with `startTime` +### Decision 4: `PendingOperation` extended with `SbmdOperationContext` -A `std::chrono::steady_clock::time_point startTime` field is added to `PendingOperation`. It is set alongside `overallDeadline` in `ExecuteRequestCommand`. `CompletePendingOperation` — the single convergence point for all deferred op exits — reads it to compute total duration. +A `SbmdOperationContext operationCtx` field is added to `PendingOperation`. It is initialized in `ExecuteRequestCommand` alongside `overallDeadline` with the driver name, originating op type, 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` 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. -`origOpType` (e.g., `"write"` or `"execute"`) is also added to `PendingOperation` so that the deferred metrics carry the originating operation type through the full chain. It is used as the `"op_type"` attribute on `sbmd.deferred.duration_ms`, `sbmd.deferred.depth`, `sbmd.deferred.timeout`, and `sbmd.deferred.max_depth`. - ### 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"` / `"deferred_response"` / `"deferred_error"` | invocation, outcome, deferred | +| `"op_type"` | `"read"` / `"write"` / `"execute"` / `"attribute_report"` / `"event"` | invocation, outcome, deferred | | `"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 `"op_type"` for deferred lifecycle metrics:** For handler callback invocations going through `InvokeHandler` (op_type `"deferred_response"` / `"deferred_error"`), `"op_type"` reflects the callback type. For deferred lifecycle metrics (`sbmd.deferred.duration_ms`, `sbmd.deferred.depth`, `sbmd.deferred.timeout`, `sbmd.deferred.max_depth`), `"op_type"` uses `pending.origOpType` — the originating operation type (e.g., `"write"` or `"execute"`) captured when the `PendingOperation` was created. +**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/SbmdMetricsTest.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, adding `SbmdMetrics::Initialize()` to the setup. Tests invoke handlers via `SbmdHandlerInvoker::InvokeHandler`, then call `observabilityDumpJson()` and parse the JSON to assert: +**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 all four `InitializeMetrics()` functions in `SetUpTestSuite`. 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 @@ -94,33 +126,27 @@ A `std::chrono::steady_clock::time_point startTime` field is added to `PendingOp **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. -**Periodic sampler in tests**: Tests call `SbmdMetrics::ForceSnapshot()` directly rather than waiting for the background thread. This avoids time-dependent test flakiness entirely. +**Periodic 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/ │ -├── SbmdMetrics.h / SbmdMetrics.cpp ← NEW: owns all metric handles -│ ├── Initialize() / Shutdown() -│ ├── ForceSnapshot() ← synchronous heap snapshot -│ ├── RecordHandlerInvocation(...) -│ ├── RecordDriverLoad(...) -│ ├── RecordMemorySnapshot(...) -│ └── RecordDeferredOpComplete(...) -│ ├── mquickjs/ -│ ├── MQuickJsRuntime.cpp ← adds periodicSamplerThread -│ └── SbmdHandlerInvoker.cpp ← InvokeHandler extended +│ ├── MQuickJsRuntime.cpp ← heap metrics, ForceSnapshot(), RecordHeapSnapshot(), +│ │ RecordMutexWait(), RecordJsException(), TickleSampler(); +│ │ in-activity + idle sampling +│ └── SbmdHandlerInvoker.cpp ← invocation/outcome metrics, RecordOutcomeError(); +│ InvokeHandler extended │ -├── SbmdFactory.cpp ← driver load cost metrics -└── SpecBasedMatterDeviceDriver.cpp ← deferred op metrics; PendingOperation.startTime + origOpType - mutex wait timing +├── SbmdFactory.cpp ← driver load metrics +└── SpecBasedMatterDeviceDriver.cpp ← deferred op metrics; PendingOperation.operationCtx (SbmdOperationContext) ``` ## Risks / Trade-offs -- **Mutex contention from sampler thread** → The periodic sampler acquires the JS mutex briefly to call `JS_GetMemoryUsage`. At 30 s intervals this is negligible. If sample period is lowered significantly (e.g., for tests), brief extra mutex contention is introduced. `ForceSnapshot()` mitigates this in tests by making the thread unnecessary. +- **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 + after `JS_Call`). The mquickjs implementation is an O(1) struct read (no heap walk; the `JS_MEMUSAGE_WALK_HEAP` flag is not set). Overhead is negligible. diff --git a/openspec/changes/sbmd-observability-instrumentation/proposal.md b/openspec/changes/sbmd-observability-instrumentation/proposal.md index 060b56f8..197381e3 100644 --- a/openspec/changes/sbmd-observability-instrumentation/proposal.md +++ b/openspec/changes/sbmd-observability-instrumentation/proposal.md @@ -4,11 +4,11 @@ The SBMDv4 JavaScript runtime (mquickjs) runs inside a fixed 1 MB arena with a s ## What Changes -- **New `SbmdMetrics` class** (`core/deviceDrivers/matter/sbmd/SbmdMetrics.h/.cpp`): owns all SBMD metric handles and provides a `ForceSnapshot()` API. +- **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. - **Periodic memory sampler** in `MQuickJsRuntime`: a background thread snapshots heap stats at a configurable interval. -- **Per-invocation instrumentation** in `SbmdHandlerInvoker::InvokeHandler`: measures duration, heap delta, and outcome for every JS handler call. Signature extended with optional `driverName` / `opType` attribution parameters (backwards-compatible defaults). +- **Per-invocation instrumentation** in `SbmdHandlerInvoker::InvokeHandler`: measures duration, heap delta, and outcome for every JS handler call. Signature extended with a single optional `const SbmdOperationContext *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 and originating op type), deferral depth, timeout events, and max-depth-exceeded events. Adds `startTime` and `origOpType` fields to `PendingOperation` struct. +- **Deferred operation instrumentation** in `SpecBasedMatterDeviceDriver`: tracks in-flight count, total duration (attributed by driver and originating op type), deferral depth, timeout events, and max-depth-exceeded events. Adds `SbmdOperationContext 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. @@ -27,13 +27,13 @@ The SBMDv4 JavaScript runtime (mquickjs) runs inside a fixed 1 MB arena with a s ## Impact - **Affected code**: `core/deviceDrivers/matter/sbmd/` (SbmdHandlerInvoker, SbmdFactory, SpecBasedMatterDeviceDriver, MQuickJsRuntime) -- **New file**: `SbmdMetrics.h` / `SbmdMetrics.cpp` -- **Struct change**: `PendingOperation` gains `startTime` and `origOpType` fields -- **API change**: `SbmdHandlerInvoker::InvokeHandler` signature extended (backwards-compatible) +- **New file**: none (metric handles and initialization are added to existing modules) +- **Struct change**: `PendingOperation` gains `SbmdOperationContext operationCtx` field (carries driver name, originating op type, and start time) +- **API change**: `SbmdHandlerInvoker::InvokeHandler` gains a single optional `const SbmdOperationContext *opCtx = nullptr` parameter; new `SbmdOperationContext` 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) controlling the periodic heap sampler interval - **Dependencies**: existing `observabilityMetrics.h` API; no new external dependencies -- **Tests**: new GTest file `core/test/src/SbmdMetricsTest.cpp`; new pytest test in `testing/test/` +- **Tests**: new GTest file `core/test/src/SbmdObservabilityTest.cpp`; new pytest test in `testing/test/` ## Non-Goals 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 index 70d91aa2..501a78c8 100644 --- a/openspec/changes/sbmd-observability-instrumentation/specs/sbmd-runtime-observability/spec.md +++ b/openspec/changes/sbmd-observability-instrumentation/specs/sbmd-runtime-observability/spec.md @@ -1,18 +1,22 @@ ## ADDED Requirements ### Requirement: JS heap pool utilization tracking -The SBMD runtime SHALL periodically sample the mquickjs heap and record pool utilization as a histogram named `sbmd.js.heap.used_bytes`. The sample period SHALL be configurable at CMake time via `BCORE_SBMD_METRICS_SAMPLE_PERIOD_MS` (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 gauges for current free bytes (`sbmd.js.heap.free_bytes`) and free block count (`sbmd.js.heap.free_blocks`) updated with each sample. +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 `BCORE_SBMD_METRICS_SAMPLE_PERIOD_MS` milliseconds (configurable at CMake time, 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 gauges for current free bytes (`sbmd.js.heap.free_bytes`) and free block count (`sbmd.js.heap.free_blocks`) updated with each sample. -#### Scenario: Heap utilization sampled periodically -- **WHEN** the mquickjs runtime is initialized and drivers are loaded -- **THEN** `sbmd.js.heap.used_bytes` histogram contains at least one observation after `SbmdMetrics::ForceSnapshot()` is called +#### 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 attributed to that invocation + +#### Scenario: Heap utilization captured during idle period +- **WHEN** no handler invocations have occurred for `BCORE_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 block count reflects fragmentation -- **WHEN** `SbmdMetrics::ForceSnapshot()` is called after JS handler invocations +- **WHEN** `MQuickJsRuntime::ForceSnapshot()` is called after JS handler invocations - **THEN** `sbmd.js.heap.free_blocks` gauge is updated with the current free block count from `JS_GetMemoryUsage` ### Requirement: Peak heap watermark gauge @@ -23,10 +27,10 @@ The SBMD runtime SHALL maintain a gauge named `sbmd.js.heap.peak_bytes` recordin - **THEN** `sbmd.js.heap.peak_bytes` reflects the highest value observed, never decreasing ### Requirement: Force snapshot API -The system SHALL provide a `SbmdMetrics::ForceSnapshot()` public static function that synchronously samples heap stats and records one observation to each pool health metric. This function SHALL be callable without holding the JS mutex (it acquires it internally). The periodic sampler thread SHALL use this function for its loop body. +The system SHALL provide a `MQuickJsRuntime::ForceSnapshot()` public static function that synchronously samples heap stats, records one observation to each pool health metric, and calls `TickleSampler()` to reset the idle thread's timer. This function SHALL be callable without holding the JS mutex (it acquires it internally). 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** `SbmdMetrics::ForceSnapshot()` is called +- **WHEN** `MQuickJsRuntime::ForceSnapshot()` is called - **THEN** `sbmd.js.heap.used_bytes` observation count increases by one ### Requirement: Per-invocation heap delta tracking @@ -133,7 +137,7 @@ The SBMD runtime SHALL maintain a gauge named `sbmd.deferred.in_flight` represen - **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"` and `"op_type"` (the originating operation type from `PendingOperation.origOpType`). Duration includes device round-trip time. +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"` and `"op_type"` (the originating operation type from `pending.operationCtx.opType`). Duration includes device round-trip time. #### Scenario: Total duration includes device round-trip - **WHEN** a deferred operation completes after a device response @@ -164,13 +168,13 @@ The SBMD runtime SHALL count deferred operations terminated because they reached - **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: SbmdMetrics lifecycle -The `SbmdMetrics` class SHALL provide `Initialize()` and `Shutdown()` static functions. `Initialize()` SHALL create all metric instruments. `Shutdown()` SHALL release all metric handles. `SbmdMetrics::Initialize()` SHALL be called by `SbmdFactory::RegisterDriversFromDirectory` after `MQuickJsRuntime::Initialize()` succeeds. `SbmdMetrics::Shutdown()` SHALL be called by `SbmdFactory` or the subsystem shutdown path. +### Requirement: Subsystem metrics initialization +Each instrumented module (`MQuickJsRuntime`, `SbmdHandlerInvoker`, `SbmdFactory`, `SpecBasedMatterDeviceDriver`) SHALL provide `static void InitializeMetrics()` and `static void ShutdownMetrics()` functions. All four `InitializeMetrics()` calls SHALL be made by `SbmdFactory::RegisterDriversFromDirectory` after `MQuickJsRuntime::Initialize()` succeeds. The corresponding `ShutdownMetrics()` calls SHALL be made in the subsystem shutdown path. #### Scenario: Metrics available after initialization -- **WHEN** `SbmdMetrics::Initialize()` is called -- **THEN** `SbmdMetrics::ForceSnapshot()` and all recording functions operate without error +- **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 `SbmdMetrics::Initialize()` +- **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 index 83016c35..cc0d9c53 100644 --- a/openspec/changes/sbmd-observability-instrumentation/tasks.md +++ b/openspec/changes/sbmd-observability-instrumentation/tasks.md @@ -1,57 +1,58 @@ -## 1. SbmdMetrics class scaffold +## 1. Startup and shutdown wiring -- [ ] 1.1 Create `SbmdMetrics.h` declaring all metric handles as private static members and all recording functions as public static functions -- [ ] 1.2 Create `SbmdMetrics.cpp` with `Initialize()` creating all instruments via `observabilityHistogramCreate` / `observabilityGaugeCreate` / `observabilityCounterCreate`, and `Shutdown()` releasing handles -- [ ] 1.3 Implement `SbmdMetrics::ForceSnapshot()`: acquires `MQuickJsRuntime::GetMutex()`, calls `JS_GetMemoryUsage`, records to pool health metrics, releases lock -- [ ] 1.4 Add `SbmdMetrics.cpp` to `core/CMakeLists.txt` SBMD source list -- [ ] 1.5 Add CMake option `BCORE_SBMD_METRICS_SAMPLE_PERIOD_MS` (default 30000) to `config/cmake/options.cmake` -- [ ] 1.6 Wire `SbmdMetrics::Shutdown()` into `SbmdFactory` or the subsystem shutdown path that already calls `MQuickJsRuntime::Shutdown()`; identify the correct call site during implementation +- [ ] 1.1 Add CMake option `BCORE_SBMD_METRICS_SAMPLE_PERIOD_MS` (default 30000) to `config/cmake/options.cmake` +- [ ] 1.2 In `SbmdFactory::RegisterDriversFromDirectory`, after `MQuickJsRuntime::Initialize()` succeeds, call `MQuickJsRuntime::InitializeMetrics()`, `SbmdHandlerInvoker::InitializeMetrics()`, `SbmdFactory::InitializeMetrics()`, and `SpecBasedMatterDeviceDriver::InitializeMetrics()` (these functions are added in tasks 2.0, 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 — periodic sampler +## 2. MQuickJsRuntime — hybrid heap sampler -- [ ] 2.1 Add `static std::thread periodicSamplerThread` and `static std::atomic periodicSamplerRunning` to `MQuickJsRuntime` -- [ ] 2.2 Start sampler thread at end of `MQuickJsRuntime::Initialize()`: loop calls `SbmdMetrics::ForceSnapshot()`, sleeps `BCORE_SBMD_METRICS_SAMPLE_PERIOD_MS` ms, exits when `periodicSamplerRunning` is false -- [ ] 2.3 Stop and join thread in `MQuickJsRuntime::Shutdown()` before `JS_FreeContext` +- [ ] 2.0 Add heap metric handles (`sbmd.js.heap.used_bytes`, `sbmd.js.heap.arena_bytes`, `sbmd.js.heap.free_bytes`, `sbmd.js.heap.free_blocks`, `sbmd.js.heap.peak_bytes`), `sbmd.js.mutex.wait_ms`, and `sbmd.js.exception` as private static members of `MQuickJsRuntime`; add `static void InitializeMetrics()`, `ShutdownMetrics()`, `ForceSnapshot()`, `RecordHeapSnapshot(JSContext *ctx)`, `TickleSampler()`, `RecordMutexWait(double ms)`, and `RecordJsException(const char *phase, const char *driver)` static functions +- [ ] 2.1 Add `static std::thread periodicSamplerThread`, `static std::atomic samplerShouldStop`, `static std::condition_variable samplerCv`, and `static std::mutex samplerCvMutex` to `MQuickJsRuntime` +- [ ] 2.2 Start idle sampler thread at end of `MQuickJsRuntime::Initialize()`: loop waits on `samplerCv` for up to `BCORE_SBMD_METRICS_SAMPLE_PERIOD_MS` ms; on natural timeout calls `ForceSnapshot()`; on early wakeup (tickled by activity) resets the timer without taking a snapshot +- [ ] 2.3 In `MQuickJsRuntime::Shutdown()`, set `samplerShouldStop = true`, call `TickleSampler()` to wake the thread immediately, then join `periodicSamplerThread` before `JS_FreeContext` - [ ] 2.4 Record `sbmd.js.heap.arena_bytes` gauge once at end of `MQuickJsRuntime::Initialize()` after context is created ## 3. SbmdHandlerInvoker — per-invocation instrumentation -- [ ] 3.1 Extend `SbmdHandlerInvoker::InvokeHandler` signature with `const char *driverName = nullptr, const char *opType = nullptr` (backwards-compatible) +- [ ] 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()`, `ShutdownMetrics()`, and `RecordOutcomeError(const char *driver, const char *opType)` static functions +- [ ] 3.1 Define `SbmdOperationContext` struct in `SbmdHandlerInvoker.h` with fields `const char *driverName = nullptr`, `const char *opType = nullptr`, and `std::chrono::steady_clock::time_point startTime`; extend `SbmdHandlerInvoker::InvokeHandler` with `const SbmdOperationContext *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; call `SbmdMetrics::RecordHandlerInvocation(driverName, opType, durationMs, heapDelta, outcome)` +- [ ] 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(ctx)` to update pool health 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() > GetDeadline()` (or use a flag set before `ClearDeadline()`) to emit `"timeout"` vs `"exception"` -- [ ] 3.5 Update all `InvokeHandler` call sites in `SpecBasedMatterDeviceDriver` to pass `driver->GetRegistration().name.c_str()` and the appropriate `opType` string -- [ ] 3.6 Add mutex wait timing to `HandleResourceOp` and the attribute/event handler paths: `auto t0 = steady_clock::now()` before `lock_guard`, record `elapsed(t0)` to `SbmdMetrics::RecordMutexWait` after lock acquired -- [ ] 3.7 At each `ResultTerminal::Error` handling site in `SpecBasedMatterDeviceDriver::ExecuteTerminal` and `ContinueDeferredChain`, call `SbmdMetrics::RecordHandlerOutcomeError(driverName, opType)` to emit `sbmd.handler.outcome{outcome="error"}` +- [ ] 3.5 Update `InvokeHandler` call sites in `SpecBasedMatterDeviceDriver`: synchronous paths (`HandleResourceOp`) stack-allocate `SbmdOperationContext{driver, opType, steady_clock::now()}` and 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` and the attribute/event handler paths: `auto t0 = steady_clock::now()` before `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)` 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 `ShutdownMetrics()` static functions - [ ] 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; call `SbmdMetrics::RecordDriverLoad(name, durationMs, heapDelta)` -- [ ] 4.3 Add `SbmdMetrics::Initialize()` call immediately after `MQuickJsRuntime::Initialize()` succeeds in `RegisterDriversFromDirectory` -- [ ] 4.4 At each `allRegistered = false; continue` branch, call `SbmdMetrics::RecordDriverLoadFailure(stem, reason)` with appropriate reason string -- [ ] 4.5 After the loading loop, call `SbmdMetrics::RecordRegisteredDriverCount(count)` with the total successful count +- [ ] 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.1 Add `std::chrono::steady_clock::time_point startTime` and `std::string origOpType` fields to `PendingOperation` struct -- [ ] 5.2 Set `pending.startTime = steady_clock::now()` and `pending.origOpType = opType` in `ExecuteRequestCommand` alongside `overallDeadline` +- [ ] 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 `ShutdownMetrics()` static functions +- [ ] 5.1 Add `SbmdOperationContext 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"`), 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.startTime)` and call `SbmdMetrics::RecordDeferredOpComplete(driverName, pending.origOpType, durationMs, depth, success)` before erasing from map; decrement `sbmd.deferred.in_flight` -- [ ] 5.5 In `HandleDeferredCommandResponse` at the `now() > overallDeadline` branch, call `SbmdMetrics::RecordDeferredTimeout(driverName, pending.origOpType)` before calling `CompletePendingOperation` -- [ ] 5.6 In `ContinueDeferredChain` at the `deferralDepth >= MAX_DEFERRAL_DEPTH` branch, call `SbmdMetrics::RecordDeferredMaxDepth(driverName, pending.origOpType)` before calling `CompletePendingOperation` +- [ ] 5.4 In `CompletePendingOperation`, compute `elapsed(pending.operationCtx.startTime)` and record `durationMs` and `depth` to `SpecBasedMatterDeviceDriver`'s deferred histogram handles with `pending.operationCtx.driverName` and `pending.operationCtx.opType` 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` and `pending.operationCtx.opType` 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` and `pending.operationCtx.opType` attributes before calling `CompletePendingOperation` ## 6. JS exception event tracking -- [ ] 6.1 Call `SbmdMetrics::RecordJsException("loading", driverStem)` at the JS evaluation failure site in `SbmdLoader::LoadDriver` -- [ ] 6.2 Call `SbmdMetrics::RecordJsException("init", nullptr)` at the polyfill/bundle failure sites in `MQuickJsRuntime::Initialize` and `SbmdBundleLoader` +- [ ] 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 — SbmdMetricsTest.cpp +## 7. Unit tests — SbmdObservabilityTest.cpp -- [ ] 7.1 Create `core/test/src/SbmdMetricsTest.cpp` with `SetUpTestSuite` calling `MQuickJsRuntime::Initialize(512*1024)`, `SbmdBundleLoader::LoadBundle`, `SbmdLoader::InjectCaptureFunction`, and `SbmdMetrics::Initialize()` +- [ ] 7.1 Create `core/test/src/SbmdObservabilityTest.cpp` with `SetUpTestSuite` calling `MQuickJsRuntime::Initialize(512*1024)`, then all four `InitializeMetrics()` calls per task 1.2, 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 `ForceSnapshot()`, parse `observabilityDumpJson()`, assert `sbmd.js.heap.used_bytes` count >= 1 +- [ ] 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 value > 0 - [ ] 7.6 Test: heap delta histogram populated — invoke a handler, assert `sbmd.handler.heap_delta_bytes` count increased @@ -59,7 +60,7 @@ - [ ] 7.8 Test: exception outcome counter increments when handler throws - [ ] 7.9 Test: driver load cost metrics populated — assert `sbmd.driver.load.duration_ms` and `sbmd.driver.load.heap_bytes` have observations after `SbmdLoader::LoadDriver` - [ ] 7.10 Test: driver load failure counter increments when `LoadDriver` is called with invalid JS -- [ ] 7.11 Add `SbmdMetricsTest.cpp` to `core/CMakeLists.txt` test target +- [ ] 7.11 Add `SbmdObservabilityTest.cpp` to `core/CMakeLists.txt` test target - [ ] 7.12 Test: mutex wait histogram populated — hold the JS mutex from a second thread while calling `InvokeHandler` from the main thread to create contention; assert `sbmd.js.mutex.wait_ms` records 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 — load N test drivers; assert `sbmd.driver.registered.count` gauge equals N From 95b8b87a3d7790530615a39ba518dd41fedbc1ae Mon Sep 17 00:00:00 2001 From: rchowdcmcsa Date: Wed, 15 Jul 2026 14:51:40 +0000 Subject: [PATCH 03/24] addressing copilot comments --- .../sbmd-observability-instrumentation/design.md | 2 +- .../sbmd-observability-instrumentation/proposal.md | 2 +- .../specs/sbmd-runtime-observability/spec.md | 14 +++++++------- .../sbmd-observability-instrumentation/tasks.md | 2 +- 4 files changed, 10 insertions(+), 10 deletions(-) diff --git a/openspec/changes/sbmd-observability-instrumentation/design.md b/openspec/changes/sbmd-observability-instrumentation/design.md index 584b895f..ef931286 100644 --- a/openspec/changes/sbmd-observability-instrumentation/design.md +++ b/openspec/changes/sbmd-observability-instrumentation/design.md @@ -148,7 +148,7 @@ core/deviceDrivers/matter/sbmd/ - **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 + after `JS_Call`). The mquickjs implementation is an O(1) struct read (no heap walk; the `JS_MEMUSAGE_WALK_HEAP` flag is not set). Overhead is negligible. +- **`JS_GetMemoryUsage` overhead inside `InvokeHandler`** → Called twice per invocation (before + after `JS_Call`). `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. - **Heap delta sign** → If implicit GC fires during an invocation, `heap_used` may drop. The delta will be negative, which is valid and informative. Histograms accept negative values (the OTel SDK default buckets go below zero). This is expected behavior, not a bug. diff --git a/openspec/changes/sbmd-observability-instrumentation/proposal.md b/openspec/changes/sbmd-observability-instrumentation/proposal.md index 197381e3..8dae179f 100644 --- a/openspec/changes/sbmd-observability-instrumentation/proposal.md +++ b/openspec/changes/sbmd-observability-instrumentation/proposal.md @@ -27,7 +27,7 @@ The SBMDv4 JavaScript runtime (mquickjs) runs inside a fixed 1 MB arena with a s ## Impact - **Affected code**: `core/deviceDrivers/matter/sbmd/` (SbmdHandlerInvoker, SbmdFactory, SpecBasedMatterDeviceDriver, MQuickJsRuntime) -- **New file**: none (metric handles and initialization are added to existing modules) +- **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 `SbmdOperationContext operationCtx` field (carries driver name, originating op type, and start time) - **API change**: `SbmdHandlerInvoker::InvokeHandler` gains a single optional `const SbmdOperationContext *opCtx = nullptr` parameter; new `SbmdOperationContext` 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 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 index 501a78c8..d70ccf40 100644 --- a/openspec/changes/sbmd-observability-instrumentation/specs/sbmd-runtime-observability/spec.md +++ b/openspec/changes/sbmd-observability-instrumentation/specs/sbmd-runtime-observability/spec.md @@ -1,7 +1,7 @@ ## 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 `BCORE_SBMD_METRICS_SAMPLE_PERIOD_MS` milliseconds (configurable at CMake time, 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 gauges for current free bytes (`sbmd.js.heap.free_bytes`) and free block count (`sbmd.js.heap.free_blocks`) updated with each sample. +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 `BCORE_SBMD_METRICS_SAMPLE_PERIOD_MS` milliseconds (configurable at CMake time, 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` @@ -15,12 +15,12 @@ The SBMD runtime SHALL record mquickjs heap pool utilization as a histogram name - **WHEN** `MQuickJsRuntime::Initialize(N)` is called - **THEN** the `sbmd.js.heap.arena_bytes` gauge records the value `N` -#### Scenario: Free block count reflects fragmentation -- **WHEN** `MQuickJsRuntime::ForceSnapshot()` is called after JS handler invocations -- **THEN** `sbmd.js.heap.free_blocks` gauge is updated with the current free block count from `JS_GetMemoryUsage` +#### 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 net heap utilization (`heap_used - heap_free_blocks`) observed since `MQuickJsRuntime::Initialize()`. The gauge SHALL be updated whenever `MQuickJsRuntime::LogMemoryUsage` updates the internal `peakHeapUsed` tracking. +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 @@ -52,7 +52,7 @@ The SBMD runtime SHALL record the wall-clock duration of each JS handler invocat - **THEN** `sbmd.handler.duration_ms` gains one observation greater than zero #### Scenario: Timeout invocations are recorded -- **WHEN** a JS handler exceeds the 5000 ms execution deadline and is interrupted +- **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 @@ -67,7 +67,7 @@ The SBMD runtime SHALL count handler invocation outcomes using a counter named ` - **THEN** `sbmd.handler.outcome` counter for `outcome="exception"` increments by one #### Scenario: Timeout outcome counted -- **WHEN** a JS handler exceeds the 5000 ms deadline and the interrupt handler fires +- **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 diff --git a/openspec/changes/sbmd-observability-instrumentation/tasks.md b/openspec/changes/sbmd-observability-instrumentation/tasks.md index cc0d9c53..c0bfaf2e 100644 --- a/openspec/changes/sbmd-observability-instrumentation/tasks.md +++ b/openspec/changes/sbmd-observability-instrumentation/tasks.md @@ -6,7 +6,7 @@ ## 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.free_blocks`, `sbmd.js.heap.peak_bytes`), `sbmd.js.mutex.wait_ms`, and `sbmd.js.exception` as private static members of `MQuickJsRuntime`; add `static void InitializeMetrics()`, `ShutdownMetrics()`, `ForceSnapshot()`, `RecordHeapSnapshot(JSContext *ctx)`, `TickleSampler()`, `RecordMutexWait(double ms)`, and `RecordJsException(const char *phase, const char *driver)` static functions +- [ ] 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 `static void InitializeMetrics()`, `ShutdownMetrics()`, `ForceSnapshot()`, `RecordHeapSnapshot(JSContext *ctx)`, `TickleSampler()`, `RecordMutexWait(double ms)`, and `RecordJsException(const char *phase, const char *driver)` static functions - [ ] 2.1 Add `static std::thread periodicSamplerThread`, `static std::atomic samplerShouldStop`, `static std::condition_variable samplerCv`, and `static std::mutex samplerCvMutex` to `MQuickJsRuntime` - [ ] 2.2 Start idle sampler thread at end of `MQuickJsRuntime::Initialize()`: loop waits on `samplerCv` for up to `BCORE_SBMD_METRICS_SAMPLE_PERIOD_MS` ms; on natural timeout calls `ForceSnapshot()`; on early wakeup (tickled by activity) resets the timer without taking a snapshot - [ ] 2.3 In `MQuickJsRuntime::Shutdown()`, set `samplerShouldStop = true`, call `TickleSampler()` to wake the thread immediately, then join `periodicSamplerThread` before `JS_FreeContext` From 926a4fa17ef69a9f5b91b55be6388c6d33a0c408 Mon Sep 17 00:00:00 2001 From: rchowdcmcsa Date: Wed, 15 Jul 2026 15:14:59 +0000 Subject: [PATCH 04/24] more copilot comments --- openspec/changes/sbmd-observability-instrumentation/design.md | 4 ++-- .../changes/sbmd-observability-instrumentation/proposal.md | 4 ++-- .../specs/sbmd-runtime-observability/spec.md | 4 ++-- openspec/changes/sbmd-observability-instrumentation/tasks.md | 4 ++-- 4 files changed, 8 insertions(+), 8 deletions(-) diff --git a/openspec/changes/sbmd-observability-instrumentation/design.md b/openspec/changes/sbmd-observability-instrumentation/design.md index ef931286..5c112632 100644 --- a/openspec/changes/sbmd-observability-instrumentation/design.md +++ b/openspec/changes/sbmd-observability-instrumentation/design.md @@ -29,7 +29,7 @@ Metric handles (histograms, gauges, counters) are private static members of the | Module | Metric handles owned | |---|---| -| `MQuickJsRuntime` | `sbmd.js.heap.*`, `sbmd.js.heap.peak_bytes`, `sbmd.js.mutex.wait_ms`, `sbmd.js.exception` | +| `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.*` | @@ -71,7 +71,7 @@ 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(ctx)` updates the pool health gauges using the same `JS_GetMemoryUsage` data already captured for the heap delta histogram. `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 `BCORE_SBMD_METRICS_SAMPLE_PERIOD_MS` timeout. It calls `ForceSnapshot()` only when the wait times out naturally — meaning no `InvokeHandler` activity has occurred for the full idle period. When woken early by `TickleSampler()`, it resets the timer and waits again without taking a snapshot. +**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). It calls `ForceSnapshot()` only when the wait times out naturally — meaning no `InvokeHandler` activity has occurred for the full idle period. When woken early by `TickleSampler()`, it resets the timer and waits again without taking a 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. diff --git a/openspec/changes/sbmd-observability-instrumentation/proposal.md b/openspec/changes/sbmd-observability-instrumentation/proposal.md index 8dae179f..e1c79f2e 100644 --- a/openspec/changes/sbmd-observability-instrumentation/proposal.md +++ b/openspec/changes/sbmd-observability-instrumentation/proposal.md @@ -5,7 +5,7 @@ The SBMDv4 JavaScript runtime (mquickjs) runs inside a fixed 1 MB arena with a s ## 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. -- **Periodic memory sampler** in `MQuickJsRuntime`: a background thread snapshots heap stats at a configurable interval. +- **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 SbmdOperationContext *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 and originating op type), deferral depth, timeout events, and max-depth-exceeded events. Adds `SbmdOperationContext operationCtx` field to `PendingOperation` struct. @@ -31,7 +31,7 @@ The SBMDv4 JavaScript runtime (mquickjs) runs inside a fixed 1 MB arena with a s - **Struct change**: `PendingOperation` gains `SbmdOperationContext operationCtx` field (carries driver name, originating op type, and start time) - **API change**: `SbmdHandlerInvoker::InvokeHandler` gains a single optional `const SbmdOperationContext *opCtx = nullptr` parameter; new `SbmdOperationContext` 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) controlling the periodic heap sampler interval +- **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/` 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 index d70ccf40..99aca304 100644 --- a/openspec/changes/sbmd-observability-instrumentation/specs/sbmd-runtime-observability/spec.md +++ b/openspec/changes/sbmd-observability-instrumentation/specs/sbmd-runtime-observability/spec.md @@ -1,14 +1,14 @@ ## 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 `BCORE_SBMD_METRICS_SAMPLE_PERIOD_MS` milliseconds (configurable at CMake time, 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. +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 attributed to that invocation #### Scenario: Heap utilization captured during idle period -- **WHEN** no handler invocations have occurred for `BCORE_SBMD_METRICS_SAMPLE_PERIOD_MS` milliseconds +- **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 diff --git a/openspec/changes/sbmd-observability-instrumentation/tasks.md b/openspec/changes/sbmd-observability-instrumentation/tasks.md index c0bfaf2e..b8930310 100644 --- a/openspec/changes/sbmd-observability-instrumentation/tasks.md +++ b/openspec/changes/sbmd-observability-instrumentation/tasks.md @@ -1,6 +1,6 @@ ## 1. Startup and shutdown wiring -- [ ] 1.1 Add CMake option `BCORE_SBMD_METRICS_SAMPLE_PERIOD_MS` (default 30000) to `config/cmake/options.cmake` +- [ ] 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`, after `MQuickJsRuntime::Initialize()` succeeds, call `MQuickJsRuntime::InitializeMetrics()`, `SbmdHandlerInvoker::InitializeMetrics()`, `SbmdFactory::InitializeMetrics()`, and `SpecBasedMatterDeviceDriver::InitializeMetrics()` (these functions are added in tasks 2.0, 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 @@ -8,7 +8,7 @@ - [ ] 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 `static void InitializeMetrics()`, `ShutdownMetrics()`, `ForceSnapshot()`, `RecordHeapSnapshot(JSContext *ctx)`, `TickleSampler()`, `RecordMutexWait(double ms)`, and `RecordJsException(const char *phase, const char *driver)` static functions - [ ] 2.1 Add `static std::thread periodicSamplerThread`, `static std::atomic samplerShouldStop`, `static std::condition_variable samplerCv`, and `static std::mutex samplerCvMutex` to `MQuickJsRuntime` -- [ ] 2.2 Start idle sampler thread at end of `MQuickJsRuntime::Initialize()`: loop waits on `samplerCv` for up to `BCORE_SBMD_METRICS_SAMPLE_PERIOD_MS` ms; on natural timeout calls `ForceSnapshot()`; on early wakeup (tickled by activity) resets the timer without taking a snapshot +- [ ] 2.2 Start idle sampler thread at end of `MQuickJsRuntime::Initialize()`: loop waits on `samplerCv` for up to `BARTON_CONFIG_SBMD_METRICS_SAMPLE_PERIOD_MS` ms; on natural timeout calls `ForceSnapshot()`; on early wakeup (tickled by activity) resets the timer without taking a snapshot - [ ] 2.3 In `MQuickJsRuntime::Shutdown()`, set `samplerShouldStop = true`, call `TickleSampler()` to wake the thread immediately, then join `periodicSamplerThread` before `JS_FreeContext` - [ ] 2.4 Record `sbmd.js.heap.arena_bytes` gauge once at end of `MQuickJsRuntime::Initialize()` after context is created From 01d8b981e45d730b9c10de1be5d9011140be96dd Mon Sep 17 00:00:00 2001 From: rchowdcmcsa Date: Wed, 15 Jul 2026 15:25:34 +0000 Subject: [PATCH 05/24] more copilot comments --- .../changes/sbmd-observability-instrumentation/design.md | 6 +++--- .../specs/sbmd-runtime-observability/spec.md | 2 +- .../changes/sbmd-observability-instrumentation/tasks.md | 2 +- 3 files changed, 5 insertions(+), 5 deletions(-) diff --git a/openspec/changes/sbmd-observability-instrumentation/design.md b/openspec/changes/sbmd-observability-instrumentation/design.md index 5c112632..8b509a13 100644 --- a/openspec/changes/sbmd-observability-instrumentation/design.md +++ b/openspec/changes/sbmd-observability-instrumentation/design.md @@ -71,7 +71,7 @@ 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(ctx)` updates the pool health gauges using the same `JS_GetMemoryUsage` data already captured for the heap delta histogram. `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). It calls `ForceSnapshot()` only when the wait times out naturally — meaning no `InvokeHandler` activity has occurred for the full idle period. When woken early by `TickleSampler()`, it resets the timer and waits again without taking a snapshot. +**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 woken early by `TickleSampler()`, it resets the timer and re-checks `samplerShouldStop` without taking a 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. @@ -126,7 +126,7 @@ A `SbmdOperationContext operationCtx` field is added to `PendingOperation`. It i **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. -**Periodic sampler in tests**: Tests call `MQuickJsRuntime::ForceSnapshot()` directly rather than waiting for the background thread. This avoids time-dependent test flakiness entirely. +**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 @@ -150,7 +150,7 @@ core/deviceDrivers/matter/sbmd/ - **`JS_GetMemoryUsage` overhead inside `InvokeHandler`** → Called twice per invocation (before + after `JS_Call`). `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. -- **Heap delta sign** → If implicit GC fires during an invocation, `heap_used` may drop. The delta will be negative, which is valid and informative. Histograms accept negative values (the OTel SDK default buckets go below zero). This is expected behavior, not a bug. +- **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 observations are recorded in the histogram's underflow bucket. 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. 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 index 99aca304..b4c851f2 100644 --- a/openspec/changes/sbmd-observability-instrumentation/specs/sbmd-runtime-observability/spec.md +++ b/openspec/changes/sbmd-observability-instrumentation/specs/sbmd-runtime-observability/spec.md @@ -155,7 +155,7 @@ The SBMD runtime SHALL record the deferral depth at completion of each deferred - **THEN** `sbmd.deferred.depth` records 2 for that driver ### Requirement: Deferred operation timeout counting -The SBMD runtime SHALL count deferred operations that exceed the 30 s overall deadline using a counter named `sbmd.deferred.timeout` with attributes `"driver"` and `"op_type"`. +The SBMD runtime SHALL count deferred operations that exceed their configured `overallDeadline` using a counter named `sbmd.deferred.timeout` with attributes `"driver"` and `"op_type"`. 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 diff --git a/openspec/changes/sbmd-observability-instrumentation/tasks.md b/openspec/changes/sbmd-observability-instrumentation/tasks.md index b8930310..663d596d 100644 --- a/openspec/changes/sbmd-observability-instrumentation/tasks.md +++ b/openspec/changes/sbmd-observability-instrumentation/tasks.md @@ -8,7 +8,7 @@ - [ ] 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 `static void InitializeMetrics()`, `ShutdownMetrics()`, `ForceSnapshot()`, `RecordHeapSnapshot(JSContext *ctx)`, `TickleSampler()`, `RecordMutexWait(double ms)`, and `RecordJsException(const char *phase, const char *driver)` static functions - [ ] 2.1 Add `static std::thread periodicSamplerThread`, `static std::atomic samplerShouldStop`, `static std::condition_variable samplerCv`, and `static std::mutex samplerCvMutex` to `MQuickJsRuntime` -- [ ] 2.2 Start idle sampler thread at end of `MQuickJsRuntime::Initialize()`: loop waits on `samplerCv` for up to `BARTON_CONFIG_SBMD_METRICS_SAMPLE_PERIOD_MS` ms; on natural timeout calls `ForceSnapshot()`; on early wakeup (tickled by activity) resets the timer without taking a snapshot +- [ ] 2.2 Start idle sampler thread at end of `MQuickJsRuntime::Initialize()`: loop checks `samplerShouldStop` and exits if set; otherwise waits on `samplerCv` for up to `BARTON_CONFIG_SBMD_METRICS_SAMPLE_PERIOD_MS` ms; on natural timeout calls `ForceSnapshot()`; on early wakeup (tickled by activity or shutdown) resets the timer without taking a snapshot, then re-checks `samplerShouldStop` - [ ] 2.3 In `MQuickJsRuntime::Shutdown()`, set `samplerShouldStop = true`, call `TickleSampler()` to wake the thread immediately, then join `periodicSamplerThread` before `JS_FreeContext` - [ ] 2.4 Record `sbmd.js.heap.arena_bytes` gauge once at end of `MQuickJsRuntime::Initialize()` after context is created From cab231ced5fbcbda5b833ab9ac56daacb8a5a0f9 Mon Sep 17 00:00:00 2001 From: rchowdcmcsa Date: Wed, 15 Jul 2026 17:04:54 +0000 Subject: [PATCH 06/24] more code review comments --- .../design.md | 21 ++++++++++-------- .../proposal.md | 8 +++---- .../specs/sbmd-runtime-observability/spec.md | 18 +++++++-------- .../tasks.md | 22 +++++++++---------- 4 files changed, 36 insertions(+), 33 deletions(-) diff --git a/openspec/changes/sbmd-observability-instrumentation/design.md b/openspec/changes/sbmd-observability-instrumentation/design.md index 8b509a13..1df75ead 100644 --- a/openspec/changes/sbmd-observability-instrumentation/design.md +++ b/openspec/changes/sbmd-observability-instrumentation/design.md @@ -36,18 +36,19 @@ Metric handles (histograms, gauges, counters) are private static members of the **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)`. -- `sbmd.js.mutex.wait_ms` is measured in `HandleResourceOp` (`SpecBasedMatterDeviceDriver`), `sbmd.js.heap.*` pool health gauges 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(JSContext *ctx)` (requires caller to hold the JS mutex). +- `sbmd.js.mutex.wait_ms` is measured in `HandleResourceOp` (`SpecBasedMatterDeviceDriver`), `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(JSContext *ctx)` (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 SbmdOperationContext *opCtx = nullptr`. `SbmdOperationContext` is a plain struct defined in `SbmdHandlerInvoker.h`: +`InvokeHandler` is extended with a single optional parameter: `const OperationContext *opCtx = nullptr`. `OperationContext` is a plain struct defined in `SbmdHandlerInvoker.h`: ```cpp -struct SbmdOperationContext { +struct OperationContext { const char *driverName = nullptr; - const char *opType = nullptr; // originating op type (e.g., "write", "execute") + 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 }; @@ -55,7 +56,7 @@ struct SbmdOperationContext { All existing callers compile unchanged (null default). **Two distinct calling patterns:** -- **Synchronous ops** (`HandleResourceOp`): caller stack-allocates `SbmdOperationContext{driver, opType, steady_clock::now()}` and passes `&opCtx`. Lifetime is that single call. +- **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. @@ -69,7 +70,7 @@ All existing callers compile unchanged (null default). **Two distinct calling pa 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(ctx)` updates the pool health gauges using the same `JS_GetMemoryUsage` data already captured for the heap delta histogram. `InvokeHandler` then calls `MQuickJsRuntime::TickleSampler()` to notify the idle thread to reset its timer. +**In-activity path:** At the end of every `InvokeHandler` call, while the JS mutex is already held by the caller, `MQuickJsRuntime::RecordHeapSnapshot(ctx)` updates the pool health metrics (`sbmd.js.heap.used_bytes` histogram and `free_bytes`/`peak_bytes` gauges) using the same `JS_GetMemoryUsage` data already captured for the heap delta histogram. `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 woken early by `TickleSampler()`, it resets the timer and re-checks `samplerShouldStop` without taking a snapshot. @@ -96,9 +97,9 @@ InvokeHandler (JS mutex held by caller): Idle background thread: **Thread startup/shutdown:** The thread is started at the end of `MQuickJsRuntime::Initialize()`. In `Shutdown()`, `samplerShouldStop` is set to `true` and `TickleSampler()` is called to wake the thread immediately before joining. -### Decision 4: `PendingOperation` extended with `SbmdOperationContext` +### Decision 4: `PendingOperation` extended with `OperationContext` -A `SbmdOperationContext operationCtx` field is added to `PendingOperation`. It is initialized in `ExecuteRequestCommand` alongside `overallDeadline` with the driver name, originating op type, 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` as attributes on all deferred lifecycle metrics (`sbmd.deferred.duration_ms`, `sbmd.deferred.depth`, `sbmd.deferred.timeout`, `sbmd.deferred.max_depth`). +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. @@ -108,6 +109,7 @@ A `SbmdOperationContext operationCtx` field is added to `PendingOperation`. It i |---|---|---| | `"driver"` | driver name string (e.g., `"door-lock"`) | all per-driver metrics | | `"op_type"` | `"read"` / `"write"` / `"execute"` / `"attribute_report"` / `"event"` | invocation, outcome, deferred | +| `"resource_id"` | resource ID string (e.g., `"isOn"`); omitted for attribute/event handlers | `sbmd.handler.*`, `sbmd.deferred.*` | | `"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 | @@ -141,7 +143,7 @@ core/deviceDrivers/matter/sbmd/ │ InvokeHandler extended │ ├── SbmdFactory.cpp ← driver load metrics -└── SpecBasedMatterDeviceDriver.cpp ← deferred op metrics; PendingOperation.operationCtx (SbmdOperationContext) +└── SpecBasedMatterDeviceDriver.cpp ← deferred op metrics; PendingOperation.operationCtx (OperationContext) ``` ## Risks / Trade-offs @@ -158,3 +160,4 @@ core/deviceDrivers/matter/sbmd/ - **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 index e1c79f2e..9768f1f1 100644 --- a/openspec/changes/sbmd-observability-instrumentation/proposal.md +++ b/openspec/changes/sbmd-observability-instrumentation/proposal.md @@ -6,9 +6,9 @@ The SBMDv4 JavaScript runtime (mquickjs) runs inside a fixed 1 MB arena with a s - **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 SbmdOperationContext *opCtx = nullptr` parameter; the struct is extensible without further signature changes and carries natural operation-scope lifetime for deferred chains. +- **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 and originating op type), deferral depth, timeout events, and max-depth-exceeded events. Adds `SbmdOperationContext operationCtx` field to `PendingOperation` struct. +- **Deferred operation instrumentation** in `SpecBasedMatterDeviceDriver`: tracks in-flight count, total duration (attributed by driver and originating op type), 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. @@ -28,8 +28,8 @@ The SBMDv4 JavaScript runtime (mquickjs) runs inside a fixed 1 MB arena with a s - **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 `SbmdOperationContext operationCtx` field (carries driver name, originating op type, and start time) -- **API change**: `SbmdHandlerInvoker::InvokeHandler` gains a single optional `const SbmdOperationContext *opCtx = nullptr` parameter; new `SbmdOperationContext` struct defined in `SbmdHandlerInvoker.h` (backwards-compatible) +- **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 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 index b4c851f2..274156ca 100644 --- a/openspec/changes/sbmd-observability-instrumentation/specs/sbmd-runtime-observability/spec.md +++ b/openspec/changes/sbmd-observability-instrumentation/specs/sbmd-runtime-observability/spec.md @@ -27,14 +27,14 @@ The SBMD runtime SHALL maintain a gauge named `sbmd.js.heap.peak_bytes` recordin - **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, records one observation to each pool health metric, and calls `TickleSampler()` to reset the idle thread's timer. This function SHALL be callable without holding the JS mutex (it acquires it internally). 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. +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 the `sbmd.js.heap.free_bytes` and `sbmd.js.heap.peak_bytes` gauges with current values, and calls `TickleSampler()` to reset the idle thread's timer. This function SHALL be callable without holding the JS mutex (it acquires it internally). 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` around the `JS_Call` in `SbmdHandlerInvoker::InvokeHandler`. The histogram SHALL support `"driver"` and `"op_type"` attributes. +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` around the `JS_Call` in `SbmdHandlerInvoker::InvokeHandler`. 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` @@ -45,7 +45,7 @@ The SBMD runtime SHALL record the net heap allocation of each JS handler invocat - **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"` and `"op_type"` attributes. +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 @@ -56,7 +56,7 @@ The SBMD runtime SHALL record the wall-clock duration of each JS handler invocat - **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"`, 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. +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 @@ -90,7 +90,7 @@ The SBMD runtime SHALL record the time a request spends waiting to acquire the J - **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 gauge named `sbmd.driver.load.duration_ms` with attribute `"driver"`, and the net heap bytes consumed during load and activation as a gauge named `sbmd.driver.load.heap_bytes` with attribute `"driver"`. Both SHALL be recorded once per driver at startup in `SbmdFactory::RegisterDriversFromDirectory`. +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 @@ -137,14 +137,14 @@ The SBMD runtime SHALL maintain a gauge named `sbmd.deferred.in_flight` represen - **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"` and `"op_type"` (the originating operation type from `pending.operationCtx.opType`). Duration includes device round-trip time. +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"` and `"op_type"`. Depth 0 means the operation resolved after one round-trip; depth N means the operation re-armed N times. +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 @@ -155,14 +155,14 @@ The SBMD runtime SHALL record the deferral depth at completion of each deferred - **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"` and `"op_type"`. 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). +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"` and `"op_type"`. +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 diff --git a/openspec/changes/sbmd-observability-instrumentation/tasks.md b/openspec/changes/sbmd-observability-instrumentation/tasks.md index 663d596d..ce5298e9 100644 --- a/openspec/changes/sbmd-observability-instrumentation/tasks.md +++ b/openspec/changes/sbmd-observability-instrumentation/tasks.md @@ -14,14 +14,14 @@ ## 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()`, `ShutdownMetrics()`, and `RecordOutcomeError(const char *driver, const char *opType)` static functions -- [ ] 3.1 Define `SbmdOperationContext` struct in `SbmdHandlerInvoker.h` with fields `const char *driverName = nullptr`, `const char *opType = nullptr`, and `std::chrono::steady_clock::time_point startTime`; extend `SbmdHandlerInvoker::InvokeHandler` with `const SbmdOperationContext *opCtx = nullptr` (backwards-compatible) +- [ ] 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()`, `ShutdownMetrics()`, and `RecordOutcomeError(const char *driver, const char *opType, const char *resourceId)` static functions +- [ ] 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(ctx)` to update pool health gauges while the JS mutex is still held; then call `MQuickJsRuntime::TickleSampler()` to notify the idle thread +- [ ] 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(ctx)` 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() > GetDeadline()` (or use a flag set before `ClearDeadline()`) to emit `"timeout"` vs `"exception"` -- [ ] 3.5 Update `InvokeHandler` call sites in `SpecBasedMatterDeviceDriver`: synchronous paths (`HandleResourceOp`) stack-allocate `SbmdOperationContext{driver, opType, steady_clock::now()}` and pass `&opCtx`; deferred callback paths (`HandleDeferredCommandResponse`, `HandleDeferredCommandError`, `ContinueDeferredChain`) pass `&pending.operationCtx` (the persistent context initialized in task 5.2) +- [ ] 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` and the attribute/event handler paths: `auto t0 = steady_clock::now()` before `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)` to emit `sbmd.handler.outcome{outcome="error"}` +- [ ] 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 @@ -35,12 +35,12 @@ ## 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 `ShutdownMetrics()` static functions -- [ ] 5.1 Add `SbmdOperationContext 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"`), and `operationCtx.startTime = steady_clock::now()` +- [ ] 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` and `pending.operationCtx.opType` 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` and `pending.operationCtx.opType` 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` and `pending.operationCtx.opType` attributes before calling `CompletePendingOperation` +- [ ] 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 @@ -54,7 +54,7 @@ - [ ] 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 value > 0 +- [ ] 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 From 9d23055b38b09b67a791768c263617022b992cf5 Mon Sep 17 00:00:00 2001 From: rchowdcmcsa Date: Wed, 15 Jul 2026 18:53:43 +0000 Subject: [PATCH 07/24] gauge for gc root entries, mquickjs patch, wait for mquickjs upgrade --- openspec/changes/sbmd-observability-instrumentation/proposal.md | 1 + 1 file changed, 1 insertion(+) diff --git a/openspec/changes/sbmd-observability-instrumentation/proposal.md b/openspec/changes/sbmd-observability-instrumentation/proposal.md index 9768f1f1..63e838d5 100644 --- a/openspec/changes/sbmd-observability-instrumentation/proposal.md +++ b/openspec/changes/sbmd-observability-instrumentation/proposal.md @@ -38,6 +38,7 @@ The SBMDv4 JavaScript runtime (mquickjs) runs inside a fixed 1 MB arena with a s ## 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. From ad201e25493b8e354d3944a5d3a429cd12de1a67 Mon Sep 17 00:00:00 2001 From: rchowdcmcsa Date: Wed, 15 Jul 2026 18:57:41 +0000 Subject: [PATCH 08/24] make note of non-uniform sampling for heap delta histogram just accept it as-is for now --- openspec/changes/sbmd-observability-instrumentation/design.md | 2 ++ 1 file changed, 2 insertions(+) diff --git a/openspec/changes/sbmd-observability-instrumentation/design.md b/openspec/changes/sbmd-observability-instrumentation/design.md index 1df75ead..d168cc14 100644 --- a/openspec/changes/sbmd-observability-instrumentation/design.md +++ b/openspec/changes/sbmd-observability-instrumentation/design.md @@ -152,6 +152,8 @@ core/deviceDrivers/matter/sbmd/ - **`JS_GetMemoryUsage` overhead inside `InvokeHandler`** → Called twice per invocation (before + after `JS_Call`). `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 sampling-independent and remain reliable regardless of workload. 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 observations are recorded in the histogram's underflow bucket. 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. From 8246ed92f000b0e900d35bd1380f6bae687db733 Mon Sep 17 00:00:00 2001 From: rchowdcmcsa Date: Wed, 15 Jul 2026 19:29:35 +0000 Subject: [PATCH 09/24] copilot comments --- .../design.md | 29 ++++++++++--------- .../proposal.md | 2 +- .../tasks.md | 6 ++-- 3 files changed, 20 insertions(+), 17 deletions(-) diff --git a/openspec/changes/sbmd-observability-instrumentation/design.md b/openspec/changes/sbmd-observability-instrumentation/design.md index d168cc14..e175f2bf 100644 --- a/openspec/changes/sbmd-observability-instrumentation/design.md +++ b/openspec/changes/sbmd-observability-instrumentation/design.md @@ -12,7 +12,7 @@ This design covers how to wire the observability API into the SBMD runtime witho - 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"` and `"op_type"` attribute keys +- 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:** @@ -35,8 +35,8 @@ Metric handles (histograms, gauges, counters) are private static members of the | `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)`. -- `sbmd.js.mutex.wait_ms` is measured in `HandleResourceOp` (`SpecBasedMatterDeviceDriver`), `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(JSContext *ctx)` (requires caller to hold the JS mutex). +- `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(JSContext *ctx)` (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()`. @@ -72,7 +72,7 @@ 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(ctx)` updates the pool health metrics (`sbmd.js.heap.used_bytes` histogram and `free_bytes`/`peak_bytes` gauges) using the same `JS_GetMemoryUsage` data already captured for the heap delta histogram. `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 woken early by `TickleSampler()`, it resets the timer and re-checks `samplerShouldStop` without taking a snapshot. +**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_for` returns before the timeout, 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: continue waiting without resetting the timer or taking a snapshot. 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. @@ -83,16 +83,19 @@ Pool health metrics (`sbmd.js.heap.*`) are recorded from two complementary paths **`MQuickJsRuntime::ForceSnapshot()`** is a public synchronous function that acquires the JS mutex, calls `RecordHeapSnapshot`, releases the mutex, and calls `TickleSampler()`. 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. Calls `samplerCv.notify_one()` *without* acquiring `samplerCvMutex` — the standard C++ idiom; only the waiter needs the lock. Safe to call from any context including while holding the JS mutex. +**`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 cv.wait_for(SAMPLE_PERIOD_MS) - → record sbmd.handler.* if timed_out (true idle): - → RecordHeapSnapshot(ctx) ← pool health ForceSnapshot() - → TickleSampler() ← reset idle timer // woken early by TickleSampler: - // no snapshot, reset and wait + → JS_GetMemoryUsage if samplerShouldStop: exit + → record sbmd.handler.* seq = tickleSeq + → RecordHeapSnapshot(ctx) ← pool health cv.wait_for(SAMPLE_PERIOD_MS) + → TickleSampler() ← increments tickleSeq 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()`, `samplerShouldStop` is set to `true` and `TickleSampler()` is called to wake the thread immediately before joining. @@ -108,8 +111,8 @@ An `OperationContext operationCtx` field is added to `PendingOperation`. It is i | 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, deferred | -| `"resource_id"` | resource ID string (e.g., `"isOn"`); omitted for attribute/event handlers | `sbmd.handler.*`, `sbmd.deferred.*` | +| `"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 | @@ -154,7 +157,7 @@ core/deviceDrivers/matter/sbmd/ - **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 sampling-independent and remain reliable regardless of workload. 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 observations are recorded in the histogram's underflow bucket. This is expected behavior, not a bug. +- **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. diff --git a/openspec/changes/sbmd-observability-instrumentation/proposal.md b/openspec/changes/sbmd-observability-instrumentation/proposal.md index 63e838d5..bca58109 100644 --- a/openspec/changes/sbmd-observability-instrumentation/proposal.md +++ b/openspec/changes/sbmd-observability-instrumentation/proposal.md @@ -8,7 +8,7 @@ The SBMDv4 JavaScript runtime (mquickjs) runs inside a fixed 1 MB arena with a s - **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 and originating op type), deferral depth, timeout events, and max-depth-exceeded events. Adds `OperationContext operationCtx` field to `PendingOperation` struct. +- **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. diff --git a/openspec/changes/sbmd-observability-instrumentation/tasks.md b/openspec/changes/sbmd-observability-instrumentation/tasks.md index ce5298e9..223682e4 100644 --- a/openspec/changes/sbmd-observability-instrumentation/tasks.md +++ b/openspec/changes/sbmd-observability-instrumentation/tasks.md @@ -7,8 +7,8 @@ ## 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 `static void InitializeMetrics()`, `ShutdownMetrics()`, `ForceSnapshot()`, `RecordHeapSnapshot(JSContext *ctx)`, `TickleSampler()`, `RecordMutexWait(double ms)`, and `RecordJsException(const char *phase, const char *driver)` static functions -- [ ] 2.1 Add `static std::thread periodicSamplerThread`, `static std::atomic samplerShouldStop`, `static std::condition_variable samplerCv`, and `static std::mutex samplerCvMutex` to `MQuickJsRuntime` -- [ ] 2.2 Start idle sampler thread at end of `MQuickJsRuntime::Initialize()`: loop checks `samplerShouldStop` and exits if set; otherwise waits on `samplerCv` for up to `BARTON_CONFIG_SBMD_METRICS_SAMPLE_PERIOD_MS` ms; on natural timeout calls `ForceSnapshot()`; on early wakeup (tickled by activity or shutdown) resets the timer without taking a snapshot, then re-checks `samplerShouldStop` +- [ ] 2.1 Add `static std::thread periodicSamplerThread`, `static std::atomic samplerShouldStop`, `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()`: loop checks `samplerShouldStop` and exits if set; otherwise records the current `tickleSeq` value, then waits on `samplerCv` for up to `BARTON_CONFIG_SBMD_METRICS_SAMPLE_PERIOD_MS` ms; on natural timeout calls `ForceSnapshot()`; on early wakeup compares the current `tickleSeq` to the recorded value — if changed a real tickle occurred (reset timer, re-check `samplerShouldStop`), if unchanged the wakeup was spurious (continue waiting without resetting the timer or taking a snapshot) - [ ] 2.3 In `MQuickJsRuntime::Shutdown()`, set `samplerShouldStop = true`, call `TickleSampler()` to wake the thread immediately, then join `periodicSamplerThread` before `JS_FreeContext` - [ ] 2.4 Record `sbmd.js.heap.arena_bytes` gauge once at end of `MQuickJsRuntime::Initialize()` after context is created @@ -20,7 +20,7 @@ - [ ] 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(ctx)` 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() > GetDeadline()` (or use a flag set before `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` and the attribute/event handler paths: `auto t0 = steady_clock::now()` before `lock_guard`, call `MQuickJsRuntime::RecordMutexWait(elapsed(t0))` after lock acquired +- [ ] 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 `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 From ed564a37fe74588141165477a48053ca654b9939 Mon Sep 17 00:00:00 2001 From: rchowdcmcsa Date: Wed, 15 Jul 2026 20:03:40 +0000 Subject: [PATCH 10/24] copilot comment --- openspec/changes/sbmd-observability-instrumentation/design.md | 2 +- openspec/changes/sbmd-observability-instrumentation/proposal.md | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/openspec/changes/sbmd-observability-instrumentation/design.md b/openspec/changes/sbmd-observability-instrumentation/design.md index e175f2bf..f4b86209 100644 --- a/openspec/changes/sbmd-observability-instrumentation/design.md +++ b/openspec/changes/sbmd-observability-instrumentation/design.md @@ -1,6 +1,6 @@ ## Context -SBMDv4 runs all device driver JavaScript through a single shared mquickjs context — a pre-allocated, fixed-size arena (default 1 MB) protected by a single mutex. Every resource read/write/execute, attribute report, and event goes through `SbmdHandlerInvoker::InvokeHandler`, which acquires this mutex and calls `JS_Call`. Because all drivers compete for the same runtime, the JS context is the primary resource bottleneck of the SBMD subsystem. +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 acquires this mutex and calls `JS_Call`. 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. It is fully implemented but has zero call sites in production code today. diff --git a/openspec/changes/sbmd-observability-instrumentation/proposal.md b/openspec/changes/sbmd-observability-instrumentation/proposal.md index bca58109..2960eced 100644 --- a/openspec/changes/sbmd-observability-instrumentation/proposal.md +++ b/openspec/changes/sbmd-observability-instrumentation/proposal.md @@ -1,6 +1,6 @@ ## Why -The SBMDv4 JavaScript runtime (mquickjs) runs inside a fixed 1 MB arena 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. +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 From 8bbced413997534223e1d3dfc56096abb9ef96d0 Mon Sep 17 00:00:00 2001 From: rchowdcmcsa Date: Thu, 16 Jul 2026 18:05:19 +0000 Subject: [PATCH 11/24] more copilot comments --- .../changes/sbmd-observability-instrumentation/design.md | 2 +- .../changes/sbmd-observability-instrumentation/tasks.md | 8 ++++---- 2 files changed, 5 insertions(+), 5 deletions(-) diff --git a/openspec/changes/sbmd-observability-instrumentation/design.md b/openspec/changes/sbmd-observability-instrumentation/design.md index f4b86209..1fac5dc6 100644 --- a/openspec/changes/sbmd-observability-instrumentation/design.md +++ b/openspec/changes/sbmd-observability-instrumentation/design.md @@ -155,7 +155,7 @@ core/deviceDrivers/matter/sbmd/ - **`JS_GetMemoryUsage` overhead inside `InvokeHandler`** → Called twice per invocation (before + after `JS_Call`). `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 sampling-independent and remain reliable regardless of workload. Percentiles should be interpreted with the deployment's activity level in mind. +- **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. diff --git a/openspec/changes/sbmd-observability-instrumentation/tasks.md b/openspec/changes/sbmd-observability-instrumentation/tasks.md index 223682e4..706e1fc3 100644 --- a/openspec/changes/sbmd-observability-instrumentation/tasks.md +++ b/openspec/changes/sbmd-observability-instrumentation/tasks.md @@ -6,7 +6,7 @@ ## 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 `static void InitializeMetrics()`, `ShutdownMetrics()`, `ForceSnapshot()`, `RecordHeapSnapshot(JSContext *ctx)`, `TickleSampler()`, `RecordMutexWait(double ms)`, and `RecordJsException(const char *phase, const char *driver)` static functions +- [ ] 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 `static void InitializeMetrics()`, `static void ShutdownMetrics()`, `static void ForceSnapshot()`, `static void RecordHeapSnapshot(JSContext *ctx)`, `static void TickleSampler()`, `static void RecordMutexWait(double ms)`, and `static void RecordJsException(const char *phase, const char *driver)` - [ ] 2.1 Add `static std::thread periodicSamplerThread`, `static std::atomic samplerShouldStop`, `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()`: loop checks `samplerShouldStop` and exits if set; otherwise records the current `tickleSeq` value, then waits on `samplerCv` for up to `BARTON_CONFIG_SBMD_METRICS_SAMPLE_PERIOD_MS` ms; on natural timeout calls `ForceSnapshot()`; on early wakeup compares the current `tickleSeq` to the recorded value — if changed a real tickle occurred (reset timer, re-check `samplerShouldStop`), if unchanged the wakeup was spurious (continue waiting without resetting the timer or taking a snapshot) - [ ] 2.3 In `MQuickJsRuntime::Shutdown()`, set `samplerShouldStop = true`, call `TickleSampler()` to wake the thread immediately, then join `periodicSamplerThread` before `JS_FreeContext` @@ -14,7 +14,7 @@ ## 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()`, `ShutdownMetrics()`, and `RecordOutcomeError(const char *driver, const char *opType, const char *resourceId)` static functions +- [ ] 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)` - [ ] 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(ctx)` 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 @@ -25,7 +25,7 @@ ## 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 `ShutdownMetrics()` static functions +- [ ] 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 @@ -34,7 +34,7 @@ ## 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 `ShutdownMetrics()` static functions +- [ ] 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 From c8eddfca7c5a5ac0b4c40de4421881d2a497fc8d Mon Sep 17 00:00:00 2001 From: rchowdcmcsa Date: Thu, 16 Jul 2026 18:18:11 +0000 Subject: [PATCH 12/24] copilot comment --- .../sbmd-observability-instrumentation/design.md | 11 ++++++----- .../sbmd-observability-instrumentation/tasks.md | 2 +- 2 files changed, 7 insertions(+), 6 deletions(-) diff --git a/openspec/changes/sbmd-observability-instrumentation/design.md b/openspec/changes/sbmd-observability-instrumentation/design.md index 1fac5dc6..848e1670 100644 --- a/openspec/changes/sbmd-observability-instrumentation/design.md +++ b/openspec/changes/sbmd-observability-instrumentation/design.md @@ -25,7 +25,7 @@ This design covers how to wire the observability API into the SBMD runtime witho ### 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 `ShutdownMetrics()` functions. `SbmdFactory::RegisterDriversFromDirectory` calls all four `InitializeMetrics()` functions after `MQuickJsRuntime::Initialize()` succeeds. +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 all four `InitializeMetrics()` functions after `MQuickJsRuntime::Initialize()` succeeds. | Module | Metric handles owned | |---|---| @@ -72,7 +72,7 @@ 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(ctx)` updates the pool health metrics (`sbmd.js.heap.used_bytes` histogram and `free_bytes`/`peak_bytes` gauges) using the same `JS_GetMemoryUsage` data already captured for the heap delta histogram. `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_for` returns before the timeout, 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: continue waiting without resetting the timer or taking a snapshot. This ensures spurious wakeups cannot indefinitely delay an idle-period snapshot. +**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. @@ -89,9 +89,10 @@ Pool health metrics (`sbmd.js.heap.*`) are recorded from two complementary paths InvokeHandler (JS mutex held by caller): Idle background thread: → JS_Call loop: → JS_GetMemoryUsage if samplerShouldStop: exit - → record sbmd.handler.* seq = tickleSeq - → RecordHeapSnapshot(ctx) ← pool health cv.wait_for(SAMPLE_PERIOD_MS) - → TickleSampler() ← increments tickleSeq if timed_out: ForceSnapshot() + → record sbmd.handler.* deadline = now() + SAMPLE_PERIOD_MS + → RecordHeapSnapshot(ctx) ← pool health seq = tickleSeq + → TickleSampler() ← increments tickleSeq cv.wait_until(deadline) + if timed_out: ForceSnapshot() // real tickle (tickleSeq != seq): // no snapshot, reset timer // spurious (tickleSeq == seq): diff --git a/openspec/changes/sbmd-observability-instrumentation/tasks.md b/openspec/changes/sbmd-observability-instrumentation/tasks.md index 706e1fc3..c7cc333d 100644 --- a/openspec/changes/sbmd-observability-instrumentation/tasks.md +++ b/openspec/changes/sbmd-observability-instrumentation/tasks.md @@ -8,7 +8,7 @@ - [ ] 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 `static void InitializeMetrics()`, `static void ShutdownMetrics()`, `static void ForceSnapshot()`, `static void RecordHeapSnapshot(JSContext *ctx)`, `static void TickleSampler()`, `static void RecordMutexWait(double ms)`, and `static void RecordJsException(const char *phase, const char *driver)` - [ ] 2.1 Add `static std::thread periodicSamplerThread`, `static std::atomic samplerShouldStop`, `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()`: loop checks `samplerShouldStop` and exits if set; otherwise records the current `tickleSeq` value, then waits on `samplerCv` for up to `BARTON_CONFIG_SBMD_METRICS_SAMPLE_PERIOD_MS` ms; on natural timeout calls `ForceSnapshot()`; on early wakeup compares the current `tickleSeq` to the recorded value — if changed a real tickle occurred (reset timer, re-check `samplerShouldStop`), if unchanged the wakeup was spurious (continue waiting without resetting the timer or taking a snapshot) +- [ ] 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() + 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 `samplerShouldStop = true`, call `TickleSampler()` to wake the thread immediately, then join `periodicSamplerThread` before `JS_FreeContext` - [ ] 2.4 Record `sbmd.js.heap.arena_bytes` gauge once at end of `MQuickJsRuntime::Initialize()` after context is created From 6325baf621fda835c0d2921b706af0109e68787f Mon Sep 17 00:00:00 2001 From: rchowdcmcsa Date: Thu, 16 Jul 2026 18:31:47 +0000 Subject: [PATCH 13/24] more copilet comments addressed --- openspec/changes/sbmd-observability-instrumentation/design.md | 2 +- openspec/changes/sbmd-observability-instrumentation/tasks.md | 4 ++-- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/openspec/changes/sbmd-observability-instrumentation/design.md b/openspec/changes/sbmd-observability-instrumentation/design.md index 848e1670..ba2a7f72 100644 --- a/openspec/changes/sbmd-observability-instrumentation/design.md +++ b/openspec/changes/sbmd-observability-instrumentation/design.md @@ -1,6 +1,6 @@ ## 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 acquires this mutex and calls `JS_Call`. Because all drivers compete for the same runtime, the JS context is the primary resource bottleneck of the SBMD subsystem. +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. It is fully implemented but has zero call sites in production code today. diff --git a/openspec/changes/sbmd-observability-instrumentation/tasks.md b/openspec/changes/sbmd-observability-instrumentation/tasks.md index c7cc333d..cc1ccec2 100644 --- a/openspec/changes/sbmd-observability-instrumentation/tasks.md +++ b/openspec/changes/sbmd-observability-instrumentation/tasks.md @@ -6,7 +6,7 @@ ## 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 `static void InitializeMetrics()`, `static void ShutdownMetrics()`, `static void ForceSnapshot()`, `static void RecordHeapSnapshot(JSContext *ctx)`, `static void TickleSampler()`, `static void RecordMutexWait(double ms)`, and `static void RecordJsException(const char *phase, const char *driver)` +- [ ] 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 `static void InitializeMetrics()`, `static void ShutdownMetrics()`, `static void ForceSnapshot()`, `static void RecordHeapSnapshot(JSContext *ctx)`, `static void TickleSampler()`, `static void RecordMutexWait(double ms)`, and `static void RecordJsException(const char *phase, const char *driver)`; all recording functions (`ForceSnapshot`, `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 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() + 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 `samplerShouldStop = true`, call `TickleSampler()` to wake the thread immediately, then join `periodicSamplerThread` before `JS_FreeContext` @@ -14,7 +14,7 @@ ## 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)` +- [ ] 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(ctx)` 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 From 77e6d0588548566c7488fd4cc97b69210e96262b Mon Sep 17 00:00:00 2001 From: rchowdcmcsa Date: Thu, 16 Jul 2026 18:47:15 +0000 Subject: [PATCH 14/24] copilot comments addressed --- .../changes/sbmd-observability-instrumentation/design.md | 2 +- .../specs/sbmd-runtime-observability/spec.md | 4 ++-- .../changes/sbmd-observability-instrumentation/tasks.md | 6 +++--- 3 files changed, 6 insertions(+), 6 deletions(-) diff --git a/openspec/changes/sbmd-observability-instrumentation/design.md b/openspec/changes/sbmd-observability-instrumentation/design.md index ba2a7f72..4301d3e6 100644 --- a/openspec/changes/sbmd-observability-instrumentation/design.md +++ b/openspec/changes/sbmd-observability-instrumentation/design.md @@ -99,7 +99,7 @@ InvokeHandler (JS mutex held by caller): Idle background thread: // no snapshot, keep waiting ``` -**Thread startup/shutdown:** The thread is started at the end of `MQuickJsRuntime::Initialize()`. In `Shutdown()`, `samplerShouldStop` is set to `true` and `TickleSampler()` is called to wake the thread immediately before joining. +**Thread startup/shutdown:** The thread is started at the end of `MQuickJsRuntime::Initialize()`. In `Shutdown()`, `samplerShouldStop` is set to `true` and `TickleSampler()` is called to wake the thread immediately, then `periodicSamplerThread` is joined — guarded with `joinable()` to avoid `std::terminate` if `Initialize()` failed before the thread was started. ### Decision 4: `PendingOperation` extended with `OperationContext` 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 index 274156ca..ce197fea 100644 --- a/openspec/changes/sbmd-observability-instrumentation/specs/sbmd-runtime-observability/spec.md +++ b/openspec/changes/sbmd-observability-instrumentation/specs/sbmd-runtime-observability/spec.md @@ -5,7 +5,7 @@ The SBMD runtime SHALL record mquickjs heap pool utilization as a histogram name #### 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 attributed to that invocation +- **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 @@ -79,7 +79,7 @@ The SBMD runtime SHALL count handler invocation outcomes using a counter named ` - **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 `lock_guard(MQuickJsRuntime::GetMutex())` begins until the mutex is acquired, in all code paths that acquire the mutex for handler invocation. +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 diff --git a/openspec/changes/sbmd-observability-instrumentation/tasks.md b/openspec/changes/sbmd-observability-instrumentation/tasks.md index cc1ccec2..d46fc375 100644 --- a/openspec/changes/sbmd-observability-instrumentation/tasks.md +++ b/openspec/changes/sbmd-observability-instrumentation/tasks.md @@ -9,7 +9,7 @@ - [ ] 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 `static void InitializeMetrics()`, `static void ShutdownMetrics()`, `static void ForceSnapshot()`, `static void RecordHeapSnapshot(JSContext *ctx)`, `static void TickleSampler()`, `static void RecordMutexWait(double ms)`, and `static void RecordJsException(const char *phase, const char *driver)`; all recording functions (`ForceSnapshot`, `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 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() + 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 `samplerShouldStop = true`, call `TickleSampler()` to wake the thread immediately, then join `periodicSamplerThread` before `JS_FreeContext` +- [ ] 2.3 In `MQuickJsRuntime::Shutdown()`, 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 Record `sbmd.js.heap.arena_bytes` gauge once at end of `MQuickJsRuntime::Initialize()` after context is created ## 3. SbmdHandlerInvoker — per-invocation instrumentation @@ -18,9 +18,9 @@ - [ ] 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(ctx)` 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() > GetDeadline()` (or use a flag set before `ClearDeadline()`) to emit `"timeout"` vs `"exception"` +- [ ] 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 `lock_guard`, call `MQuickJsRuntime::RecordMutexWait(elapsed(t0))` after lock acquired +- [ ] 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 From db4948a2c52f9515c0e308930318ef18eb475b51 Mon Sep 17 00:00:00 2001 From: rchowdcmcsa Date: Thu, 16 Jul 2026 18:58:10 +0000 Subject: [PATCH 15/24] more copilot comments addressed --- openspec/changes/sbmd-observability-instrumentation/design.md | 4 ++-- .../specs/sbmd-runtime-observability/spec.md | 2 +- openspec/changes/sbmd-observability-instrumentation/tasks.md | 4 ++-- 3 files changed, 5 insertions(+), 5 deletions(-) diff --git a/openspec/changes/sbmd-observability-instrumentation/design.md b/openspec/changes/sbmd-observability-instrumentation/design.md index 4301d3e6..8e8c5e2d 100644 --- a/openspec/changes/sbmd-observability-instrumentation/design.md +++ b/openspec/changes/sbmd-observability-instrumentation/design.md @@ -25,7 +25,7 @@ This design covers how to wire the observability API into the SBMD runtime witho ### 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 all four `InitializeMetrics()` functions after `MQuickJsRuntime::Initialize()` succeeds. +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 | |---|---| @@ -124,7 +124,7 @@ An `OperationContext operationCtx` field is added to `PendingOperation`. It is i ### 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 all four `InitializeMetrics()` functions in `SetUpTestSuite`. Tests invoke handlers via `SbmdHandlerInvoker::InvokeHandler`, then call `observabilityDumpJson()` and parse the JSON to assert: +**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 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 index ce197fea..a173037f 100644 --- a/openspec/changes/sbmd-observability-instrumentation/specs/sbmd-runtime-observability/spec.md +++ b/openspec/changes/sbmd-observability-instrumentation/specs/sbmd-runtime-observability/spec.md @@ -169,7 +169,7 @@ The SBMD runtime SHALL count deferred operations terminated because they reached - **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. All four `InitializeMetrics()` calls SHALL be made by `SbmdFactory::RegisterDriversFromDirectory` after `MQuickJsRuntime::Initialize()` succeeds. The corresponding `ShutdownMetrics()` calls SHALL be made in the subsystem shutdown path. +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 diff --git a/openspec/changes/sbmd-observability-instrumentation/tasks.md b/openspec/changes/sbmd-observability-instrumentation/tasks.md index d46fc375..e18dcff3 100644 --- a/openspec/changes/sbmd-observability-instrumentation/tasks.md +++ b/openspec/changes/sbmd-observability-instrumentation/tasks.md @@ -1,7 +1,7 @@ ## 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`, after `MQuickJsRuntime::Initialize()` succeeds, call `MQuickJsRuntime::InitializeMetrics()`, `SbmdHandlerInvoker::InitializeMetrics()`, `SbmdFactory::InitializeMetrics()`, and `SpecBasedMatterDeviceDriver::InitializeMetrics()` (these functions are added in tasks 2.0, 3.0, 4.0, and 5.0 respectively) +- [ ] 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 2.0, 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 @@ -50,7 +50,7 @@ ## 7. Unit tests — SbmdObservabilityTest.cpp -- [ ] 7.1 Create `core/test/src/SbmdObservabilityTest.cpp` with `SetUpTestSuite` calling `MQuickJsRuntime::Initialize(512*1024)`, then all four `InitializeMetrics()` calls per task 1.2, then `SbmdBundleLoader::LoadBundle` and `SbmdLoader::InjectCaptureFunction` +- [ ] 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 From 3c032bb78662d4d1030e4c9d174541682c27fab6 Mon Sep 17 00:00:00 2001 From: rchowdcmcsa Date: Thu, 16 Jul 2026 19:07:45 +0000 Subject: [PATCH 16/24] more copilot comments addressed --- openspec/changes/sbmd-observability-instrumentation/design.md | 2 +- openspec/changes/sbmd-observability-instrumentation/tasks.md | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/openspec/changes/sbmd-observability-instrumentation/design.md b/openspec/changes/sbmd-observability-instrumentation/design.md index 8e8c5e2d..e9e8b364 100644 --- a/openspec/changes/sbmd-observability-instrumentation/design.md +++ b/openspec/changes/sbmd-observability-instrumentation/design.md @@ -89,7 +89,7 @@ Pool health metrics (`sbmd.js.heap.*`) are recorded from two complementary paths InvokeHandler (JS mutex held by caller): Idle background thread: → JS_Call loop: → JS_GetMemoryUsage if samplerShouldStop: exit - → record sbmd.handler.* deadline = now() + SAMPLE_PERIOD_MS + → record sbmd.handler.* deadline = now() + std::chrono::milliseconds(BARTON_CONFIG_SBMD_METRICS_SAMPLE_PERIOD_MS) → RecordHeapSnapshot(ctx) ← pool health seq = tickleSeq → TickleSampler() ← increments tickleSeq cv.wait_until(deadline) if timed_out: ForceSnapshot() diff --git a/openspec/changes/sbmd-observability-instrumentation/tasks.md b/openspec/changes/sbmd-observability-instrumentation/tasks.md index e18dcff3..fc3c74e9 100644 --- a/openspec/changes/sbmd-observability-instrumentation/tasks.md +++ b/openspec/changes/sbmd-observability-instrumentation/tasks.md @@ -8,7 +8,7 @@ - [ ] 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 `static void InitializeMetrics()`, `static void ShutdownMetrics()`, `static void ForceSnapshot()`, `static void RecordHeapSnapshot(JSContext *ctx)`, `static void TickleSampler()`, `static void RecordMutexWait(double ms)`, and `static void RecordJsException(const char *phase, const char *driver)`; all recording functions (`ForceSnapshot`, `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 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() + 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.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 `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 Record `sbmd.js.heap.arena_bytes` gauge once at end of `MQuickJsRuntime::Initialize()` after context is created From a7aaec5a3e0610c4f805352672ce16ade1dcac66 Mon Sep 17 00:00:00 2001 From: rchowdcmcsa Date: Thu, 16 Jul 2026 19:12:42 +0000 Subject: [PATCH 17/24] addressing copilot comment --- openspec/changes/sbmd-observability-instrumentation/design.md | 2 ++ .../specs/sbmd-runtime-observability/spec.md | 2 +- 2 files changed, 3 insertions(+), 1 deletion(-) diff --git a/openspec/changes/sbmd-observability-instrumentation/design.md b/openspec/changes/sbmd-observability-instrumentation/design.md index e9e8b364..bbe5b272 100644 --- a/openspec/changes/sbmd-observability-instrumentation/design.md +++ b/openspec/changes/sbmd-observability-instrumentation/design.md @@ -118,6 +118,8 @@ An `OperationContext operationCtx` field is added to `PendingOperation`. It is i | `"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. 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 index a173037f..298ad5b4 100644 --- a/openspec/changes/sbmd-observability-instrumentation/specs/sbmd-runtime-observability/spec.md +++ b/openspec/changes/sbmd-observability-instrumentation/specs/sbmd-runtime-observability/spec.md @@ -119,7 +119,7 @@ The SBMD runtime SHALL count driver load failures using a counter named `sbmd.dr - **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"` (if known) and `"phase"`. 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. +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 From 8013a232080d9d43ab84e696bd74986662ef2117 Mon Sep 17 00:00:00 2001 From: rchowdcmcsa Date: Thu, 16 Jul 2026 19:22:18 +0000 Subject: [PATCH 18/24] copilot comments --- .../sbmd-observability-instrumentation/design.md | 10 +++++----- .../sbmd-observability-instrumentation/tasks.md | 4 ++-- 2 files changed, 7 insertions(+), 7 deletions(-) diff --git a/openspec/changes/sbmd-observability-instrumentation/design.md b/openspec/changes/sbmd-observability-instrumentation/design.md index bbe5b272..60d44535 100644 --- a/openspec/changes/sbmd-observability-instrumentation/design.md +++ b/openspec/changes/sbmd-observability-instrumentation/design.md @@ -36,7 +36,7 @@ Metric handles (histograms, gauges, counters) are private static members of the **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(JSContext *ctx)` (requires caller to hold the JS mutex). +- `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()`. @@ -70,7 +70,7 @@ All existing callers compile unchanged (null default). **Two distinct calling pa 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(ctx)` updates the pool health metrics (`sbmd.js.heap.used_bytes` histogram and `free_bytes`/`peak_bytes` gauges) using the same `JS_GetMemoryUsage` data already captured for the heap delta histogram. `InvokeHandler` then calls `MQuickJsRuntime::TickleSampler()` to notify the idle thread to reset its timer. +**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. @@ -79,7 +79,7 @@ Pool health metrics (`sbmd.js.heap.*`) are recorded from two complementary paths - 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(JSContext *ctx)`** records the current `JS_GetMemoryUsage` output to the pool health instruments. Requires the caller to hold the JS mutex. Called from `InvokeHandler`. +**`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`, releases the mutex, and calls `TickleSampler()`. Used in unit tests and available for on-demand telemetry. Any snapshot from any path resets the idle timer. @@ -90,7 +90,7 @@ 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(ctx) ← pool health seq = tickleSeq + → RecordHeapSnapshot(usage_after) ← pool health seq = tickleSeq → TickleSampler() ← increments tickleSeq cv.wait_until(deadline) if timed_out: ForceSnapshot() // real tickle (tickleSeq != seq): @@ -142,7 +142,7 @@ An `OperationContext operationCtx` field is added to `PendingOperation`. It is i core/deviceDrivers/matter/sbmd/ │ ├── mquickjs/ -│ ├── MQuickJsRuntime.cpp ← heap metrics, ForceSnapshot(), RecordHeapSnapshot(), +│ ├── MQuickJsRuntime.cpp ← heap metrics, ForceSnapshot(), RecordHeapSnapshot(JSMemoryUsage&), │ │ RecordMutexWait(), RecordJsException(), TickleSampler(); │ │ in-activity + idle sampling │ └── SbmdHandlerInvoker.cpp ← invocation/outcome metrics, RecordOutcomeError(); diff --git a/openspec/changes/sbmd-observability-instrumentation/tasks.md b/openspec/changes/sbmd-observability-instrumentation/tasks.md index fc3c74e9..10b1d566 100644 --- a/openspec/changes/sbmd-observability-instrumentation/tasks.md +++ b/openspec/changes/sbmd-observability-instrumentation/tasks.md @@ -6,7 +6,7 @@ ## 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 `static void InitializeMetrics()`, `static void ShutdownMetrics()`, `static void ForceSnapshot()`, `static void RecordHeapSnapshot(JSContext *ctx)`, `static void TickleSampler()`, `static void RecordMutexWait(double ms)`, and `static void RecordJsException(const char *phase, const char *driver)`; all recording functions (`ForceSnapshot`, `RecordHeapSnapshot`, `RecordMutexWait`, `RecordJsException`) must null-check their handles and return silently if called before `InitializeMetrics()` +- [ ] 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()`, and `static void TickleSampler()`; add private static recording functions `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); all recording functions (`ForceSnapshot`, `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 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 `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 @@ -17,7 +17,7 @@ - [ ] 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(ctx)` 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.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 From 380c5625230278bfd1057afa06431f0d737987af Mon Sep 17 00:00:00 2001 From: rchowdcmcsa Date: Thu, 16 Jul 2026 19:35:25 +0000 Subject: [PATCH 19/24] copilot comments --- .../changes/sbmd-observability-instrumentation/design.md | 8 ++++---- .../specs/sbmd-runtime-observability/spec.md | 2 +- .../changes/sbmd-observability-instrumentation/tasks.md | 4 ++-- 3 files changed, 7 insertions(+), 7 deletions(-) diff --git a/openspec/changes/sbmd-observability-instrumentation/design.md b/openspec/changes/sbmd-observability-instrumentation/design.md index 60d44535..16b16787 100644 --- a/openspec/changes/sbmd-observability-instrumentation/design.md +++ b/openspec/changes/sbmd-observability-instrumentation/design.md @@ -61,9 +61,9 @@ All existing callers compile unchanged (null default). **Two distinct calling pa **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 around `JS_Call`:** -- `steady_clock::now()` before and after → invocation duration histogram -- `JS_GetMemoryUsage` before and after → heap delta histogram +**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 @@ -156,7 +156,7 @@ core/deviceDrivers/matter/sbmd/ - **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 + after `JS_Call`). `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. +- **`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. 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 index 298ad5b4..f29cddde 100644 --- a/openspec/changes/sbmd-observability-instrumentation/specs/sbmd-runtime-observability/spec.md +++ b/openspec/changes/sbmd-observability-instrumentation/specs/sbmd-runtime-observability/spec.md @@ -34,7 +34,7 @@ The system SHALL provide a `MQuickJsRuntime::ForceSnapshot()` public static func - **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` around the `JS_Call` in `SbmdHandlerInvoker::InvokeHandler`. The histogram SHALL support `"driver"`, `"op_type"`, and `"resource_id"` attributes; `"resource_id"` is omitted for attribute/event handler invocations. +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` diff --git a/openspec/changes/sbmd-observability-instrumentation/tasks.md b/openspec/changes/sbmd-observability-instrumentation/tasks.md index 10b1d566..6964b78b 100644 --- a/openspec/changes/sbmd-observability-instrumentation/tasks.md +++ b/openspec/changes/sbmd-observability-instrumentation/tasks.md @@ -6,7 +6,7 @@ ## 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()`, and `static void TickleSampler()`; add private static recording functions `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); all recording functions (`ForceSnapshot`, `RecordHeapSnapshot`, `RecordMutexWait`, `RecordJsException`) must null-check their handles and return silently if called before `InitializeMetrics()` +- [ ] 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); all recording functions (`ForceSnapshot`, `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 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 `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 @@ -61,7 +61,7 @@ - [ ] 7.9 Test: driver load cost metrics populated — assert `sbmd.driver.load.duration_ms` and `sbmd.driver.load.heap_bytes` have observations after `SbmdLoader::LoadDriver` - [ ] 7.10 Test: driver load failure counter increments when `LoadDriver` is called with invalid JS - [ ] 7.11 Add `SbmdObservabilityTest.cpp` to `core/CMakeLists.txt` test target -- [ ] 7.12 Test: mutex wait histogram populated — hold the JS mutex from a second thread while calling `InvokeHandler` from the main thread to create contention; assert `sbmd.js.mutex.wait_ms` records at least one non-zero observation +- [ ] 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 — load N test drivers; assert `sbmd.driver.registered.count` gauge equals N From 948485754cb211a1b875c4cb2c718233a80fbee7 Mon Sep 17 00:00:00 2001 From: rchowdcmcsa Date: Thu, 16 Jul 2026 19:42:05 +0000 Subject: [PATCH 20/24] copilot comment --- openspec/changes/sbmd-observability-instrumentation/design.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/openspec/changes/sbmd-observability-instrumentation/design.md b/openspec/changes/sbmd-observability-instrumentation/design.md index 16b16787..7c104bef 100644 --- a/openspec/changes/sbmd-observability-instrumentation/design.md +++ b/openspec/changes/sbmd-observability-instrumentation/design.md @@ -2,7 +2,7 @@ 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. It is fully implemented but has zero call sites in production code today. +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. From 6df797536110b90f9106622f7b4ad4cb982e7af0 Mon Sep 17 00:00:00 2001 From: rchowdcmcsa Date: Thu, 16 Jul 2026 19:55:50 +0000 Subject: [PATCH 21/24] copilot comment --- openspec/changes/sbmd-observability-instrumentation/design.md | 2 +- .../specs/sbmd-runtime-observability/spec.md | 2 +- openspec/changes/sbmd-observability-instrumentation/tasks.md | 2 +- 3 files changed, 3 insertions(+), 3 deletions(-) diff --git a/openspec/changes/sbmd-observability-instrumentation/design.md b/openspec/changes/sbmd-observability-instrumentation/design.md index 7c104bef..ba5e818a 100644 --- a/openspec/changes/sbmd-observability-instrumentation/design.md +++ b/openspec/changes/sbmd-observability-instrumentation/design.md @@ -81,7 +81,7 @@ Pool health metrics (`sbmd.js.heap.*`) are recorded from two complementary paths **`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`, releases the mutex, and calls `TickleSampler()`. Used in unit tests and available for on-demand telemetry. Any snapshot from any path resets the idle timer. +**`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 called before `MQuickJsRuntime::Initialize()` has succeeded (the metric handle null-check alone is insufficient because the JS context may not exist yet). 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. 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 index f29cddde..6238216a 100644 --- a/openspec/changes/sbmd-observability-instrumentation/specs/sbmd-runtime-observability/spec.md +++ b/openspec/changes/sbmd-observability-instrumentation/specs/sbmd-runtime-observability/spec.md @@ -27,7 +27,7 @@ The SBMD runtime SHALL maintain a gauge named `sbmd.js.heap.peak_bytes` recordin - **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 the `sbmd.js.heap.free_bytes` and `sbmd.js.heap.peak_bytes` gauges with current values, and calls `TickleSampler()` to reset the idle thread's timer. This function SHALL be callable without holding the JS mutex (it acquires it internally). 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. +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 (i.e., before the JS context exists); the metric handle null-check alone is insufficient because the JS context itself may not exist yet. 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 diff --git a/openspec/changes/sbmd-observability-instrumentation/tasks.md b/openspec/changes/sbmd-observability-instrumentation/tasks.md index 6964b78b..28e74e08 100644 --- a/openspec/changes/sbmd-observability-instrumentation/tasks.md +++ b/openspec/changes/sbmd-observability-instrumentation/tasks.md @@ -6,7 +6,7 @@ ## 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); all recording functions (`ForceSnapshot`, `RecordHeapSnapshot`, `RecordMutexWait`, `RecordJsException`) must null-check their handles and return silently if called before `InitializeMetrics()` +- [ ] 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 `GetSharedContext() == nullptr` (in addition to the metric handle null-check) and silently no-op without acquiring the JS mutex if the context does not exist, since `InitializeMetrics()` is called before `Initialize()` and the context may not yet be valid; 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 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 `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 From c03742b726e9d022eef991bf9aae381db62c499f Mon Sep 17 00:00:00 2001 From: rchowdcmcsa Date: Thu, 16 Jul 2026 20:11:05 +0000 Subject: [PATCH 22/24] copilot comments --- .../changes/sbmd-observability-instrumentation/design.md | 4 ++-- .../specs/sbmd-runtime-observability/spec.md | 2 +- .../changes/sbmd-observability-instrumentation/tasks.md | 8 ++++---- 3 files changed, 7 insertions(+), 7 deletions(-) diff --git a/openspec/changes/sbmd-observability-instrumentation/design.md b/openspec/changes/sbmd-observability-instrumentation/design.md index ba5e818a..1642df5b 100644 --- a/openspec/changes/sbmd-observability-instrumentation/design.md +++ b/openspec/changes/sbmd-observability-instrumentation/design.md @@ -81,7 +81,7 @@ Pool health metrics (`sbmd.js.heap.*`) are recorded from two complementary paths **`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 called before `MQuickJsRuntime::Initialize()` has succeeded (the metric handle null-check alone is insufficient because the JS context may not exist yet). Used in unit tests and available for on-demand telemetry. Any snapshot from any path resets the idle timer. +**`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`. Using `GetSharedContext() == nullptr` for this check is unsafe because `GetSharedContext()` requires the JS mutex to already be held; 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 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. @@ -99,7 +99,7 @@ InvokeHandler (JS mutex held by caller): Idle background thread: // no snapshot, keep waiting ``` -**Thread startup/shutdown:** The thread is started at the end of `MQuickJsRuntime::Initialize()`. In `Shutdown()`, `samplerShouldStop` is set to `true` and `TickleSampler()` is called to wake the thread immediately, then `periodicSamplerThread` is joined — guarded with `joinable()` to avoid `std::terminate` if `Initialize()` failed before the thread was started. +**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` 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 index 6238216a..5b93929a 100644 --- a/openspec/changes/sbmd-observability-instrumentation/specs/sbmd-runtime-observability/spec.md +++ b/openspec/changes/sbmd-observability-instrumentation/specs/sbmd-runtime-observability/spec.md @@ -27,7 +27,7 @@ The SBMD runtime SHALL maintain a gauge named `sbmd.js.heap.peak_bytes` recordin - **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 (i.e., before the JS context exists); the metric handle null-check alone is insufficient because the JS context itself may not exist yet. 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. +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 diff --git a/openspec/changes/sbmd-observability-instrumentation/tasks.md b/openspec/changes/sbmd-observability-instrumentation/tasks.md index 28e74e08..3cb4eb26 100644 --- a/openspec/changes/sbmd-observability-instrumentation/tasks.md +++ b/openspec/changes/sbmd-observability-instrumentation/tasks.md @@ -6,11 +6,11 @@ ## 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 `GetSharedContext() == nullptr` (in addition to the metric handle null-check) and silently no-op without acquiring the JS mutex if the context does not exist, since `InitializeMetrics()` is called before `Initialize()` and the context may not yet be valid; 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 tickleSeq`, `static std::condition_variable samplerCv`, and `static std::mutex samplerCvMutex` to `MQuickJsRuntime` +- [ ] 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 because it requires the JS mutex to already be held, which would make the check unsafe or lock-free; `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 `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 Record `sbmd.js.heap.arena_bytes` gauge once at end of `MQuickJsRuntime::Initialize()` after context is created +- [ ] 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 From d4aaf94a42bfd67b65d4926bf1018018f6d9ac37 Mon Sep 17 00:00:00 2001 From: rchowdcmcsa Date: Thu, 16 Jul 2026 20:22:41 +0000 Subject: [PATCH 23/24] copilot comments --- .../changes/sbmd-observability-instrumentation/design.md | 2 +- .../changes/sbmd-observability-instrumentation/tasks.md | 8 ++++---- 2 files changed, 5 insertions(+), 5 deletions(-) diff --git a/openspec/changes/sbmd-observability-instrumentation/design.md b/openspec/changes/sbmd-observability-instrumentation/design.md index 1642df5b..bad3c275 100644 --- a/openspec/changes/sbmd-observability-instrumentation/design.md +++ b/openspec/changes/sbmd-observability-instrumentation/design.md @@ -81,7 +81,7 @@ Pool health metrics (`sbmd.js.heap.*`) are recorded from two complementary paths **`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`. Using `GetSharedContext() == nullptr` for this check is unsafe because `GetSharedContext()` requires the JS mutex to already be held; 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 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::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. diff --git a/openspec/changes/sbmd-observability-instrumentation/tasks.md b/openspec/changes/sbmd-observability-instrumentation/tasks.md index 3cb4eb26..b9d7d3f6 100644 --- a/openspec/changes/sbmd-observability-instrumentation/tasks.md +++ b/openspec/changes/sbmd-observability-instrumentation/tasks.md @@ -6,7 +6,7 @@ ## 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 because it requires the JS mutex to already be held, which would make the check unsafe or lock-free; `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.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 @@ -58,12 +58,12 @@ - [ ] 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 — assert `sbmd.driver.load.duration_ms` and `sbmd.driver.load.heap_bytes` have observations after `SbmdLoader::LoadDriver` -- [ ] 7.10 Test: driver load failure counter increments when `LoadDriver` is called with invalid JS +- [ ] 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 — load N test drivers; assert `sbmd.driver.registered.count` gauge equals N +- [ ] 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 From 77ec5cda7870d92aa6fa1a6665e8da77d9022c93 Mon Sep 17 00:00:00 2001 From: rchowdcmcsa Date: Thu, 16 Jul 2026 20:28:19 +0000 Subject: [PATCH 24/24] copilot comment --- openspec/changes/sbmd-observability-instrumentation/design.md | 4 ++-- openspec/changes/sbmd-observability-instrumentation/tasks.md | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/openspec/changes/sbmd-observability-instrumentation/design.md b/openspec/changes/sbmd-observability-instrumentation/design.md index bad3c275..88813676 100644 --- a/openspec/changes/sbmd-observability-instrumentation/design.md +++ b/openspec/changes/sbmd-observability-instrumentation/design.md @@ -91,7 +91,7 @@ InvokeHandler (JS mutex held by caller): Idle background thread: → 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(deadline) + → TickleSampler() ← increments tickleSeq cv.wait_until(lock, deadline) if timed_out: ForceSnapshot() // real tickle (tickleSeq != seq): // no snapshot, reset timer @@ -142,7 +142,7 @@ An `OperationContext operationCtx` field is added to `PendingOperation`. It is i core/deviceDrivers/matter/sbmd/ │ ├── mquickjs/ -│ ├── MQuickJsRuntime.cpp ← heap metrics, ForceSnapshot(), RecordHeapSnapshot(JSMemoryUsage&), +│ ├── MQuickJsRuntime.cpp ← heap metrics, ForceSnapshot(), RecordHeapSnapshot(const JSMemoryUsage &), │ │ RecordMutexWait(), RecordJsException(), TickleSampler(); │ │ in-activity + idle sampling │ └── SbmdHandlerInvoker.cpp ← invocation/outcome metrics, RecordOutcomeError(); diff --git a/openspec/changes/sbmd-observability-instrumentation/tasks.md b/openspec/changes/sbmd-observability-instrumentation/tasks.md index b9d7d3f6..8d279021 100644 --- a/openspec/changes/sbmd-observability-instrumentation/tasks.md +++ b/openspec/changes/sbmd-observability-instrumentation/tasks.md @@ -1,7 +1,7 @@ ## 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 2.0, 3.0, 4.0, and 5.0 respectively) +- [ ] 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