Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
3 changes: 3 additions & 0 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -8,6 +8,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
## [Unreleased]

### Added
- **A collector losing cycles to the wall-clock budget no longer reports `HEALTHY` with `errors: 0`** ([#2804]) - [#2803] gave a budget-abandoned cycle its own `ABANDONED` status so it would stop masquerading as SUCCESS. The write side landed; the READ side never caught up, so the fact reached every surface as a sentence inside `note_summary` and never as a number. An ABANDONED run incremented `total_runs` and **nothing else** - not success, error, permission denial or yield - so it grew the failure-rate DENOMINATOR while contributing nothing to its numerator, and never advanced `last_success_time`. TOTAL abandonment does still reach FAILING through staleness, because no success lands at all; the gap was the PARTIAL case, where a collector abandons some cycles and succeeds often enough to stay fresh, so staleness never fires, the error rate is exactly 0, and the row reads HEALTHY indefinitely while losing collections. Measured on a production server: `procedure_stats` at **24 abandoned of 1,226 runs** and `query_stats` at 14 of 1,226, both `status=HEALTHY errors=0`. The count is now first-class (`abandoned` / `abandon_rate_pct` on both MCP tools, an **Abandoned** column on the web grid and both WPF grids) and feeds the shared `CollectorHealthClassifier`, which bands **WARNING** above a 0.5% rate. **The threshold came from the fleet, not from taste**: across 1,639 (server, collector) pairs and 520,455 runs in 24h, only FOUR pairs abandoned anything at all - 28 runs, 0.005% fleet-wide - and the per-pair rate distribution is p50 = p75 = p90 = p95 = **p99 = 0.000%** with a max of 2.157%, so the real population is an empty body and a four-point tail spanning 0.60%-2.16%. 0.5 sits strictly below that observed floor and strictly above the 99th percentile, and keeps a lone abandonment quiet in any window under ~400 runs. **WARNING rather than a new band** because a new string would have to be learned by four display mappings that fail in opposite directions - the web's `statusToSev` defaults to "Unknown" while the deprecated Dashboard's brush converter defaults to `Transparent`, the same brush it gives HEALTHY - and attribution survives anyway, since the abandoned count now sits beside the error count in the same row. The fix is **read-side only**: no new column, no schema rung. Caught while wiring it: the fleet rollup builds its own banding row from `FleetCollectionHealthSql` and would have kept calling an abandoning collector HEALTHY while every other surface called it WARNING - and it **compiled**, because an unset count defaults to 0. That is the [#2779]/[#2784] shape, so the pin asserts over all FOUR banding reads by name rather than over the one that was broken.

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nit: this line uses [#2803] as a reference-style link, but [#2803]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2803 is never defined anywhere in this file (unlike [#2804], [#2779], [#2784], which are all defined further down). As written, [#2803] will render as literal bracketed text instead of a link.

- **The server-scoped phase split is now a set of columns, so it can be aggregated and read without an SSM session** ([#2859]) - [#2851] decomposes a server-scoped collector's `sql_duration_ms` into `open:` and `drain:` and reports the store-side watermark read beside them, and all of it existed only as an app-log line. So the one question the split was built to answer - which phase owns a collector's cost, across servers and over time - needed a session onto the box and a log scrape per server, and could not be trended or reached through the MCP at all. On 2026-09-03 an investigation into where `procedure_stats`' 4,724ms drain actually goes stalled on exactly that: AWS SSO began returning `InternalServerException` on `GetRoleCredentials`, SSM went unavailable, and the numbers were unreachable even though the store itself was answering normally. V108 adds `sql_open_ms`, `sql_drain_ms` and `watermark_ms` to `collection_log`, and `get_collection_log` returns them, so `avg(sql_drain_ms) / avg(sql_duration_ms)` is a store query - 96.4% for a `procedure_stats` row in the verification rig. **Columns rather than a jsonb blob** because the phase set on this path is FIXED (open, drain, watermark), so jsonb's flexibility buys nothing and costs the cheap aggregation that is the entire point; the shape that genuinely does vary - [#2811]'s fetch split, with its per-chunk and per-id counts - is emitted once per DATABASE while `collection_log` holds one row per RUN, so it is N:1 here and needs a rollup decision of its own exactly as the V80 fan-out did, filed separately rather than half-answered. **`other:` is deliberately NOT stored**: it is a residual defined against `sql_duration_ms`, and a stored copy could drift from the parent it completes - the sum-to-parent property is precisely what makes a large residual a finding rather than noise, so readers subtract instead. **`watermark_ms` keeps its own name without the `sql_` prefix** because on this path it genuinely is outside that sum (it runs before the stopwatch starts), and folding it in would print a permanent zero and teach every reader that a store read [#2796] clocked at 50s cold is free. All three write together or not at all, gated on [#2851]'s MEASURED flag rather than a non-zero test, so a genuinely instant open records 0 rather than vanishing into NULL. Nullable with no DEFAULT and no backfill, the V80 reasoning: verified against a real store at the production shape - 37 compressed chunks - where the rung applied in ~100ms as a catalog-only change and pre-existing rows read back NULL rather than 0. The view refresh is proven load-bearing by negative control: with the ALTER alone the columns exist on the table and the MCP read fails with `column "sql_drain_ms" does not exist`. `InsertCollectionLogSql` is deliberately SHARED between the per-collector writer and the fleet-wide retention run-record, so both binding blocks widened together - the retention sweep stores NULL phases, having no monitored-server open or drain and no watermark read. Missing that second writer raised `08P01: bind message supplies 14 parameters, but prepared statement "" requires 17`, and because both writers are failure-isolated by design (an observability write must never break the collection loop) it failed SILENTLY to a Debug log - the run-record simply never appeared. Now pinned by asserting binding-count against placeholder-count across every writer of the shared statement rather than the two that exist today, since a third would fail exactly as quietly; the comment beside the fanout block already warned the statement was shared, and a comment enforces nothing.
- **Server-scoped collectors now emit the `open:`/`drain:` phase split, so the largest collector on the fleet can be attributed** ([#2851]) - the breakdown was gated on `PerItemOpenMs > 0`, which only the per-database enumerated path sets, so a server-scoped collector logged one blended `sql:Nms` and nothing else. `procedure_stats` is the biggest single term in use1's 1-minute body (p50 4,900ms, 69% of it) and the same shipped query run from the same box against the same target takes 247ms - an 18.8x gap measured with the box at 4% CPU, and no way to say whether it was the execute, the drain, or neither. Same shape as the store probe's ~40x (36ms in a harness vs ~1,451ms in production), and THAT was only tractable because [#2811]/[#2816] had split its phases. Cycles on this path now emit a second line - `sql:Nms = open:Nms + drain:Nms + other:Nms (wm:Nms store-side, outside sql)` - on its own line so the existing one stays byte-identical for tooling outside this repo. Three deliberate departures from the enumerated form: `drain:` is MEASURED rather than inferred, so `other:` is a real residual (query building, command construction, the probe-failure rowset, the supplemental query) instead of a term that silently absorbs them; the line is gated on a `ServerPhasesMeasured` FLAG rather than a value being non-zero, because `> 0` cannot tell a genuinely instant open from a path that measures nothing; and `wm:` is reported OUTSIDE the sum, because on this path the watermark read runs before the `sql:` stopwatch even starts - the issue's own framing that `sql_duration_ms` is wm+open+drain is wrong here, and folding it in would have printed a permanent `wm:0ms` and taught every future reader that a store read [#2796] clocked at 50s cold is free. Stamps come from `finally` blocks, not trailing assignments ([#2816]'s lesson: a throwing await jumps a trailing assignment, the phase reports 0ms, and the residual absorbs a cost it documents as belonging to neither database - 97% of one day's residual budget was a single such misattribution), and the abandoned-cycle return reports its phases too, since a collector that blew its wall-clock budget is exactly the one worth asking "on what". Pinned two ways because one cannot see what the other misses: arithmetic (the parts sum to the parent, the residual clamps at zero) and IL REACHABILITY (both stamps are invoked from inside an exception-handling region), the latter carrying a control setter that shares the scanner's failure surface. Instrumentation only - no query, schedule or collector change.
- **The sweep-body detach policy (#2700/#2717) is now pinned, including the invariant that makes it safe** ([#2840]) - `query_store` and `plan_correction` are fired DETACHED from the sequential per-server collection body, because the outer launch loop will not relaunch that body while it runs (INV-2, one body per server), so one slow collector delays every other collector for that server. That set had no test at all, and the criterion for admitting a third collector was recorded nowhere. Measured against production `collection_log`, the set is exactly right: `query_store` at p90 65,053ms and `plan_correction` at max 133,934ms are the only per-cycle cost outliers, and the intuitive derivation from enumerated-vs-scalar fanout is disproved in BOTH directions - `database_scoped_config` fans out to 10 databases at p90 127ms, while `procedure_stats` has zero fanout at p90 11,964ms, so a fanout-derived split would detach the cheap collector and leave the expensive one starving the tier. The pin that generalizes asserts no detached collector sits on the 1-minute tier: a detached run SKIPS when its previous run is still in flight, so detaching a 1-minute collector converts starvation into guaranteed misses - exactly what would happen if the residual ~1.5-minute floor ([#2841]) were "fixed" by detaching `procedure_stats`.
Expand Down Expand Up @@ -3148,6 +3149,8 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
[#2791]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2791
[#2795]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2795
[#2801]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2801
[#2803]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2803
[#2804]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2804
[#2779]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2779
[#2784]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2784
[#2786]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2786
Expand Down
Loading
Loading