# Temperlux UI Performance Logging — Design Document

Status: **Design only — no code changes yet.**
Audience: Temperlux maintainers diagnosing slider-lag complaints in the GTK4/libadwaita GUI.
Target binary: `temperlux-gui` (`src/bin/gui.rs` → `gui::window::run`).

---

## 1. Goal

Build an opt-in, low-overhead performance log that lets us answer, for any
slider drag:

1. *Did the GTK signal fire on time?*  → input-side latency
2. *Did the worker channel deliver it on time?*  → in-process queuing
3. *How long did the DDC/CI I²C write take?*  → hardware-side latency
4. *Did the monitor actually move to that value?*  → readback verification
5. *What is the end-to-end "finger-lift → photons" delay?*

A run with `--perf-log=/tmp/temperlux.perf` (or `TEMPERLUX_PERF_LOG=/tmp/...`)
must produce a single append-only NDJSON file with millisecond timestamps and
a stable schema that downstream tooling (`jq`, pandas) can analyse.

---

## 2. Current pipeline (verified by reading the source)

```
GTK slider drag (main thread)
  └─ Scale::connect_value_changed                       src/gui/window.rs:675
        │  closure: clamp → raw → worker_tx.set(raw)    src/gui/window.rs:677–685
        │                       worker_pool             src/gui/window.rs:653
        ▼
DisplayWorker (per-display std::thread)                 src/gui/debounce.rs:80–134
   mpsc::channel::<i32>
     ├─ recv()                                          debounce.rs:109
     ├─ try_recv() drain  ← coalescing #1               debounce.rs:111–113
     └─ executor(latest)                                debounce.rs:116
            │
            ├─ DDC path: DdcService.set_brightness()    src/display/ddc_ffi.rs:315
            │     mpsc::channel::<DdcCommand>
            │       ├─ recv()                           ddc_ffi.rs:251
            │       ├─ try_recv() drain ← coalescing #2 ddc_ffi.rs:257–280
            │       └─ DdcHandle::set_brightness()      ddc_ffi.rs:117 (libddcutil I²C write)
            │              │
            │              └─ optional readback:
            │                 DdcHandle::get_brightness()  ddc_ffi.rs:133
            │
            └─ Backlight path: RealBacklightProvider    src/display/backlight.rs:39
                  └─ sysfs write
```

Observations driving the design:

- **Two coalescing stages** (DisplayWorker drains + DdcService drains).
  Either can silently drop slider samples. Both must be observable.
- `DisplayWorker::last_latency_ms` (debounce.rs:84) and
  `DdcService::latency_ms` (ddc_ffi.rs:203) already exist but are GUI-only
  scalars — no history, no correlation with the source GTK event.
- `DdcHandle::get_brightness` (ddc_ffi.rs:133) is a real readback via
  `ddca_get_non_table_vcp_value` (FFI) — usable as a "hardware response"
  signal (item 3 of the issue), but it costs an extra I²C round-trip.
- CLI today is a `clap` enum (`src/cli.rs`) with no global options, and
  `src/bin/gui.rs` calls `gui::window::run()` with no argv plumbing. Both
  need a small extension.

---

## 3. Top-level design

### 3.1 New module: `src/perf.rs`

A single file, feature-gated, with zero cost when disabled.

```rust
// src/perf.rs (sketch — DO NOT IMPLEMENT YET)

use std::sync::OnceLock;
use std::sync::atomic::{AtomicU64, Ordering};
use std::time::Instant;

/// Globally accessible perf recorder. `None` ⇒ logging disabled (zero cost).
static RECORDER: OnceLock<Option<PerfRecorder>> = OnceLock::new();

/// Monotonic event id, monotonically increasing across all threads.
static EVENT_SEQ: AtomicU64 = AtomicU64::new(0);

/// Process-wide reference instant; t_ms in records is (now - START).
/// Stored as Instant so we never call SystemTime on the hot path.
static START: OnceLock<Instant> = OnceLock::new();

pub fn init(path: Option<&std::path::Path>) -> anyhow::Result<()> { ... }
pub fn is_enabled() -> bool { RECORDER.get().map(|r| r.is_some()).unwrap_or(false) }

/// Cheap no-op when disabled. Inlined.
#[inline]
pub fn log(ev: Event) {
    if let Some(Some(rec)) = RECORDER.get() { rec.push(ev); }
}

/// One worker thread drains a bounded mpsc and serialises NDJSON to file.
/// We never block the GTK / worker / DdcService threads on file I/O.
struct PerfRecorder {
    tx: crossbeam_channel::Sender<Event>,  // or std::sync::mpsc
}
```

The recorder runs a dedicated thread whose only job is `serde_json::to_writer`
+ `BufWriter::flush()` every N ms. The hot path does at most:

1. one `OnceLock::get()`,
2. one `Instant::now()`,
3. one `Sender::try_send()` (drops oldest on a full bounded channel so we
   never block the GTK loop even under storm).

### 3.2 Event model

```rust
#[derive(serde::Serialize, Clone, Debug)]
#[serde(tag = "kind")]
pub enum Event {
    /// GTK Scale::value-changed signal fired (main thread).
    SliderChanged {
        seq: u64,
        t_ms: u64,                // ms since perf init
        display_key: String,      // e.g. "ddc:1" or "bl:intel_backlight"
        gtk_value_pct: f64,
        raw_value: i32,
        sync_mode: u32,           // 0=off / 1=relative / 2=absolute
    },

    /// Slider sample sent into DisplayWorker channel (debounce.rs:127).
    WorkerEnqueued {
        seq: u64,
        t_ms: u64,
        parent_seq: u64,          // → SliderChanged.seq
        display_key: String,
        raw_value: i32,
        channel_len: usize,       // best-effort; counter we maintain
    },

    /// DisplayWorker took a value off the channel; reports coalescing depth.
    WorkerDequeued {
        seq: u64,
        t_ms: u64,
        display_key: String,
        raw_value_executed: i32,
        coalesced_count: u32,     // how many samples drained in try_recv loop
        coalesced_dropped: Vec<i32>,  // optional; gated by --perf-log-verbose
    },

    /// Just before DdcService::set_brightness() is called from the worker.
    DdcDispatched {
        seq: u64,
        t_ms: u64,
        parent_seq: u64,          // → WorkerDequeued.seq
        display_num: i32,
        raw_value: u16,
    },

    /// DdcService thread received the command (ddc_ffi.rs:251).
    DdcServiceReceived {
        seq: u64,
        t_ms: u64,
        parent_seq: u64,          // → DdcDispatched.seq
        display_num: i32,
        raw_value: u16,
        coalesced_count: u32,     // try_recv drain at ddc_ffi.rs:257
    },

    /// I²C / libddcutil write boundaries (ddc_ffi.rs:283–289).
    DdcWriteStart { seq: u64, t_ms: u64, parent_seq: u64, display_num: i32, raw: u16 },
    DdcWriteEnd   {
        seq: u64, t_ms: u64, parent_seq: u64,
        display_num: i32, raw: u16,
        duration_us: u64,
        result: WriteResult,      // Ok | Err(String)
    },

    /// Optional verification via ddca_get_non_table_vcp_value (ddc_ffi.rs:133).
    /// Only emitted when --perf-log-readback is set.
    DdcReadback {
        seq: u64, t_ms: u64, parent_seq: u64,
        display_num: i32,
        expected_raw: u16,
        actual_raw: u16,
        duration_us: u64,
        matched: bool,
    },

    /// Backlight (sysfs) write — analogous to DdcWriteStart/End.
    BacklightWriteStart { seq: u64, t_ms: u64, parent_seq: u64, name: String, raw: u32 },
    BacklightWriteEnd   { seq: u64, t_ms: u64, parent_seq: u64, name: String, raw: u32, duration_us: u64, result: WriteResult },

    /// One per drag, emitted on a 250 ms idle after the last SliderChanged.
    /// Computed off-thread by the recorder by joining seq → parent_seq.
    EndToEnd {
        first_slider_seq: u64,
        last_slider_seq: u64,
        display_key: String,
        slider_count: u32,         // samples GTK emitted
        executed_count: u32,       // writes actually performed (= 1 + non-coalesced)
        drop_count: u32,           // slider_count − executed_count
        first_t_ms: u64,
        last_write_end_t_ms: u64,
        last_readback_t_ms: Option<u64>,
        e2e_ms: u64,               // last_readback_t_ms or last_write_end_t_ms − first_t_ms
    },
}

#[derive(serde::Serialize, Clone, Debug)]
pub enum WriteResult { Ok, Err(String) }
```

`seq`/`parent_seq` is the glue. Every record carries a monotonically
increasing `seq` (from `EVENT_SEQ.fetch_add(1, Relaxed)`), and downstream
events embed the upstream `seq` they originated from. This lets `jq` join
records across threads without timestamp guessing.

### 3.3 File format

NDJSON (one JSON object per line). One file per process run. Path:

- `--perf-log <PATH>` ⇒ that exact path
- `--perf-log` with no value ⇒ `$XDG_CACHE_HOME/temperlux/perf-<pid>-<unix_ts>.ndjson`
- `TEMPERLUX_PERF_LOG` env var ⇒ same semantics (env loses to CLI)

The first record is always a header:

```json
{"kind":"Header","version":1,"pid":12345,"start_unix_ms":1716923400123,
 "temperlux_version":"x.y.z","gtk_version":"4.14.2","libddcutil":"2.1.4",
 "displays":[{"key":"ddc:1","name":"DELL U2723QE","max_raw":100}]}
```

`start_unix_ms` lets analysts map relative `t_ms` back to wall-clock; on the
hot path we still use `Instant`.

---

## 4. Integration points (file:line → what to add)

| # | Location | Insertion |
|---|----------|-----------|
| A | `src/cli.rs` (Cli enum) | Add a sibling `#[derive(Parser)] struct GlobalArgs { #[arg(long, value_name="PATH")] pub perf_log: Option<Option<PathBuf>>, #[arg(long)] pub perf_log_readback: bool, #[arg(long)] pub perf_log_verbose: bool }` and `#[command(flatten)]` it. |
| B | `src/main.rs` | Call `perf::init(args.global.perf_log.as_deref())?` before dispatching the subcommand. |
| C | `src/bin/gui.rs` | Parse a minimal argv (or `std::env::var("TEMPERLUX_PERF_LOG")`) and call `perf::init(...)` before `gui::window::run()`. Pass a `Config` struct (or `OnceLock`) into `run()` so the GUI knows whether readback is on. |
| D | `src/gui/window.rs:675` (`scale.connect_value_changed`) | Right after `let val = s.value();` and before `worker_tx.set(raw);`, emit `Event::SliderChanged { ..., seq=new_seq }`. Stash `seq` in a small `Arc<Mutex<Option<u64>>>` per slider so the worker can pick it up. Better: thread the seq alongside the value by changing the worker channel payload to `(i32, u64)` (see §5). |
| E | `src/gui/debounce.rs:104` (`mpsc::channel::<i32>`) | Replace payload `i32` with `(i32 raw, u64 parent_seq)` so we can propagate causality. Backwards-compatible: the only callers are `worker.set()` (debounce.rs:127) and the executor closure in window.rs:653. |
| F | `src/gui/debounce.rs:109–117` | Emit `WorkerDequeued { coalesced_count, ... }` after the drain loop, before `executor(latest)`. Counter is computed during the existing `while let Ok(val) = rx.try_recv()` loop. |
| G | `src/gui/window.rs:653–666` (executor closure) | Around `svc.set_brightness(...)` emit `DdcDispatched`; around the backlight write emit `BacklightWriteStart`/`End`. Use `Instant` deltas. |
| H | `src/display/ddc_ffi.rs:200–204` (`DdcCommand` & `DdcService`) | Add a `parent_seq: u64` field to `DdcCommand::SetBrightness`. Update both the `set_brightness` API (`ddc_ffi.rs:315`) to accept and forward it, and the service loop. |
| I | `src/display/ddc_ffi.rs:251` (after `cmd_rx.recv()`) | Emit `DdcServiceReceived`. Track `coalesced_count` while draining at `ddc_ffi.rs:257–280`. |
| J | `src/display/ddc_ffi.rs:282–290` (write block) | Emit `DdcWriteStart` immediately before `handle.set_brightness`, `DdcWriteEnd` immediately after, recording `start.elapsed()` in microseconds. The existing `latency_ms` HashMap stays unchanged (UI indicator). |
| K | `src/display/ddc_ffi.rs:282–290` (post-write) | If `perf::readback_enabled()`, call `handle.get_brightness()` and emit `DdcReadback` with `expected_raw`, `actual_raw`, `matched = (actual == expected within max-tolerance 1)`. **Throttle**: only readback for the last write in a coalesced batch and never more than once per 250 ms per display — otherwise we double the I²C traffic and *cause* the lag we're trying to measure. |
| L | `src/display/backlight.rs:39` | Emit `BacklightWriteStart`/`End` around the `std::fs::write`. |
| M | `src/perf.rs` recorder thread | Implements the `EndToEnd` aggregation: groups records by `display_key`, fires when no new `SliderChanged` arrives within 250 ms. |

### 4.1 Causal seq propagation

Today the slider→worker→service path carries only `i32` (or `i32` + display_num).
To make the log analysable we need the original `SliderChanged.seq` to ride
with the value all the way to `DdcWriteEnd`. Two minimal type changes:

- `DisplayWorker::set(value: i32)` → `set(value: i32, parent_seq: u64)` (debounce.rs:126)
  internal channel `mpsc::Sender<i32>` → `mpsc::Sender<(i32, u64)>`.
- `DdcCommand::SetBrightness { display_num, raw }` → `{ display_num, raw, parent_seq }`.

Both are private types; the changes are confined to three files
(`debounce.rs`, `window.rs`, `ddc_ffi.rs`). When perf logging is disabled the
seq is still computed (`AtomicU64`) but never serialised — overhead is ≈ 4 ns.

---

## 5. CLI surface

```
temperlux-gui --perf-log[=PATH] [--perf-log-readback] [--perf-log-verbose]
temperlux     <SUBCMD> --perf-log[=PATH] ...    # for CLI parity, optional
```

- `--perf-log` (omitting value) ⇒ default path under `$XDG_CACHE_HOME`.
- `--perf-log-readback` ⇒ enable post-write `DdcHandle::get_brightness` verification.
  **Off by default** because it doubles I²C traffic.
- `--perf-log-verbose` ⇒ include `coalesced_dropped: Vec<i32>` and finer
  GTK event categories (see §6).
- Environment fallback: `TEMPERLUX_PERF_LOG`, `TEMPERLUX_PERF_LOG_READBACK=1`.

---

## 6. GTK input-side coverage

The issue mentions `value-changed`, `change-value`, `scroll-event`. Today
only `connect_value_changed` is wired (`window.rs:675`). To attribute lag to
the *input source*, also instrument:

- `Scale::connect_change_value` — fires before the adjustment is updated;
  carries `ScrollType`. Lets us distinguish *keyboard step*, *page step*,
  *drag*, *scroll wheel*.
- `EventControllerScroll` (GTK4 replacement for legacy `scroll-event`)
  attached to the `Scale` — captures discrete wheel ticks.
- `GestureDrag` on the slider trough — gives us the *finger-down* timestamp
  (the true "user intent" zero of end-to-end latency).

Each emits a `SliderChanged`-variant with a `source: "drag"|"wheel"|"key"|"gesture_begin"` field. Gating these behind `--perf-log-verbose` keeps the default file size manageable.

---

## 7. Hardware response semantics

The issue asks to track "WHEN the hardware responds (if possible — DDC/CI
VCP acknowledgment)". Important facts from the code:

- libddcutil's `ddca_set_non_table_vcp_value` returns when the I²C
  transaction completes; there is **no explicit VCP ACK** in the protocol
  beyond `ddc_set` status. So `DdcWriteEnd.duration_us` already approximates
  "monitor accepted the byte".
- The *only* truly empirical confirmation is a follow-up
  `ddca_get_non_table_vcp_value` (`DdcHandle::get_brightness`,
  ddc_ffi.rs:133), which we expose as the `DdcReadback` event.
- Monitors typically lag the readback value by 50–200 ms (firmware filtering
  + lamp ramp). The end-to-end metric therefore distinguishes:
    - `e2e_write_ms` = first slider → last successful `DdcWriteEnd`
    - `e2e_observed_ms` = first slider → first `DdcReadback{matched=true}`
       (only available with `--perf-log-readback`).

---

## 8. Performance budget

Hot path cost when disabled: 1 atomic load + 1 branch. With
`#[inline]` and `OnceLock`, this is < 2 ns.

Hot path cost when enabled: 1 `Instant::now()` (~25 ns), 1 atomic increment
(~5 ns), 1 `Sender::try_send()` on a bounded channel (~80 ns), no syscalls.
Worst case at 120 Hz slider sampling × 3 events per sample = 360 events/s ⇒
trivial.

The recorder thread does all `serde_json::to_writer` work + buffered file
I/O. If the bounded channel saturates we drop the oldest event and increment
a `dropped_events` counter, recorded periodically as a `RecorderStats` event.

---

## 9. Validation strategy

1. **Unit tests** (in `src/perf.rs`):
   - When `init(None)` is called, `log(...)` is a no-op (proved by a test
     handler returning a counter).
   - `seq` is monotonic across threads.
   - Header is the first line of the file.

2. **Integration test** (`tests/perf_logging.rs`):
   - Use the existing `MockDdcProvider` (referenced by tests in
     `debounce.rs`) to simulate 10 rapid value updates.
   - Assert: exactly 1 `DdcWriteEnd`, ≥ 1 `WorkerDequeued{coalesced_count≥9}`,
     1 `EndToEnd` with `executed_count == 1`, `drop_count == 9`.

3. **Manual run**:
   ```
   temperlux-gui --perf-log=/tmp/t.ndjson --perf-log-readback
   # drag slider for 3 seconds
   jq -r 'select(.kind=="EndToEnd") | "\(.display_key) e2e=\(.e2e_ms)ms dropped=\(.drop_count)/\(.slider_count)"' /tmp/t.ndjson
   ```

4. **Lag-bisection helper** (`scripts/perf-report.py`, future): consumes
   NDJSON and emits a histogram per stage:
   - GTK → WorkerEnqueued     (signal → channel send)
   - WorkerEnqueued → DdcDispatched   (worker queue + coalescing)
   - DdcDispatched → DdcServiceReceived (cross-thread mpsc)
   - DdcServiceReceived → DdcWriteStart (service queue + coalescing)
   - DdcWriteStart → DdcWriteEnd       (I²C)
   - DdcWriteEnd → DdcReadback.matched (monitor firmware)

   This is the artefact maintainers will actually use to point at the
   guilty stage.

---

## 10. Open questions / out of scope

- **Frame-level latency** (when the monitor's photons change) cannot be
  measured from software. Readback is the best proxy.
- The current `DdcService` uses `std::sync::mpsc` (no length introspection).
  `channel_len` on `WorkerEnqueued`/`DdcServiceReceived` requires either
  switching to `crossbeam_channel` (which has `.len()`) or maintaining a
  shadow `AtomicUsize`. Recommendation: shadow counters — minimal risk.
- We deliberately don't log every backlight read or detection-time event;
  perf logging is scoped to *slider-driven write paths* per the issue.
- `gtk` version is queried at init for the Header via `gtk::glib::VersionInfo`
  if available; otherwise `gtk::pango::version_string()` or compile-time
  `gtk4` crate version is acceptable.

---

## 11. Summary of files touched (when implemented)

| File | Lines (approx) | Nature |
|---|---|---|
| `src/perf.rs` *(new)* | ~250 | Recorder, Event enum, public `log()`/`init()` API. |
| `src/lib.rs` or `src/main.rs` | +2 | `pub mod perf;` + `perf::init()` call. |
| `src/cli.rs` | +10 | Global flags. |
| `src/bin/gui.rs` | +15 | Argv/env parse + `perf::init()` before `run()`. |
| `src/gui/window.rs` | ~+15 | `SliderChanged` emit; pass `seq` through executor. |
| `src/gui/debounce.rs` | ~+15 | Channel payload `(i32, u64)`; `WorkerDequeued` emit. |
| `src/display/ddc_ffi.rs` | ~+25 | `parent_seq` in `DdcCommand`; receive/write/readback emits. |
| `src/display/backlight.rs` | ~+8 | Backlight write emits. |
| `tests/perf_logging.rs` *(new)* | ~80 | Coalescing + e2e aggregation test. |
| `Cargo.toml` | +2 | `serde_json` (likely already present), optional `crossbeam-channel`. |

Total new code: ~400 lines. Zero behavioural change when `--perf-log` is absent.
