feat: tick timing — durations, pinned scheduler semantics, health metrics

CHANGELOG.md

@@ -25,6 +25,16 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
   start/stop/step-error transitions logged. Anti-spam pinned: an idle tick
   (no new bar) adds zero per-unit lines — a unit's inactivity is now
   explained by the log. (#227)
+- **Tick timing measured and pinned (closes the `daemon-logging` epic)** —
+  every tick's duration is logged on the heartbeat (`in <s.mmm>s`, WARN on
+  interval overrun) and per-unit step durations captured; the tick job's
+  APScheduler semantics are now explicit (`coalesce=True`, `max_instances=1`,
+  `misfire_grace_time=interval` — the 1 s default grace silently skipped late
+  ticks, the measured source of the audit's ~74 s-vs-60 s cadence shortfall);
+  additive API fields: `/api/health` `last_tick_duration_ms` / `last_tick_ts` /
+  `ticks_total` / `ticks_overrun`, `/api/strategies` `last_step_duration_ms`.
+  Real-data check: steady-state ticks ~2 s, first tick (data load) ~46 s —
+  the duration hypothesis refuted, the misfire one confirmed as the fix. (#228)
 
 ### Changed
 

doc/dev/03-decisions.md

@@ -6,6 +6,27 @@ rejected approaches as tombstones.
 
 ---
 
+### 2026-07-14 Tick scheduler semantics pinned; timing is a health signal (PR #228)  [accepted]
+- **Choice**: the daemon tick job runs with explicit `coalesce=True`,
+  `max_instances=1`, `misfire_grace_time=interval` (cron triggers: fixed
+  30 s); every tick's duration is measured (heartbeat `in <s.mmm>s`, WARN on
+  interval overrun) and exposed additively on `/api/health`
+  (`last_tick_duration_ms`/`last_tick_ts`/`ticks_total`/`ticks_overrun`) and
+  `/api/strategies` (`last_step_duration_ms`). Per-unit duration lives on
+  the API field only, measured in the supervisor's `step` `finally` (counted
+  even when the step raises).
+- **Why**: APScheduler's **1 s default misfire grace silently skips** a tick
+  that fires late — the measured cause of the audit's ~74 s realised cadence
+  vs the 60 s nominal (real-data check: steady-state ticks ~2 s, first tick
+  ~46 s data load — duration never exceeds the interval, so skips, not
+  overruns, explain the shortfall). `max_instances=1` guarantees two ticks
+  never race one engine.
+- **Rejected alternatives**: raising the tick interval (hides the problem);
+  gathering units concurrently inside a tick (the per-unit lock serializes
+  anyway; complexity without cadence benefit); putting per-unit duration on
+  the leaf-02 rebalance line (emitted inside the runner, before the outer
+  step timing exists).
+
 ### 2026-07-14 Unit event trail: runner-attributed lines, bus and log are two sinks (PR #227)  [accepted]
 - **Choice**: order-lifecycle log lines live in the **runner** (per-unit, sees
   the router's outcome and the unit name) — not the shared router; the new

doc/dev/06-status.md

@@ -120,6 +120,17 @@ and `CHANGELOG.md` for what shipped.
 - **E1–E11 + the multi-asset/portfolio unit** shipped; the pre-production safety
   hardening (audit) is wired in (see *Where things stand*). `CHANGELOG.md` + git log are
   authoritative for what shipped per release.
+- **`daemon-logging` (2026-07-14, PRs #226–#228)**: the daemon is auditable
+  from its log alone — rotated, tz-offset-timestamped `logs/daemon.log`
+  (manifest `logging:` section), per-unit rebalance summaries + round-up/skip
+  `LegDecision.reason`s + order/fill lines (a unit's inactivity is now
+  explained by the log), tick durations on the heartbeat + additive
+  `/api/health`//`api/strategies` timing fields. Root-caused the 2026-07-14
+  audit's ~74 s-vs-60 s cadence shortfall: APScheduler's 1 s default misfire
+  grace silently skipped late ticks (steady-state ticks measure ~2 s; first
+  tick ~46 s data load) — the job now runs `coalesce=True`, `max_instances=1`,
+  `misfire_grace_time=interval`. The legacy unrotated log gets archived at the
+  post-release daemon restart.
 - **`paper-integrity` (2026-07-11, PRs #190–#194)**: paper ids unique across
   engine lifetimes, fills reach the tracked order + store row (`OrderFillSync`,
   startup healing), reconcile persists orphan-closes, restart/replay E2E.
@@ -183,12 +194,6 @@ engine code: **real-key live enablement** (validate Kraken private endpoints +
 venue-level idempotency against a real-key sandbox, then flip `live_enabled`) — the one
 maintainer step in [`07-roadmap.md`](07-roadmap.md).
 
-- **`daemon-logging` in flight (2/3)**: the logging spine (rotated,
-  tz-offset-timestamped `logs/daemon.log`, manifest `logging:` section, tick
-  tracebacks) and the per-unit event trail (rebalance summaries, skip
-  reasons, order/fill lines — a unit's inactivity is now explained by the
-  log) have landed. Next: tick-timing metrics (leaf 03). Plan:
-  `plans/daemon-logging/`.
 
 ## Known gaps / deferred
 

doc/dev/07-roadmap.md

@@ -86,8 +86,6 @@ order — none started yet, each is a `/pick-task` candidate:
    risk-limit visibility incl. daily-loss usage); `last_error` on
    `/api/strategies` (a stopped unit is indistinguishable from a crashed one).
 
-3b. [ ] **Daemon observability — structured logs** (surfaced by the 2026-07-14 health audit; prereq for #4's systemd alerting + soak evidence): timestamped rotated `logs/daemon.log`, per-unit evaluation/order/skip trail, tick-duration metrics on `/api/health` (additive). Plan: `plans/daemon-logging/`.
-
 4. [ ] **Ops readiness** (not engine code): daemon under **systemd** (restart
    policy + an alert when the process dies — today it is a `nohup` from a
    terminal session); a **multi-week paper soak** on the real-data books

trading_bot/application/supervisor.py

@@ -167,6 +167,14 @@ class StrategyStatus:
         .last_asof_ms` / :attr:`~trading_bot.application.portfolio_runner
         .PortfolioRunner.last_asof_ms`), i.e. "the data this strategy last
         computed on". ``None`` before the first completed evaluation.
+    last_step_duration_ms : int or None
+        Wall-clock duration (**milliseconds**) of the unit's most recent
+        :meth:`StrategySupervisor.step` — the time its runner spent evaluating
+        one tick (data drain + signal + any routing), measured with a monotonic
+        clock. ``None`` before the unit has ever been stepped. Recorded on every
+        step (even one that raised), so a dashboard can spot a unit whose
+        evaluation is creeping toward the tick interval (the tick-timing health
+        signal — see ``doc/dev/plans/daemon-logging/03-tick-timing-metrics.md``).
     allocation : Money or None
         The unit's **genesis** capital — its declared ``allocation`` (or a
         portfolio's ``allocation``/``capital``). ``None`` for a single-instrument
@@ -218,6 +226,7 @@ class StrategyStatus:
     open_orders: int
     last_eval_ts: int | None = None
     last_asof_ts: int | None = None
+    last_step_duration_ms: int | None = None
     allocation: Money | None = None
     contributed: Money | None = None
     unrealised: Money | None = None
@@ -504,6 +513,12 @@ class _Unit:
     #: are cleared by :meth:`StrategySupervisor._teardown`) so a stopped unit still
     #: reports its last-known state.
     accounting: _AccountingState | None = None
+    #: Wall-clock duration (ms) of this unit's most recent :meth:`StrategySupervisor
+    #: .step` — the time its runner spent on one evaluation. ``None`` before the
+    #: unit has ever been stepped; recorded on every step (incl. one that raised),
+    #: and (like :attr:`accounting`) it survives ``stop`` so a stopped unit still
+    #: reports the last duration it measured.
+    last_step_duration_ms: int | None = None
 
 
 class StrategySupervisor:
@@ -1525,6 +1540,15 @@ async def step(self, name: str) -> Order | object | None:
             if not unit.running or unit.runner is None:
                 return None
             runner = unit.runner
+        # Time the runner's evaluation (data drain + signal + any routing) with a
+        # monotonic clock, and stamp it on the unit's runtime state in a `finally`
+        # so a slow-and-then-raising step is still measured (the duration is a
+        # health signal, not a success signal). Per-unit duration lives ONLY on
+        # this field, not the leaf-02 rebalance-summary line: that line is emitted
+        # from *inside* the runner, before this outer step timing exists, so
+        # threading the total back into it would mean the summary timing itself —
+        # the runner is deliberately not contorted for it (leaf 03, step 3).
+        started = time.monotonic()
         try:
             if isinstance(runner, StrategyRunner):
                 result: Order | object | None = await runner.step_latest()
@@ -1538,6 +1562,8 @@ async def step(self, name: str) -> Order | object | None:
             # never steady-state — this is not an anti-spam concern.
             logger.exception("unit=%s step error", name)
             raise
+        finally:
+            unit.last_step_duration_ms = int((time.monotonic() - started) * 1000)
         if result is None:
             # Evaluated nothing this tick (freshness gate skip / no new bar): a
             # DEBUG line only, so a steady-state INFO log stays free of per-unit
@@ -1626,6 +1652,7 @@ def _status_of(self, unit: _Unit) -> StrategyStatus:
             open_orders=open_orders,
             last_eval_ts=last_eval_ts,
             last_asof_ts=last_asof_ts,
+            last_step_duration_ms=unit.last_step_duration_ms,
             allocation=allocation,
             contributed=contributed,
             unrealised=unrealised,