diff --git a/CLAUDE.md b/CLAUDE.md index 46c7d8f..ab758f4 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -719,6 +719,27 @@ Two lines of the self-check output are assertions in disguise: whole window fits in the raw path and the publish is too short to lose a race. (Do not raise `--batch` to chase the rate: a batch of 20000 exceeds the datagram limit and the mock dies with `OSError: [Errno 90] Message too long`.) +- `publish cost: N events, A/B ms (mean/worst, blocks the UI); M pauses, C/D ms (mean/worst, + blocks the producer)` — what *freezing a view* costs, and the line that attributes the stall + `frame cost:`'s `tick` max can only hint at. The two publishes are counted apart because they + stall **opposite threads**, and nothing else in the dump distinguishes them: + `publish_event()` runs on the producer with `mutex()` already held, so its cost lands on the UI + as a long tick; `publish_pause_view()` runs on the UI thread and takes the lock, so its cost + lands on the producer and can only surface as `gaps`. Read the event figure against `tick`'s max + and the pause figure against `gaps`. Measured on the fast mock over a 3 s run: one event at + **115 ms** and one pause at **22.3 ms** — the event figure is far above the ~40 ms the `tick` + entry above quotes, so treat that 40 as the old reading and this line as the authority. + It is also **the number to judge a second live ring against**, which is the one design question + it exists to answer: freezing a whole `BufferStore` copies nothing and inherits the pyramid a + `ChannelBuffer` already maintains incrementally, so both `worst` figures would go to **0** — at + the price of a second budget's worth of memory (README records that one live ring is why + `--buffer-mb 200` really is 200 MB) and a second per-sample write on the producer. Two things + make the trade less obvious than the memory arithmetic suggests, and both were measured rather + than reasoned: the event publish really is ~115 ms of blocked UI, and **a pause costs `gaps` + where a run without one reads `gaps=0`** (73 with the pause against 0 without). That second + finding is *not* the publish length — it read 79 gaps with the pyramid build removed and 73 with + it, i.e. it does not scale with the stall — so it is **unexplained**, and anyone pricing a second + ring should find out what it actually is first rather than assume the ring would fix it. - `trace ink: N paints checked, C collapsed, S staircase, H short, worst cover P%, worst drawn-vs-quoted D px over R raw paints` plus a `[ink] paint N mode=.. axis=[..] n=.. idx=[..) spp=.. level=.. pts=.. kept=.. @@ -1138,6 +1159,21 @@ far the largest file. is built once in `publish_event()` inside the `O(n)` pass that already computes the y bounds, and the same channel on two rows shares it. It costs ≈1 byte per sample per channel. `frame path:`'s `segments` is the guard. + **"Every" includes the pause**, and that is the half this invariant was written without and + which then went wrong for real: `publish_pause_view()` filled `stamps`, `values` and `y` and + left `pyramids` empty, so a *paused* view was re-gathered raw on every frame. Both halves of + the cost are readable, and the second is the one a performance line cannot show. + `frame path:` read `raw=21 lod=118` over a 1.6 s pause against `raw=1 lod=170` for the same run + live, with the draw mean 12.34 → 18.18 ms — and the **trace changed appearance**, which is what + gets reported. `stage_trace_density()` grades a column against *its own peak* from a `1/height` + deposit per segment, so a column fed ~660 raw inter-sample segments accumulates a far spikier + distribution, and a far larger peak to normalise against, than one fed the one or two bucket + envelopes the pyramid gives: the paused trace read as a hard bright core with its dwell tail + dimmed out. **A pause is not a cheaper case than a capture — it freezes the same rings**, so + anything `publish_event()` does to a snapshot, `publish_pause_view()` owes too. Building it is + not free (see `publish cost:` below): it took the pause publish from 6.15 ms to 22.31 ms, a + one-off producer stall against ~5 ms a frame of draw for the pause's whole length, which at + ~60 fps repays about thirty times over on a 1.6 s pause. - **`EventSeries::gather()` emits a bucket's envelope, not every `2^level`-th sample.** Point decimation hides exactly the spike the capture was triggered on; a scope has to draw a bucket's extremes. It needs no index rebasing, unlike the ring: the snapshot's diff --git a/README.md b/README.md index 9d6c639..642ec9b 100644 --- a/README.md +++ b/README.md @@ -459,7 +459,8 @@ ring per channel (N enabled signals -- see the limitation on multi-element signa below). The spec's second buffer is the latched `EventSnapshot`, which is already an immutable copy of the captured window (see "Trigger" below); a second live ring bought nothing and cost half the memory budget, so `--buffer-mb 200` really is -200 MB. +200 MB. What it *would* buy is priced in the dump's `publish cost:` line — see +"There is one live buffer, not two" under the review findings. `plan_partition()` sizes the rings to cover `--max-window` seconds and then grows them with the rest of the budget. When a channel's declared sample rate is lower than the fastest channel's, it is decimated by the integer ratio @@ -973,8 +974,31 @@ which hides exactly the spike a capture was triggered on, and since the level wa it never even ran. On the same repro: **138,078 segments** (43× fewer) and a 66 ms worst frame, with the steady-state draw around 2 ms. It costs about 1 byte per sample per channel (≈25 % on top of the snapshot's `f32` values) and one stall per latch, since the -build runs under `ScopeModel::mutex()` — at 1.3 MS/s that is a ~40 ms tick, once, with no -packet gaps. +build runs under `ScopeModel::mutex()`. That stall is now measured rather than estimated — +the dump's `publish cost:` line read **115 ms** for one event publish at 1.3 MS/s, against +the ~40 ms this paragraph used to quote — and it produced no packet gaps. + +**A paused view carries one too**, and that half was missing until it was found by its +*appearance*. `publish_pause_view()` filled `stamps`, `values` and `y` and left `pyramids` +empty, so a frozen pause was drawn from every raw sample it held, on every frame — the same +defect as above with the same cause, in the other snapshot. `frame path:` read +`raw=21 lod=118` over a 1.6 s pause against `raw=1 lod=170` for the same run live, with the +draw mean going 12.34 → 18.18 ms and its worst frame 30.35 → 86.92 ms. But the reason it was +noticed is that the trace *looked* different: `Renderer::stage_trace_density()` grades each +pixel column against that column's own peak, from a `1/height` dwell deposit per segment, so +a column fed several hundred raw inter-sample segments accumulates a far spikier +distribution — and a far larger peak to normalise against — than one fed the one or two +bucket envelopes the pyramid gives. The paused trace read as a hard bright core with its +dwell tail dimmed away. The rule the invariant was written without: **a pause is not a +cheaper case than a capture — it freezes the same rings.** + +It is not free, and the trade is one-off against per-frame. Building the pause pyramid took +that publish from 6.15 ms to 22.31 ms, and unlike the event publish this one runs on the +**UI** thread and so blocks the *producer* — against ~5 ms a frame of draw for as long as the +pause lasts, which over a 1.6 s pause at ~60 fps repays thirty times over. One finding there +is still open: a run that pauses reports `gaps=73` where the same run without a pause reads +`gaps=0`, and it does **not** scale with the publish length (79 gaps with the pyramid build +removed, 73 with it), so the stall is not what it is. The self-check's two `frame cost:` / `frame path:` lines are the guard: they split a frame into the tick, the plot's own draw and the whole GTK paint, and report the segment counts @@ -1738,7 +1762,17 @@ now — they are listed so they are not mistaken for anything else: latched `EventSnapshot` — an immutable copy of the captured window, which is exactly what "the buffer the view is frozen on" needs to be. Two live rings would also mean acquisition had to follow the trigger state, which is what left the first - latch after arming with no pre-trigger history. + latch after arming with no pre-trigger history. What a second ring would buy is the + publish: freezing a whole `BufferStore` copies nothing and inherits the pyramid the + producer already maintains, so both figures in the dump's `publish cost:` line would + go to zero. They are worth knowing before pricing that — one event publish measured + **115 ms of blocked UI tick** at 1.3 MS/s and one pause publish **22 ms of blocked + producer** — but they do not pay for a second budget's worth of memory, a second + per-sample write on the producer, and a single frozen slot where the app today holds + an event, a pause and an export's window at once. One thing to settle first: a run + that pauses reports `gaps=73` against `gaps=0` without a pause, and that does not + scale with the publish length, so it is not the stall and a second ring would not + obviously fix it. - **The buffer is allocated at the first CONFIG, not at initialisation.** The spec's "N+1 split" needs N, which only a CONFIG gives; `--buffer-mb` is the *budget*, and the power-of-two ring rounding means the final diff --git a/src/model.cpp b/src/model.cpp index 41f8f0d..2a31597 100644 --- a/src/model.cpp +++ b/src/model.cpp @@ -516,6 +516,9 @@ void ScopeModel::reset_live_history_locked() { } void ScopeModel::publish_pause_view(double lo_s, double hi_s, double x_offset) { + // Timed from before the lock: the wait for it is part of what freezing a view costs the thread + // doing it, and this one is the UI's. + const std::uint64_t t0 = now_ns(); auto snap = std::make_shared(); snap->x_offset = x_offset; std::lock_guard lock(mutex_); @@ -537,6 +540,7 @@ void ScopeModel::publish_pause_view(double lo_s, double hi_s, double x_offset) { } snap->values.resize(channels_.size()); snap->y.resize(channels_.size(), plot::Range{0.0, 0.0}); + snap->pyramids.resize(channels_.size()); for (std::size_t c = 0; c < channels_.size(); ++c) { const u64 stride = std::max(1, part_.stride[c]); auto& vals = snap->values[c]; @@ -545,16 +549,42 @@ void ScopeModel::publish_pause_view(double lo_s, double hi_s, double x_offset) { if (take > 0) src.values(c).copy_from(first + n - take, take, vals.data()); f32 lo = vals.empty() ? 0.0f : vals.front(); f32 hi = lo; + // The LOD index, folded into the bounds pass exactly as `publish_event()` folds it, and for + // the same reason: a snapshot that answers `pyramid()` with an empty one has `level_for()` + // descend to level 0, so the frozen view is re-gathered from every raw sample it holds on + // every frame it is on screen. A pause is not a cheaper case than a capture -- it freezes the + // *same* rings -- and leaving it out was visible twice over. The cost: `frame path:` read + // `raw=21 lod=118` over a 1.6 s pause against `raw=1 lod=170` for the same run live, with the + // draw mean 12.34 -> 18.18 ms. And the *look* changed, which is the half a cost figure does + // not show: `stage_trace_density()` grades a column against its own peak from a `1/height` + // deposit per segment, so a column fed ~660 raw inter-sample segments accumulates a far + // spikier distribution -- and a far larger peak to normalise against -- than one fed the one + // or two bucket envelopes the pyramid gives. The paused trace read as a hard bright core with + // its dwell tail dimmed out, i.e. the trace changed appearance on pause. + // + // It is not free, and the trade is one-off against per-frame: building it took the pause + // publish from 6.15 ms to 22.31 ms (`publish cost:`), which blocks the *producer* -- against + // ~5 ms a frame of draw for as long as the pause lasts, which at ~60 fps a 1.6 s pause repays + // thirty times over. The gaps a pause costs are **not** this: they measured 79 without the + // pyramid and 73 with, so they are the pause's own and still unexplained. + auto& pyr = snap->pyramids[c]; + pyr.reserve(take); for (f32 v : vals) { lo = std::min(lo, v); hi = std::max(hi, v); + pyr.append(v); } snap->y[c] = plot::Range{lo, hi}; } pause_view_.store(std::move(snap), std::memory_order_release); + note_publish(publish_pause_count_, publish_pause_us_total_, publish_pause_us_worst_, + (now_ns() - t0) / 1000u); } void ScopeModel::publish_event(double pre_s, double post_s, double edge) { + // The caller is the producer and already holds `mutex()`, so every microsecond counted here is a + // microsecond the UI tick is blocked for -- which is what the documented `tick` max is made of. + const std::uint64_t t0 = now_ns(); auto snap = std::make_shared(); snap->x_offset = edge; // the stream time x = 0 means, for everything that has to cross back BufferStore& src = live(); @@ -605,6 +635,8 @@ void ScopeModel::publish_event(double pre_s, double post_s, double edge) { // Bumped after the snapshot is in place, so a consumer that sees the new sequence // number sees the snapshot it counts. event_seq_.fetch_add(1, std::memory_order_release); + note_publish(publish_event_count_, publish_event_us_total_, publish_event_us_worst_, + (now_ns() - t0) / 1000u); } void BufferStore::set_epoch(f64 epoch) noexcept { diff --git a/src/model.hpp b/src/model.hpp index a77fa56..9795af6 100644 --- a/src/model.hpp +++ b/src/model.hpp @@ -224,6 +224,37 @@ class ScopeModel { std::uint64_t math_cost_ns() const noexcept { return math_cost_ns_.load(std::memory_order_relaxed); } + /// What freezing a view costs, and *which thread it costs it to*. The two publishes are stalls on + /// opposite sides of `mutex()` and so are counted apart: `publish_event()` runs on the **producer** + /// with the lock already held, so its cost lands on the UI as a long tick (the documented `tick` + /// max); `publish_pause_view()` runs on the **UI** thread and takes the lock, so its cost lands on + /// the producer and can only surface as `gaps`. Neither is attributable in a frame mean, which is + /// why they are counted rather than inferred. Each counter is written by one thread and read by the + /// dump, so a relaxed store of a value already in hand is enough. + /// + /// This is the number to judge a second live ring against: freezing a whole `BufferStore` would + /// make both figures zero, since a `ChannelBuffer` maintains its pyramid incrementally and there + /// would be nothing to copy -- but it costs a second budget's worth of memory and a second + /// per-sample write on the producer, so it is worth paying only if the worst figures here are + /// large enough to matter. + std::uint64_t publish_event_count() const noexcept { + return publish_event_count_.load(std::memory_order_relaxed); + } + std::uint64_t publish_event_us_total() const noexcept { + return publish_event_us_total_.load(std::memory_order_relaxed); + } + std::uint64_t publish_event_us_worst() const noexcept { + return publish_event_us_worst_.load(std::memory_order_relaxed); + } + std::uint64_t publish_pause_count() const noexcept { + return publish_pause_count_.load(std::memory_order_relaxed); + } + std::uint64_t publish_pause_us_total() const noexcept { + return publish_pause_us_total_.load(std::memory_order_relaxed); + } + std::uint64_t publish_pause_us_worst() const noexcept { + return publish_pause_us_worst_.load(std::memory_order_relaxed); + } const std::vector& signals() const noexcept { return signals_; } const std::vector& channels() const noexcept { return channels_; } @@ -491,6 +522,22 @@ class ScopeModel { std::atomic math_slots_{0}; std::atomic math_timed_{0}; std::atomic math_cost_ns_{0}; + /// See `publish_event_count()`. Single-writer each: the first three are the producer's, the last + /// three the UI thread's. + std::atomic publish_event_count_{0}; + std::atomic publish_event_us_total_{0}; + std::atomic publish_event_us_worst_{0}; + std::atomic publish_pause_count_{0}; + std::atomic publish_pause_us_total_{0}; + std::atomic publish_pause_us_worst_{0}; + /// Fold one publish's elapsed microseconds into a counter triple. Called by the one thread that + /// owns the triple, so the load/store pairs need no read-modify-write. + static void note_publish(std::atomic& count, std::atomic& total, + std::atomic& worst, std::uint64_t us) noexcept { + count.store(count.load(std::memory_order_relaxed) + 1, std::memory_order_relaxed); + total.store(total.load(std::memory_order_relaxed) + us, std::memory_order_relaxed); + if (us > worst.load(std::memory_order_relaxed)) worst.store(us, std::memory_order_relaxed); + } std::vector enabled_; Partition part_; diff --git a/src/ui.cpp b/src/ui.cpp index 238d9a7..104f11a 100644 --- a/src/ui.cpp +++ b/src/ui.cpp @@ -8383,6 +8383,28 @@ int run_ui(int argc, char** argv, const Config& cfg, ScopeModel& model, Acquisit per_slot * static_cast(app.model->math_slots()) / 1.0e6); } } + // What freezing a view costs, counted apart for the two publishes because they stall opposite + // threads (see `ScopeModel::publish_event_count()`). This is the figure a second live ring would + // buy: freezing a whole `BufferStore` copies nothing and inherits the pyramid the producer + // already maintains, so both `worst` figures would be 0 -- at a second budget's worth of memory + // and a second per-sample write on the producer. Read `event worst` against `frame cost:`'s + // `tick` max (the same stall, seen from the UI) and `pause worst` against `gaps`. + { + const auto ev = app.model->publish_event_count(); + const auto pa = app.model->publish_pause_count(); + std::printf("[udpscope] publish cost: %llu events, %.2f/%.2f ms (mean/worst, blocks the UI);" + " %llu pauses, %.2f/%.2f ms (mean/worst, blocks the producer)\n", + static_cast(ev), + ev > 0 ? static_cast(app.model->publish_event_us_total()) / + static_cast(ev) / 1000.0 + : 0.0, + static_cast(app.model->publish_event_us_worst()) / 1000.0, + static_cast(pa), + pa > 0 ? static_cast(app.model->publish_pause_us_total()) / + static_cast(pa) / 1000.0 + : 0.0, + static_cast(app.model->publish_pause_us_worst()) / 1000.0); + } // Unconditional, unlike the pane's own lines below: this is about the instruments the app // *created*, which exist whether or not any measurement was added. std::printf("[udpscope] readout instruments locked: %d (trigger marker + measurement marks)\n",