From 27c14117d9ebaed5369752856b4581ea33e85f62 Mon Sep 17 00:00:00 2001 From: ArthurBernard Date: Tue, 14 Jul 2026 15:36:59 +0200 Subject: [PATCH 1/2] =?UTF-8?q?feat:=20tick-timing=20metrics=20=E2=80=94?= =?UTF-8?q?=20durations,=20scheduler=20semantics,=20health=20fields?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Measure and expose the daemon's tick cadence so the ~74 s-vs-60 s realised shortfall a health audit measured can be proven or refuted with data. - cli/main.py: a `_TickMetrics` closure counter times every `step_all` with a monotonic clock; the leaf-01 heartbeat now carries the duration (`stepped N strategy(ies) in s`) and an interval overrun logs a WARN. The tick job is scheduled with explicit `coalesce=True`, `max_instances=1`, and `misfire_grace_time=` (derived, not hardcoded; 30 s for a cron trigger) — APScheduler's 1 s default grace silently skips a late tick, the presumed source of the shortfall. - supervisor.py: `step` times the unit's evaluation onto `last_step_duration_ms` (survives stop, like the cached accounting report); surfaced on StrategyStatus. - api/app.py: additive-only serialization — `/api/health` gains `last_tick_duration_ms`, `last_tick_ts`, `ticks_total`, `ticks_overrun` (null/0 with no scheduler hook); `/api/strategies` rows gain `last_step_duration_ms`. No existing field changed name, type, or semantics. Real-data scratch run (10 ticks, 60 s): tick 1 = 46.4 s (dccd load + genesis rebalance), steady-state ticks ~1.9-2.0 s, zero overruns, clean 60 s cadence — refuting the tick-exceeds-60 s hypothesis and pointing the production shortfall at misfire-grace skips, which the explicit grace now prevents. --- trading_bot/application/supervisor.py | 27 +++ trading_bot/interfaces/api/app.py | 41 +++- trading_bot/interfaces/cli/main.py | 140 ++++++++++- .../tests/application/test_display_ccy.py | 1 + .../tests/application/test_supervisor.py | 24 ++ .../tests/interfaces/test_cli_commands.py | 225 ++++++++++++++++++ .../tests/interfaces/test_control_api.py | 9 +- .../tests/interfaces/test_dashboard.py | 60 ++++- 8 files changed, 501 insertions(+), 26 deletions(-) diff --git a/trading_bot/application/supervisor.py b/trading_bot/application/supervisor.py index bc59a59..def9101 100644 --- a/trading_bot/application/supervisor.py +++ b/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, diff --git a/trading_bot/interfaces/api/app.py b/trading_bot/interfaces/api/app.py index 8c4775d..394705b 100644 --- a/trading_bot/interfaces/api/app.py +++ b/trading_bot/interfaces/api/app.py @@ -1163,7 +1163,9 @@ def _status_dict(status: StrategyStatus, config: AppConfig) -> dict[str, Any]: ``last_eval_ts`` / ``last_asof_ts`` are already integer epoch ms (or ``None``) on the domain side — no stringification needed, unlike the money - fields. + fields. ``last_step_duration_ms`` (the unit's most-recent step duration in + ms, ``None`` before its first step) is likewise a bare int — an additive + tick-timing field (leaf 03), never displacing a pre-existing one. ``display_currency`` (resolved for the unit's ``exchange``) + ``total_value_display`` / ``unrealised_display`` (converted from the @@ -1186,6 +1188,7 @@ def _status_dict(status: StrategyStatus, config: AppConfig) -> dict[str, Any]: "open_orders": status.open_orders, "last_eval_ts": status.last_eval_ts, "last_asof_ts": status.last_asof_ts, + "last_step_duration_ms": status.last_step_duration_ms, "allocation": _money_str(status.allocation), "contributed": _money_str(status.contributed), "unrealised": _money_str(status.unrealised), @@ -1738,12 +1741,15 @@ def create_dashboard_app( written. Typically ``lambda: supervisor.manifest().to_yaml(path)``. schedule_info : Callable[[], dict] or None, optional A hook returning ``{"next_tick_ts": , "tick": }`` — the daemon's scheduler cadence, surfaced on ``/api/health``. + or None>, "last_tick_duration_ms": , "last_tick_ts": , "ticks_total": , "ticks_overrun": }`` — the daemon's + scheduler cadence + tick-timing metrics, surfaced on ``/api/health``. Keeps this app **scheduler-agnostic**: only the daemon (``_run_daemon``) has an ``apscheduler`` job to report, so it injects this hook; the plain - ``dashboard`` command (no scheduler) passes ``None`` and both fields stay - ``null``. The hook is called under a ``try``/``except`` — a raising or - absent hook degrades to ``null``/``null``, never breaking health. + ``dashboard`` command (no scheduler) passes ``None`` and the cadence + fields stay ``null``/``0``. The hook is called under a ``try``/``except`` + — a raising or absent hook degrades to those same defaults, never + breaking health. Returns ------- @@ -1849,7 +1855,10 @@ async def health(request: Request) -> dict[str, Any]: from the ``schedule_info`` hook when one was injected (the daemon's cadence); both stay ``null`` with no hook, and a hook that raises degrades to ``null``/``null`` too — health must never 500 because the - scheduler hiccuped. + scheduler hiccuped. The same hook feeds the additive tick-timing fields + ``last_tick_duration_ms`` / ``last_tick_ts`` (``null`` before the first + tick / no hook) and ``ticks_total`` / ``ticks_overrun`` (``0`` before the + first tick / no hook) — the realised-vs-nominal cadence, in numbers. ``worst`` is the worst per-unit :attr:`~trading_bot.application. supervisor.StrategyStatus.health` among **running** units @@ -1861,15 +1870,31 @@ async def health(request: Request) -> dict[str, Any]: sup = _sup(request) next_tick_ts: int | None = None tick: str | None = None + # Additive tick-timing fields (leaf 03), fed by the same daemon hook: the + # last tick's duration + wall-clock, and the running / overrun tick counts. + # `None`/`0` with no hook (the scheduler-agnostic `dashboard` command) or a + # hook that raises — health degrades, never 500s. + last_tick_duration_ms: int | None = None + last_tick_ts: int | None = None + ticks_total = 0 + ticks_overrun = 0 hook = request.app.state.schedule_info if hook is not None: try: info = hook() or {} next_tick_ts = info.get("next_tick_ts") tick = info.get("tick") + last_tick_duration_ms = info.get("last_tick_duration_ms") + last_tick_ts = info.get("last_tick_ts") + ticks_total = info.get("ticks_total", 0) + ticks_overrun = info.get("ticks_overrun", 0) except Exception: # noqa: BLE001 - health must degrade, never 500 next_tick_ts = None tick = None + last_tick_duration_ms = None + last_tick_ts = None + ticks_total = 0 + ticks_overrun = 0 statuses = sup.status() worst = _worst_health(s.health for s in statuses if s.running) unhealthy = sum(1 for s in statuses if s.health != "ok") @@ -1880,6 +1905,10 @@ async def health(request: Request) -> dict[str, Any]: "read_only": request.app.state.read_only, "next_tick_ts": next_tick_ts, "tick": tick, + "last_tick_duration_ms": last_tick_duration_ms, + "last_tick_ts": last_tick_ts, + "ticks_total": ticks_total, + "ticks_overrun": ticks_overrun, "worst": worst, "unhealthy": unhealthy, } diff --git a/trading_bot/interfaces/cli/main.py b/trading_bot/interfaces/cli/main.py index 48a8e18..3c88793 100644 --- a/trading_bot/interfaces/cli/main.py +++ b/trading_bot/interfaces/cli/main.py @@ -54,6 +54,7 @@ import signal import sys import tempfile +import time from collections.abc import Callable from decimal import Decimal from typing import TYPE_CHECKING, Any @@ -1217,6 +1218,69 @@ def serve( # --- start (daemon) -------------------------------------------------------- # +@dataclasses.dataclass +class _TickMetrics: + """The daemon's rolling per-tick timing counters (``_run_daemon`` closure state). + + Owned by the daemon (not the served app): the plain ``dashboard`` command has + no scheduler and so no metrics, exactly like ``next_tick_ts``. A single + instance lives in :func:`_run_daemon`; each ``_tick`` folds its measured + duration in via :meth:`record`, and :func:`_run_daemon`'s ``_schedule_info`` + hook reads the fields out onto ``/api/health``. + + Attributes + ---------- + last_tick_duration_ms : int or None + Wall-clock duration (ms) of the most recent tick's ``step_all``. ``None`` + before the first tick. + last_tick_ts : int or None + Epoch-ms wall-clock time the most recent tick finished. ``None`` before + the first tick. + ticks_total : int + How many ticks have run since the daemon started (a tick that raised in + ``step_all`` still counts — it did fire). ``0`` before the first tick. + ticks_overrun : int + How many of those ticks ran **longer than the configured interval** + (never incremented for a cron trigger, where an interval overrun is not + defined). ``0`` before the first tick / when no tick has overrun. + """ + + last_tick_duration_ms: int | None = None + last_tick_ts: int | None = None + ticks_total: int = 0 + ticks_overrun: int = 0 + + def record( + self, *, duration_ms: int, now_ms: int, interval_seconds: float | None + ) -> bool: + """Fold one completed tick's timing in; return whether it overran the interval. + + Parameters + ---------- + duration_ms : int + The tick's measured wall-clock duration in milliseconds. + now_ms : int + Epoch-ms wall-clock time the tick finished. + interval_seconds : float or None + The configured interval in seconds; ``None`` for a cron trigger, where + an "overrun" against a fixed interval is undefined — the duration and + counters are still recorded, but ``ticks_overrun`` never increments. + + Returns + ------- + bool + ``True`` when the tick overran (``duration_ms`` exceeds + ``interval_seconds``), else ``False``. + """ + self.last_tick_duration_ms = duration_ms + self.last_tick_ts = now_ms + self.ticks_total += 1 + overran = interval_seconds is not None and duration_ms > interval_seconds * 1000 + if overran: + self.ticks_overrun += 1 + return overran + + async def _run_daemon( config: AppConfig, *, @@ -1280,15 +1344,48 @@ async def _run_daemon( supervisor = StrategySupervisor(config, dccd_client=dccd_client) # type: ignore[arg-type] await supervisor.start_all() + # The tick-timing counters (health signal, exposed on `/api/health` via the + # `_schedule_info` hook below). An interval trigger has a well-defined overrun + # threshold (the interval); a cron trigger does not, so its overrun check is + # disabled (`interval_seconds = None`) while duration/counters still record. + metrics = _TickMetrics() + interval_seconds: float | None = None if cron is not None else interval + async def _tick() -> None: + started = time.monotonic() + stepped = 0 try: stepped = await supervisor.step_all() - if stepped: - # Daemon-only noise: to the log file, not the console. - _daemon_logger.info("daemon tick: stepped %d strategy(ies)", stepped) except Exception as exc: # noqa: BLE001 - never let a tick kill the daemon # `exception` captures the traceback into the file (invisible before). _daemon_logger.exception("daemon tick error: %s", exc) + # Measure every tick — even one that raised (the duration is a health + # signal, not a success signal); the errored tick still counts as a tick. + duration_ms = int((time.monotonic() - started) * 1000) + overran = metrics.record( + duration_ms=duration_ms, + now_ms=int(time.time() * 1000), + interval_seconds=interval_seconds, + ) + duration_s = duration_ms / 1000 + if stepped: + # Daemon-only noise: to the log file, not the console. The leaf-01 + # heartbeat now carries the tick's duration. + _daemon_logger.info( + "daemon tick: stepped %d strategy(ies) in %.3fs", stepped, duration_s + ) + if overran: + # An interval tick that outran its interval: the next tick would have + # queued behind it — `max_instances=1` + `coalesce=True` collapse the + # backlog into one run, but the operator should know the cadence is + # slipping (the 74 s-vs-60 s health question this leaf answers). + _daemon_logger.warning( + "daemon tick overrun: %.3fs > %gs " + "(evaluation outran the tick interval; the backlog coalesces " + "under max_instances=1)", + duration_s, + interval_seconds, + ) trigger = ( CronTrigger.from_crontab(cron) @@ -1296,7 +1393,26 @@ async def _tick() -> None: else IntervalTrigger(seconds=interval) ) scheduler = AsyncIOScheduler() - job = scheduler.add_job(_tick, trigger) + # Pin the tick's overlap/misfire semantics explicitly (previously all + # APScheduler defaults): + # max_instances=1 — two ticks must never race one engine; + # coalesce=True — a backlog of missed runs collapses into a single run; + # misfire_grace_time — how late a tick may still run. APScheduler's default + # grace is 1 s, so a tick even ~1 s late is silently + # *skipped* (the presumed source of the ~74 s-vs-60 s + # shortfall a health audit measured); grant the whole + # interval instead so a late tick still runs. A cron + # trigger has no fixed interval to derive a grace from, + # so use a fixed, sensible 30 s. APScheduler requires a + # positive int, so floor the interval at 1 s. + misfire_grace_time = 30 if cron is not None else max(1, int(interval)) + job = scheduler.add_job( + _tick, + trigger, + coalesce=True, + max_instances=1, + misfire_grace_time=misfire_grace_time, + ) scheduler.start() _tick_desc = cron or f"every {interval:g}s" _daemon_logger.info( @@ -1312,17 +1428,27 @@ async def _tick() -> None: ) def _schedule_info() -> dict[str, Any]: - """The scheduler's cadence, for the dashboard's ``/api/health`` hook. + """The scheduler's cadence + tick-timing metrics, for the ``/api/health`` hook. ``next_run_time`` is a tz-aware ``datetime`` (or ``None`` between ticks / once exhausted); converted to epoch **ms** for JSON. ``tick`` is the same - human trigger description the startup banner above prints. + human trigger description the startup banner above prints. The four + ``*_tick_*`` / ``ticks_*`` keys are the live :class:`_TickMetrics` counters + (``None``/``0`` before the first tick) — additive fields on + ``/api/health`` proving the realised cadence against the nominal one. """ next_run = job.next_run_time next_tick_ts = ( int(next_run.timestamp() * 1000) if next_run is not None else None ) - return {"next_tick_ts": next_tick_ts, "tick": cron or f"every {interval:g}s"} + return { + "next_tick_ts": next_tick_ts, + "tick": cron or f"every {interval:g}s", + "last_tick_duration_ms": metrics.last_tick_duration_ms, + "last_tick_ts": metrics.last_tick_ts, + "ticks_total": metrics.ticks_total, + "ticks_overrun": metrics.ticks_overrun, + } try: if serve: diff --git a/trading_bot/tests/application/test_display_ccy.py b/trading_bot/tests/application/test_display_ccy.py index 88af182..6373c58 100644 --- a/trading_bot/tests/application/test_display_ccy.py +++ b/trading_bot/tests/application/test_display_ccy.py @@ -384,6 +384,7 @@ def test_api_strategies_display_fields_and_contract_regression() -> None: "open_orders", "last_eval_ts", "last_asof_ts", + "last_step_duration_ms", "allocation", "contributed", "unrealised", diff --git a/trading_bot/tests/application/test_supervisor.py b/trading_bot/tests/application/test_supervisor.py index 9e5420b..8938ee8 100644 --- a/trading_bot/tests/application/test_supervisor.py +++ b/trading_bot/tests/application/test_supervisor.py @@ -133,6 +133,30 @@ async def test_start_step_stop_lifecycle() -> None: assert await sup.step("btc-ma") is None +async def test_step_records_last_step_duration_ms() -> None: + """`step` times the unit's evaluation onto its status (`None` before any step). + + Leaf 03 tick-timing: the per-unit step duration is `None` on a fresh / + never-stepped unit, and after one `step` the status carries a non-negative + int (milliseconds). It survives `stop` (like the cached accounting report), + so a stopped unit still reports the last duration it measured. + """ + pytest.importorskip("fynance") # ma_crossover evaluates fynance.sma + sup = _supervisor() + + # Never stepped -> None. + assert sup.status("btc-ma")[0].last_step_duration_ms is None + + await sup.start("btc-ma") + await sup.step("btc-ma") + duration = sup.status("btc-ma")[0].last_step_duration_ms + assert isinstance(duration, int) and duration >= 0 + + # Survives stop (the measured duration is retained, like `accounting`). + await sup.stop("btc-ma") + assert sup.status("btc-ma")[0].last_step_duration_ms == duration + + async def test_set_mode_paper_testnet_roundtrip() -> None: """paper ↔ testnet switch needs no confirmation and updates the unit's mode.""" sup = _supervisor() diff --git a/trading_bot/tests/interfaces/test_cli_commands.py b/trading_bot/tests/interfaces/test_cli_commands.py index 6d3b7d9..46481fb 100644 --- a/trading_bot/tests/interfaces/test_cli_commands.py +++ b/trading_bot/tests/interfaces/test_cli_commands.py @@ -842,3 +842,228 @@ async def _step_all_signalling(self: StrategySupervisor) -> int: task.cancel() with contextlib.suppress(asyncio.CancelledError): await task + + +# --- tick-timing metrics (leaf 03) ----------------------------------------- # + + +def test_tick_metrics_record_counts_durations_and_overruns() -> None: + """`_TickMetrics.record` folds durations in, counts ticks, flags interval overruns. + + All fields start `None`/`0`; each `record` stamps the last duration/wall-clock + and bumps `ticks_total`; a duration over the interval flags an overrun and + bumps `ticks_overrun`, returning `True` (a fast tick returns `False`). + """ + from trading_bot.interfaces.cli.main import _TickMetrics + + m = _TickMetrics() + # None / 0 before any tick. + assert m.last_tick_duration_ms is None + assert m.last_tick_ts is None + assert m.ticks_total == 0 + assert m.ticks_overrun == 0 + + # A fast tick under the 60 s interval: recorded, not an overrun. + assert m.record(duration_ms=2_000, now_ms=1_000, interval_seconds=60.0) is False + assert m.last_tick_duration_ms == 2_000 + assert m.last_tick_ts == 1_000 + assert m.ticks_total == 1 + assert m.ticks_overrun == 0 + + # A second, slow tick over the interval: recorded, flagged, counted. + assert m.record(duration_ms=61_000, now_ms=2_000, interval_seconds=60.0) is True + assert m.last_tick_duration_ms == 61_000 + assert m.last_tick_ts == 2_000 + assert m.ticks_total == 2 # after two ticks + assert m.ticks_overrun == 1 + + +def test_tick_metrics_record_cron_trigger_never_overruns() -> None: + """A cron trigger (``interval_seconds=None``) records but never flags an overrun. + + An "overrun" against a fixed interval is undefined for a cron schedule, so + the duration + counters still advance while `ticks_overrun` stays `0`. + """ + from trading_bot.interfaces.cli.main import _TickMetrics + + m = _TickMetrics() + assert m.record(duration_ms=10_000_000, now_ms=5, interval_seconds=None) is False + assert m.last_tick_duration_ms == 10_000_000 + assert m.ticks_total == 1 + assert m.ticks_overrun == 0 + + +async def test_daemon_add_job_pins_scheduler_semantics( + monkeypatch: pytest.MonkeyPatch, tmp_path: pathlib.Path +) -> None: + """`_run_daemon` schedules the tick with explicit coalesce / max_instances / grace. + + Spies on `AsyncIOScheduler.add_job` to prove the daemon pins the semantics the + leaf requires: `coalesce=True`, `max_instances=1`, and a `misfire_grace_time` + equal to the configured interval (so a late tick still runs instead of being + silently skipped by APScheduler's 1 s default grace). + """ + import asyncio + import contextlib + + import apscheduler.schedulers.asyncio as aio_sched + + from trading_bot.application.config import AppConfig + from trading_bot.interfaces.cli.main import _run_daemon + + captured: dict[str, object] = {} + called = asyncio.Event() + original_add_job = aio_sched.AsyncIOScheduler.add_job + + def _spy_add_job(self, func, trigger=None, *args, **kwargs): # type: ignore[no-untyped-def] + captured["kwargs"] = dict(kwargs) + job = original_add_job(self, func, trigger, *args, **kwargs) + called.set() + return job + + monkeypatch.setattr(aio_sched.AsyncIOScheduler, "add_job", _spy_add_job) + + cfg = AppConfig.model_validate({"logging": {"dir": str(tmp_path / "logs")}}) + task = asyncio.create_task(_run_daemon(cfg, interval=60.0, cron=None)) + try: + await asyncio.wait_for(called.wait(), timeout=5.0) + finally: + task.cancel() + with contextlib.suppress(asyncio.CancelledError): + await task + + kwargs = captured["kwargs"] + assert kwargs["coalesce"] is True + assert kwargs["max_instances"] == 1 + # Derived from the interval (a positive int), so `== 60` and `== the interval`. + assert kwargs["misfire_grace_time"] == 60 + assert kwargs["misfire_grace_time"] == int(60.0) + + +async def test_daemon_tick_heartbeat_carries_duration_and_counts( + monkeypatch: pytest.MonkeyPatch, + caplog: pytest.LogCaptureFixture, + tmp_path: pathlib.Path, +) -> None: + """Each daemon tick logs its duration in the heartbeat and advances the counters. + + Drives the real daemon over a fake `step_all` (reports two strategies stepped + so the heartbeat fires); captures the daemon's own `_TickMetrics` instance to + prove its rolling counters advance with the ticks, and reads the heartbeat log + line to prove it now carries `in s` (the leaf-01 line + leaf-03 + duration). + """ + import asyncio + import contextlib + import logging + import re + + from trading_bot.application.config import AppConfig + from trading_bot.application.supervisor import StrategySupervisor + from trading_bot.interfaces.cli.main import _run_daemon + + created: list[cli_main._TickMetrics] = [] + real_cls = cli_main._TickMetrics + + def _capturing_factory() -> cli_main._TickMetrics: + instance = real_cls() + created.append(instance) + return instance + + monkeypatch.setattr(cli_main, "_TickMetrics", _capturing_factory) + + async def _fake_step_all(self: StrategySupervisor) -> int: + return 2 # pretend two strategies stepped -> the heartbeat logs + + monkeypatch.setattr(StrategySupervisor, "step_all", _fake_step_all) + + def _heartbeats() -> list[str]: + return [ + r.getMessage() + for r in caplog.records + if "daemon tick: stepped" in r.getMessage() + ] + + caplog.set_level(logging.INFO, logger="trading_bot.daemon") + cfg = AppConfig.model_validate({"logging": {"dir": str(tmp_path / "logs")}}) + task = asyncio.create_task(_run_daemon(cfg, interval=0.01, cron=None)) + try: + # Bounded poll for two ticks' worth of heartbeats (no fixed sleep race). + for _ in range(500): + if len(_heartbeats()) >= 2: + break + await asyncio.sleep(0.01) + heartbeats = _heartbeats() + finally: + task.cancel() + with contextlib.suppress(asyncio.CancelledError): + await task + + assert len(heartbeats) >= 2 + # The heartbeat carries the tick's measured duration: `in s`. + assert re.search( + r"daemon tick: stepped 2 strategy\(ies\) in \d+\.\d{3}s", heartbeats[0] + ) + # The daemon's own rolling counters advanced with the ticks. + assert created[0].ticks_total >= 2 + assert isinstance(created[0].last_tick_duration_ms, int) + assert created[0].last_tick_duration_ms >= 0 + + +async def test_daemon_tick_overrun_warns_and_counts( + monkeypatch: pytest.MonkeyPatch, + caplog: pytest.LogCaptureFixture, + tmp_path: pathlib.Path, +) -> None: + """A tick slower than the interval increments `ticks_overrun` and logs a WARN. + + A stubbed `step_all` that sleeps longer than the (tiny) interval forces an + overrun: the daemon's `ticks_overrun` counter advances and it emits the + `daemon tick overrun: s > s` WARNING. + """ + import asyncio + import contextlib + import logging + import re + + from trading_bot.application.config import AppConfig + from trading_bot.application.supervisor import StrategySupervisor + from trading_bot.interfaces.cli.main import _run_daemon + + created: list[cli_main._TickMetrics] = [] + real_cls = cli_main._TickMetrics + + def _capturing_factory() -> cli_main._TickMetrics: + instance = real_cls() + created.append(instance) + return instance + + monkeypatch.setattr(cli_main, "_TickMetrics", _capturing_factory) + + async def _slow_step_all(self: StrategySupervisor) -> int: + await asyncio.sleep(0.03) # > the 0.01 s interval -> overrun + return 1 + + monkeypatch.setattr(StrategySupervisor, "step_all", _slow_step_all) + + caplog.set_level(logging.INFO, logger="trading_bot.daemon") + cfg = AppConfig.model_validate({"logging": {"dir": str(tmp_path / "logs")}}) + task = asyncio.create_task(_run_daemon(cfg, interval=0.01, cron=None)) + try: + for _ in range(500): + if created and created[0].ticks_overrun >= 1: + break + await asyncio.sleep(0.01) + finally: + task.cancel() + with contextlib.suppress(asyncio.CancelledError): + await task + + assert created[0].ticks_overrun >= 1 + warns = [ + r.getMessage() + for r in caplog.records + if "daemon tick overrun" in r.getMessage() + ] + assert warns + assert re.search(r"daemon tick overrun: \d+\.\d{3}s > 0\.01s", warns[0]) diff --git a/trading_bot/tests/interfaces/test_control_api.py b/trading_bot/tests/interfaces/test_control_api.py index c22b3b9..7fc98ed 100644 --- a/trading_bot/tests/interfaces/test_control_api.py +++ b/trading_bot/tests/interfaces/test_control_api.py @@ -162,8 +162,9 @@ def test_control_wrapper_detail_page_has_the_control_surface() -> None: def test_control_wrapper_health_is_the_dashboard_shape() -> None: """The wrapper's `/api/health` is the unified dashboard's shape (mode + read_only). - `create_control_app` wires no `schedule_info` hook, so the cadence fields stay - `null` — same scheduler-agnostic default as the plain `dashboard` command. + `create_control_app` wires no `schedule_info` hook, so the cadence + tick-timing + fields stay `null`/`0` — same scheduler-agnostic default as the plain + `dashboard` command. """ body = _client().get("/api/health").json() assert body == { @@ -173,6 +174,10 @@ def test_control_wrapper_health_is_the_dashboard_shape() -> None: "read_only": False, "next_tick_ts": None, "tick": None, + "last_tick_duration_ms": None, + "last_tick_ts": None, + "ticks_total": 0, + "ticks_overrun": 0, "worst": "ok", "unhealthy": 0, } diff --git a/trading_bot/tests/interfaces/test_dashboard.py b/trading_bot/tests/interfaces/test_dashboard.py index 4bf6c6c..b3df241 100644 --- a/trading_bot/tests/interfaces/test_dashboard.py +++ b/trading_bot/tests/interfaces/test_dashboard.py @@ -238,10 +238,11 @@ def test_active_tab_is_highlighted() -> None: def test_health_shape_and_values() -> None: - """`GET /api/health` returns the health shape; `next_tick_ts`/`tick` null by default. + """`GET /api/health` returns the health shape; cadence fields null/0 by default. With no `schedule_info` hook (the plain `dashboard` command has no scheduler), - the cadence fields stay `null` — a scheduler-agnostic health payload. + the cadence + tick-timing fields stay `null`/`0` — a scheduler-agnostic + health payload. """ resp = _client().get("/api/health") assert resp.status_code == 200 @@ -253,20 +254,35 @@ def test_health_shape_and_values() -> None: "read_only": False, "next_tick_ts": None, "tick": None, + "last_tick_duration_ms": None, + "last_tick_ts": None, + "ticks_total": 0, + "ticks_overrun": 0, "worst": "ok", "unhealthy": 0, } def test_health_schedule_info_hook_surfaces_cadence() -> None: - """A `schedule_info` hook's `next_tick_ts` / `tick` surface on `/api/health`.""" + """A `schedule_info` hook's cadence + tick-timing fields surface on `/api/health`.""" app = create_dashboard_app( _supervisor(), - schedule_info=lambda: {"next_tick_ts": 1_700_000_000_000, "tick": "every 60s"}, + schedule_info=lambda: { + "next_tick_ts": 1_700_000_000_000, + "tick": "every 60s", + "last_tick_duration_ms": 2100, + "last_tick_ts": 1_699_999_940_000, + "ticks_total": 42, + "ticks_overrun": 1, + }, ) body = TestClient(app).get("/api/health").json() assert body["next_tick_ts"] == 1_700_000_000_000 assert body["tick"] == "every 60s" + assert body["last_tick_duration_ms"] == 2100 + assert body["last_tick_ts"] == 1_699_999_940_000 + assert body["ticks_total"] == 42 + assert body["ticks_overrun"] == 1 def test_health_schedule_info_hook_that_raises_degrades_to_nulls() -> None: @@ -281,6 +297,11 @@ def _boom() -> dict[str, object]: body = resp.json() assert body["next_tick_ts"] is None assert body["tick"] is None + # The tick-timing fields degrade to their no-hook defaults too, never 500. + assert body["last_tick_duration_ms"] is None + assert body["last_tick_ts"] is None + assert body["ticks_total"] == 0 + assert body["ticks_overrun"] == 0 async def test_api_health_worst_and_count() -> None: @@ -336,6 +357,11 @@ async def test_api_health_worst_and_count() -> None: assert body["read_only"] is False assert body["next_tick_ts"] is None assert body["tick"] is None + # Tick-timing fields: no scheduler hook here → null/0 defaults, unchanged. + assert body["last_tick_duration_ms"] is None + assert body["last_tick_ts"] is None + assert body["ticks_total"] == 0 + assert body["ticks_overrun"] == 0 # Both units running: worst is the warn one; one unhealthy unit. assert body["worst"] == "warn" assert body["unhealthy"] == 1 @@ -1311,6 +1337,7 @@ async def test_api_completeness_contract_sweep(tmp_path) -> None: # noqa: ANN00 "open_orders", "last_eval_ts", "last_asof_ts", + "last_step_duration_ms", "allocation", "contributed", "unrealised", @@ -1405,6 +1432,10 @@ async def test_api_completeness_contract_sweep(tmp_path) -> None: # noqa: ANN00 "read_only", "next_tick_ts", "tick", + "last_tick_duration_ms", + "last_tick_ts", + "ticks_total", + "ticks_overrun", "worst", "unhealthy", } @@ -2048,22 +2079,25 @@ def test_api_strategies_carries_health() -> None: async def test_strategies_endpoint_last_eval_and_asof_ts() -> None: - """`GET /api/strategies` carries `last_eval_ts`/`last_asof_ts`, set after a tick. + """`GET /api/strategies` carries eval/asof/step-duration fields, set after a tick. - Both are `None` before the unit has ever ticked via its `*_latest` path - (incl. a never-started unit — PR #168's diagnostic fields). Driving one - tick through the supervisor's `step_all` (the daemon's own path) stamps - both: `last_eval_ts` is the wall-clock of the attempt, `last_asof_ts` the - as-of of the data actually evaluated. + `last_eval_ts` / `last_asof_ts` / `last_step_duration_ms` are all `None` + before the unit has ever ticked via its `*_latest` path (incl. a + never-started unit — PR #168's diagnostic fields + leaf 03's step duration). + Driving one tick through the supervisor's `step_all` (the daemon's own path) + stamps them: `last_eval_ts` is the wall-clock of the attempt, `last_asof_ts` + the as-of of the data actually evaluated, `last_step_duration_ms` how long + the evaluation took (a non-negative int). """ pytest.importorskip("fynance") # ma_crossover evaluates fynance.sma sup = StrategySupervisor(_config(), dccd_client=_FakeStartClient()) client = TestClient(create_dashboard_app(sup)) - # Never started/ticked -> both null. + # Never started/ticked -> all null. [before] = client.get("/api/strategies").json() assert before["last_eval_ts"] is None assert before["last_asof_ts"] is None + assert before["last_step_duration_ms"] is None await sup.start("btc-ma") assert await sup.step_all() == 1 # the one running unit stepped once @@ -2071,6 +2105,10 @@ async def test_strategies_endpoint_last_eval_and_asof_ts() -> None: [after] = client.get("/api/strategies").json() assert isinstance(after["last_eval_ts"], int) and after["last_eval_ts"] > 0 assert isinstance(after["last_asof_ts"], int) and after["last_asof_ts"] > 0 + assert ( + isinstance(after["last_step_duration_ms"], int) + and after["last_step_duration_ms"] >= 0 + ) def test_set_mode_testnet_then_paper() -> None: From bc1381dec3dbd25161a032963a84f8be6c8c5350 Mon Sep 17 00:00:00 2001 From: ArthurBernard Date: Tue, 14 Jul 2026 15:40:06 +0200 Subject: [PATCH 2/2] =?UTF-8?q?feat:=20tick=20timing=20closeout=20?= =?UTF-8?q?=E2=80=94=20changelog,=20ADR,=20status,=20roadmap=20line=20remo?= =?UTF-8?q?ved,=20plan=20archived?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- CHANGELOG.md | 10 ++ doc/dev/03-decisions.md | 21 ++++ doc/dev/06-status.md | 17 ++- doc/dev/07-roadmap.md | 2 - doc/dev/plans/daemon-logging/00-plan.md | 90 -------------- .../daemon-logging/03-tick-timing-metrics.md | 117 ------------------ 6 files changed, 42 insertions(+), 215 deletions(-) delete mode 100644 doc/dev/plans/daemon-logging/00-plan.md delete mode 100644 doc/dev/plans/daemon-logging/03-tick-timing-metrics.md diff --git a/CHANGELOG.md b/CHANGELOG.md index 389fd40..8ef5cc7 100644 --- a/CHANGELOG.md +++ b/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`, 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 diff --git a/doc/dev/03-decisions.md b/doc/dev/03-decisions.md index 13c78ac..8b017d3 100644 --- a/doc/dev/03-decisions.md +++ b/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`, 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 diff --git a/doc/dev/06-status.md b/doc/dev/06-status.md index 813698a..5468618 100644 --- a/doc/dev/06-status.md +++ b/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 diff --git a/doc/dev/07-roadmap.md b/doc/dev/07-roadmap.md index ad9e80b..23eaefe 100644 --- a/doc/dev/07-roadmap.md +++ b/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 diff --git a/doc/dev/plans/daemon-logging/00-plan.md b/doc/dev/plans/daemon-logging/00-plan.md deleted file mode 100644 index 3c66bc9..0000000 --- a/doc/dev/plans/daemon-logging/00-plan.md +++ /dev/null @@ -1,90 +0,0 @@ ---- -plan: daemon-logging -kind: global -status: executing -roadmap: "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/`." -release_on_done: true ---- - -# daemon-logging — structured, timestamped, rotated daemon logs - -## Goal - -Make the daemon **auditable from its log alone**. The 2026-07-14 health audit -had to reconstruct everything from the API and the SQLite books because -`logs/daemon.log` is a bare shell redirect of untimestamped rich-console -prints: no per-line timestamps, no per-strategy-unit lines, no order/skip -trail, no rotation, and 10 process incarnations interleaved in one file. - -What the audit measured (the evidence this epic answers): - -- The strings `alloc1-binance`, `order`, `submit`, `evaluat` **never appear** - in the log; the only cadence signal is the aggregate - `daemon tick: stepped 2 strategy(ies)` line. -- `PortfolioRunner` already logs the `prepare_leg` decisions — at `DEBUG` - (`portfolio_runner.py:704/715`), with **no handler configured**, so they are - invisible; only `WARNING+` escapes via logging's last-resort stderr handler - (that is how `portfolio_feed`'s corrupted-parquet/lag warnings reached the - redirect file). -- Realised tick cadence over 47 h was **~74 s vs the nominal 60 s** (2304 - ticks where ~2832 were expected) with a single APScheduler misfire line ever - logged; `scheduler.add_job(_tick, trigger)` (`cli/main.py:1287`) sets no - explicit `coalesce` / `misfire_grace_time` / `max_instances`. -- Whether alloc1-kraken's post-genesis silence is dust-skips (expected at - capital 100) or a stall is **not answerable from the log** — after this epic - it is one grep. - -## Decomposition - -1. **01-log-setup** — the logging spine: `LoggingConfig` (level, dir, - retention), `configure_daemon_logging()` with a midnight - `TimedRotatingFileHandler` and ISO-8601 timestamps carrying the numeric tz - offset, daemon lifecycle lines routed through it, tracebacks captured via - `logger.exception`. -2. **02-unit-event-trail** — per-unit INFO story: rebalance summary line, - leg round-up/skip reasons (elevated from invisible DEBUG), fill lines, - supervisor state transitions; pinned anti-spam rule (a no-new-bar tick adds - zero INFO lines). -3. **03-tick-timing-metrics** — per-tick and per-unit durations measured and - logged (WARN on overrun), explicit APScheduler semantics - (`coalesce=True, misfire_grace_time=interval, max_instances=1`), additive - `/api/health` + `/api/strategies` timing fields — proves or refutes the - 74 s-cadence hypothesis. - -## Leaf checklist - -- [x] 01 log-setup — `feat/daemon-log-setup` — medium -- [x] 02 unit-event-trail — `feat/daemon-unit-event-logs` — medium -- [ ] 03 tick-timing-metrics — `feat/tick-timing-metrics` — medium - -## Dependencies - -`01 → 02 → 03`, strictly serial (`parallel: false` everywhere): 02 and 03 -both touch `supervisor.py`, and 03 extends the tick line 01 introduces and the -summary line 02 introduces. - -## Done criteria - -- The audit's unanswerable questions become greps on `logs/daemon.log`: when - did each unit last evaluate / trade / skip and **why** (skip reasons carry - the exact Decimals from `LegDecision.reason`). -- Every line timestamped ISO-8601 **with numeric tz offset** (the audit burned - time on UTC-vs-CEST ambiguity). -- Rotation active: `daemon.log` + dated backups, retention 14 days; one file - no longer accumulates incarnations. -- `/api/health` carries `last_tick_duration_ms` / `ticks_total` / - `ticks_overrun`; `/api/strategies` rows carry `last_step_duration_ms` — all - **additive** (public-contract rule: never change existing fields). -- Verification never touches the live daemon (port 8000) — every leaf verifies - on a **scratch instance** (port 8099, scratch book copies, read-only dccd - store). - -## Release / restart runbook note - -The production daemon keeps running the released version during the epic. At -the post-release restart (maintainer-authorized): stop the daemon, archive the -legacy unrotated file to `logs/archive/daemon-pre-rotation-20260714.log`, and -restart **without** the shell `>> logs/daemon.log` redirect (the file handler -now owns the file; a shell redirect would double-write). That restart is the -moment the old log gets cleaned — not before (the running process holds the -fd). diff --git a/doc/dev/plans/daemon-logging/03-tick-timing-metrics.md b/doc/dev/plans/daemon-logging/03-tick-timing-metrics.md deleted file mode 100644 index 3361213..0000000 --- a/doc/dev/plans/daemon-logging/03-tick-timing-metrics.md +++ /dev/null @@ -1,117 +0,0 @@ ---- -plan: daemon-logging/03-tick-timing-metrics -kind: leaf -status: planned -complexity: medium -depends: [01, 02] -parallel: false -branch: feat/tick-timing-metrics -pr: "" ---- - -# 03 — Tick timing: durations, scheduler semantics, health metrics - -## Goal - -Explain and monitor the tick cadence. The audit measured a realised ~74 s -cadence against the nominal 60 s (2304 ticks in 47 h where ~2832 were -expected) with a single misfire warning ever logged and no explicit scheduler -semantics. After this leaf: every tick's duration is measured and logged -(WARN on overrun), the APScheduler job's misfire behaviour is pinned -explicitly, and the numbers are exposed as **additive** fields on -`/api/health` and `/api/strategies` — proving (or refuting) the -tick-takes-longer-than-60s hypothesis with data. - -## Files to change - -- `trading_bot/interfaces/cli/main.py` — `_tick` timing + counters, explicit - `add_job` semantics, extended scheduler hook dict -- `trading_bot/application/supervisor.py` — per-unit step duration captured - on the unit's runtime status -- `trading_bot/interfaces/api/app.py` — additive serialization of the new - fields (health + strategies rows) -- `trading_bot/tests/` — cli daemon-tick tests, supervisor step tests, API - contract tests (additive assertions) - -## Steps - -1. **Measure total tick** — in `_tick` (`cli/main.py`): wrap the - `supervisor.step_all()` await with `time.monotonic()`; keep in the daemon - closure state: `last_tick_duration_ms: int`, `last_tick_ts: int` (epoch - ms), `ticks_total: int`, `ticks_overrun: int` (duration > interval). - - The leaf-01 heartbeat line gains the duration: - `daemon tick: stepped N strategy(ies) in s`. - - Overrun: `logger.warning("daemon tick overrun: s > s …")`. -2. **Pin scheduler semantics** — `scheduler.add_job(_tick, trigger, - coalesce=True, misfire_grace_time=, max_instances=1)` - (`cli/main.py:1287`): - - `max_instances=1` — two overlapping ticks must never race one engine; - - `coalesce=True` — a backlog of missed runs collapses into one; - - `misfire_grace_time=interval` — a late tick still runs (default grace is - 1 s: a 61-s-late job is silently **skipped** — the presumed source of the - unexplained shortfall). - Derive `` from the configured trigger, not a literal. -3. **Per-unit duration** — in `Supervisor.step` (`supervisor.py:1484`): time - the unit's evaluation, store `last_step_duration_ms` on the unit's runtime - state next to the existing `last_eval_ts`, and append `took=ms` to the - leaf-02 rebalance summary when a rebalance ran. -4. **API exposure (additive only — public contract)**: - - `/api/health`: the scheduler hook (`cli/main.py` injects it; shape - documented at `app.py:1740`) gains `last_tick_duration_ms`, - `last_tick_ts`, `ticks_total`, `ticks_overrun`; `app.py` serializes - whatever extra keys the hook returns (or mirrors them explicitly — - match the existing style). `None`s before the first tick. - - `/api/strategies` rows: `last_step_duration_ms` (`None` before first - eval). - - **No existing field changes name, type, or semantics.** -5. Housekeeping: the counters live in the daemon, not the app — the plain - `dashboard` command (no scheduler) keeps `None`s, exactly like - `next_tick_ts` today. - -## Tests - -- cli daemon tick (existing fake-supervisor harness): after two ticks, - `ticks_total == 2`, `last_tick_duration_ms >= 0`, heartbeat line carries - `in <…>s`; a stubbed slow tick (> interval) increments `ticks_overrun` and - emits the WARN. -- `add_job` called with `coalesce=True`, `max_instances=1`, - `misfire_grace_time == interval` (assert via the scheduler's job object or - a spy). -- Supervisor: after a step, the unit status carries - `last_step_duration_ms >= 0`; unset (`None`) before any step. -- API contract tests: new fields present and `None`-safe; **all existing - fields unchanged** (extend the additive-sweep suite from `api-completeness` - — same pattern as PRs #209–#214). -- Full suite + `ruff check trading_bot/` green. - -## Verification on real data - -Scratch instance (port 8099, scratch books, read-only dccd store — never port -8000): - -1. Run ≥ 10 minutes (≥ 10 ticks on the 60 s trigger). -2. `curl -s -H "Authorization: Bearer " 127.0.0.1:8099/api/health` - → report the real `last_tick_duration_ms`, `ticks_total`, `ticks_overrun` - values; `/api/strategies` → both units' `last_step_duration_ms`. -3. From the scratch log, report the observed tick-duration distribution - (grep the heartbeat lines) — e.g. "27-pair resample takes X–Y s per tick". - State explicitly whether durations approach/exceed 60 s (validating the - shortfall hypothesis) or stay low (pointing at misfire-grace skips instead - — which step 2's `misfire_grace_time` fix addresses either way). -4. Confirm the live daemon untouched. - -## Closeout - -- CHANGELOG `### Added`: "tick timing: durations logged (WARN on overrun), - explicit APScheduler `coalesce`/`misfire_grace_time`/`max_instances`, - additive `/api/health` (`last_tick_duration_ms`, `ticks_total`, - `ticks_overrun`) and `/api/strategies` (`last_step_duration_ms`) fields (#XX)". -- ADR: pinned scheduler semantics + why (silent 1 s default grace skipped - late ticks unlogged); rejected: raising the interval, async-gathering units - (per-unit lock already serializes safely). -- `06-status.md`: cadence now measured; note the audit's 74 s finding as - resolved-or-explained with the first real numbers. -- **Last leaf**: tick 03, set `00-plan.md` `status: done`, remove the `3b.` - roadmap line, move `plans/daemon-logging/` to the archive, suggest - `/release` — and after the release, apply the 00-plan "Release / restart - runbook note" (archive the legacy `daemon.log` at the prod restart).