fix(metrics): time-series rows get time-ordered ids, so an insert stops costing a disk read (#5149)

Measured on dev (385a579), agent posts cut to five samples still dropped:
flush=8.8s for 990 rows, 6.6s for 680, 8.4s for 1000 — about 110 rows/s,
~9 ms a row, with rules and evaluation near zero. One random read per
row fits a random uuid4 primary key whose index no longer fits in memory:
every new row lands on a random page of it. (Inferred from the rate; the
table and index sizes have not been read.)

- steward.core.ids.time_ordered_id: a UUIDv7-layout string (48-bit ms
  timestamp, then random), same 36-char shape as the stored uuid4 ids, so
  no migration. Python's uuid7() arrives in 3.14; the image runs 3.13.
- Used for plugin_metrics and its hourly rollup, monitor_results,
  audit_events, the docker metrics/hourly/events/logs tables, and the
  traefik and unifi time series.
- MAX_SAMPLES_PER_INGEST 5 → 2 (~400 rows) for now: it fits the agent's
  10 s even at the old rate, so hosts land data whichever way the new rate
  comes out. Raise it once the new rate is measured.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

plugins/docker/models.py

@@ -1,6 +1,5 @@
 # plugins/docker/models.py
 from __future__ import annotations
-import uuid
 from datetime import datetime, timezone
 from sqlalchemy import (
     BigInteger, Boolean, DateTime, Float, ForeignKey, Index, Integer, String, Text,
@@ -8,6 +7,7 @@ from sqlalchemy import (
 )
 from sqlalchemy.orm import Mapped, mapped_column
 from steward.models.base import Base
+from steward.core.ids import time_ordered_id
 
 
 class DockerContainer(Base):
@@ -67,7 +67,7 @@ class DockerMetric(Base):
     __tablename__ = "docker_metrics"
 
     id: Mapped[str] = mapped_column(
-        String(36), primary_key=True, default=lambda: str(uuid.uuid4())
+        String(36), primary_key=True, default=time_ordered_id
     )
     host_id: Mapped[str] = mapped_column(
         String(36), ForeignKey("hosts.id", ondelete="CASCADE"), nullable=False, index=True
@@ -103,7 +103,7 @@ class DockerMetricHourly(Base):
     __tablename__ = "docker_metrics_hourly"
 
     id: Mapped[str] = mapped_column(
-        String(36), primary_key=True, default=lambda: str(uuid.uuid4())
+        String(36), primary_key=True, default=time_ordered_id
     )
     host_id: Mapped[str] = mapped_column(
         String(36), ForeignKey("hosts.id", ondelete="CASCADE"), nullable=False
@@ -139,7 +139,7 @@ class DockerEvent(Base):
     __tablename__ = "docker_events"
 
     id: Mapped[str] = mapped_column(
-        String(36), primary_key=True, default=lambda: str(uuid.uuid4())
+        String(36), primary_key=True, default=time_ordered_id
     )
     host_id: Mapped[str] = mapped_column(
         String(36), ForeignKey("hosts.id", ondelete="CASCADE"), nullable=False
@@ -176,7 +176,7 @@ class DockerLog(Base):
     __tablename__ = "docker_logs"
 
     id: Mapped[str] = mapped_column(
-        String(36), primary_key=True, default=lambda: str(uuid.uuid4())
+        String(36), primary_key=True, default=time_ordered_id
     )
     host_id: Mapped[str] = mapped_column(
         String(36), ForeignKey("hosts.id", ondelete="CASCADE"), nullable=False, index=True

plugins/host_agent/agent.py

@@ -17,10 +17,10 @@ import time
 import urllib.error
 import urllib.request
 from collections import deque
-from concurrent.futures import ThreadPoolExecutor
+from concurrent.futures import ThreadPoolExecutor, wait as wait_futures
 from datetime import datetime, timezone
 
-AGENT_VERSION = "1.9.0"
+AGENT_VERSION = "1.10.0"
 
 # Default path to the local Docker Engine socket. Overridable via the
 # `docker_socket` config key; collection is silently skipped if it's absent or
@@ -440,6 +440,13 @@ def _rates(cur: dict, prev: dict, dt: float) -> dict:
 # when that header is present rather than assume Content-Length.
 
 DOCKER_API_TIMEOUT = 5.0
+# All of one sample's per-container Docker work (inspect + stats) must finish
+# inside this; past it the sample says Docker did not answer in time rather
+# than holding up the host's own metrics (#5154).
+DOCKER_DEADLINE_SECONDS = 20.0
+# /system/df walks every image, container and volume: asked this often, not
+# every sample. Steward keeps the last answer between reports.
+DOCKER_DF_INTERVAL_SECONDS = 600.0
 
 # Container-log collection (m79). Logs ride in the same push as metrics, so one
 # interval's batch is capped to keep a chatty container from bloating a POST (and
@@ -718,9 +725,23 @@ def collect_docker(socket_path: str) -> tuple:
     # call blocks ~1s while the daemon computes the cpu delta. Done serially that
     # stretches the whole sample on a busy host, so fan the per-container work out
     # over a small bounded thread pool (I/O-bound → threads are enough).
-    workers = min(8, len(containers))
-    with ThreadPoolExecutor(max_workers=workers) as ex:
-        return "ok", None, list(ex.map(lambda c: _collect_one_container(socket_path, c), containers))
+    # A deadline on the whole fan-out: one wedged container must not stall the
+    # sample. Unfinished work is reported as Docker not answering in time, not
+    # as a partial list: a container left out would read as removed, and one
+    # without its inspect as restarted or changed health.
+    ex = ThreadPoolExecutor(max_workers=min(8, len(containers)))
+    try:
+        futures = [ex.submit(_collect_one_container, socket_path, c) for c in containers]
+        done, pending = wait_futures(futures, timeout=DOCKER_DEADLINE_SECONDS)
+    finally:
+        try:
+            ex.shutdown(wait=False, cancel_futures=True)
+        except TypeError:          # Python < 3.9: no cancel_futures
+            ex.shutdown(wait=False)
+    if pending:
+        return ("error", "%d of %d containers not read within %g s"
+                % (len(pending), len(containers), DOCKER_DEADLINE_SECONDS), [])
+    return "ok", None, [f.result() for f in futures]
 
 
 # ─── container logs (m79) ─────────────────────────────────────────────────────
@@ -1243,7 +1264,8 @@ def build_sample(mounts: list[str], state: dict,
 
     # Image/disk usage — host-level docker fact (one /system/df call), only
     # when Docker answered.
-    if docker_status == "ok":
+    if docker_status == "ok" and now_mono - state.get("df_mono", float("-inf")) >= DOCKER_DF_INTERVAL_SECONDS:
+        state["df_mono"] = now_mono
         try:
             disk = collect_disk_usage(docker_socket)
         except Exception:
@@ -1278,7 +1300,14 @@ def build_payload(samples: list[dict], hostname: str, metadata: dict) -> dict:
 # ─── POST + backoff ──────────────────────────────────────────────────────────
 
 
-BACKOFF_CAP = 300
+# Below Steward's 180 s staleness window (host_agent stale_after_seconds): once
+# Steward is reachable again a host reports within a minute, instead of reading
+# as stale for up to five (#5154; lesson: a check-in inherits its call's backoff).
+BACKOFF_CAP = 60
+# Samples in one POST: the server writes at most this many (routes.py
+# MAX_SAMPLES_PER_INGEST), so a backlog drains a few per post, oldest first,
+# rather than in one post too big to write before the timeout.
+MAX_SAMPLES_PER_POST = 5
 
 
 def _drop_logs(sample: dict) -> dict:
@@ -1293,6 +1322,12 @@ def _drop_logs(sample: dict) -> dict:
     return sample
 
 
+def split_backlog(buffered: list, limit: int = MAX_SAMPLES_PER_POST) -> tuple:
+    """(the buffered samples to send with this one, the ones held for later):
+    the oldest limit-1, leaving room for the new sample."""
+    return buffered[:limit - 1], buffered[limit - 1:]
+
+
 def next_backoff(current: int) -> int:
     if current <= 0:
         return 30
@@ -1385,16 +1420,20 @@ def main_loop(conf_path: str) -> int:
                               docker_logs_enabled=docker_logs_enabled,
                               docker_log_exclude=docker_log_exclude)
         buffered = buffer.drain()
+        send, held = split_backlog(buffered)
         payload = build_payload(
-            samples=buffered + [sample],
+            samples=send + [sample],
             hostname=hostname,
             metadata=metadata,
         )
         ok, status = post_payload(cfg["url"], cfg["token"], payload)
 
         if ok:
-            if buffered:
-                _log("INFO", f"flushed {len(buffered)} buffered samples")
+            for s in held:
+                buffer.push(s)
+            if send:
+                _log("INFO", f"flushed {len(send)} buffered samples"
+                             + (f", {len(held)} still held" if held else ""))
             backoff = 0
             sleep_for = cfg["interval_seconds"]
         else:

plugins/host_agent/routes.py

@@ -343,7 +343,9 @@ SLOW_INGEST_SECONDS = 2.0
 # instance that did not finish inside the agent's 10 s, the rollback left the
 # buffer full, and every later post failed the same way. The newest samples
 # are kept: the older ones would be lost to the agent's ring buffer anyway.
-MAX_SAMPLES_PER_INGEST = 5
+# Two (~400 rows) fits 10 s even at the ~110 rows/s measured before
+# plugin_metrics got time-ordered ids; raise it once the new rate is known.
+MAX_SAMPLES_PER_INGEST = 2
 
 
 def newest_samples(samples: list, limit: int) -> tuple[list, int]:

plugins/traefik/models.py

@@ -1,16 +1,16 @@
 # plugins/traefik/models.py
 from __future__ import annotations
-import uuid
 from datetime import datetime, timezone
 from sqlalchemy import DateTime, Float, Integer, String, Text
 from sqlalchemy.orm import Mapped, mapped_column
 from steward.models.base import Base
+from steward.core.ids import time_ordered_id
 
 
 class TraefikMetric(Base):
     __tablename__ = "traefik_metrics"
 
-    id: Mapped[str] = mapped_column(String(36), primary_key=True, default=lambda: str(uuid.uuid4()))
+    id: Mapped[str] = mapped_column(String(36), primary_key=True, default=time_ordered_id)
     router_name: Mapped[str] = mapped_column(String(255), nullable=False)
     scraped_at: Mapped[datetime] = mapped_column(
         DateTime(timezone=True), nullable=False, default=lambda: datetime.now(timezone.utc)
@@ -41,7 +41,7 @@ class TraefikAccessSummary(Base):
     """Aggregated traffic-origin summary — one row per scheduler tick."""
     __tablename__ = "traefik_access_summaries"
 
-    id: Mapped[str] = mapped_column(String(36), primary_key=True, default=lambda: str(uuid.uuid4()))
+    id: Mapped[str] = mapped_column(String(36), primary_key=True, default=time_ordered_id)
     period_start: Mapped[datetime] = mapped_column(DateTime(timezone=True), nullable=False)
     period_end: Mapped[datetime] = mapped_column(DateTime(timezone=True), nullable=False)
     total_requests: Mapped[int] = mapped_column(Integer, nullable=False, default=0)
@@ -57,7 +57,7 @@ class TraefikGlobalStat(Base):
     """One row per scrape — process-level and config stats."""
     __tablename__ = "traefik_global_stats"
 
-    id: Mapped[str] = mapped_column(String(36), primary_key=True, default=lambda: str(uuid.uuid4()))
+    id: Mapped[str] = mapped_column(String(36), primary_key=True, default=time_ordered_id)
     scraped_at: Mapped[datetime] = mapped_column(
         DateTime(timezone=True), nullable=False, default=lambda: datetime.now(timezone.utc)
     )

plugins/unifi/models.py

@@ -1,10 +1,10 @@
 # plugins/unifi/models.py
 from __future__ import annotations
-import uuid
 from datetime import datetime, timezone
 from sqlalchemy import Boolean, DateTime, Float, Integer, String, Text
 from sqlalchemy.orm import Mapped, mapped_column
 from steward.models.base import Base
+from steward.core.ids import time_ordered_id
 
 
 # ── Time-series (one row per scrape) ──────────────────────────────────────────
@@ -13,7 +13,7 @@ class UnifiWanStat(Base):
     """WAN interface health — one row per scrape."""
     __tablename__ = "unifi_wan_stats"
 
-    id: Mapped[str] = mapped_column(String(36), primary_key=True, default=lambda: str(uuid.uuid4()))
+    id: Mapped[str] = mapped_column(String(36), primary_key=True, default=time_ordered_id)
     scraped_at: Mapped[datetime] = mapped_column(DateTime(timezone=True), nullable=False, default=lambda: datetime.now(timezone.utc))
     is_up: Mapped[bool] = mapped_column(Boolean, nullable=False, default=False)
     wan_ip: Mapped[str | None] = mapped_column(String(64), nullable=True)
@@ -27,7 +27,7 @@ class UnifiClientSnapshot(Base):
     """Aggregated client counts + top talkers — one row per scrape."""
     __tablename__ = "unifi_client_snapshots"
 
-    id: Mapped[str] = mapped_column(String(36), primary_key=True, default=lambda: str(uuid.uuid4()))
+    id: Mapped[str] = mapped_column(String(36), primary_key=True, default=time_ordered_id)
     scraped_at: Mapped[datetime] = mapped_column(DateTime(timezone=True), nullable=False, default=lambda: datetime.now(timezone.utc))
     total_clients: Mapped[int] = mapped_column(Integer, nullable=False, default=0)
     wireless_clients: Mapped[int] = mapped_column(Integer, nullable=False, default=0)
@@ -41,7 +41,7 @@ class UnifiWlanStat(Base):
     """Per-SSID/radio stats — one row per scrape per SSID+radio combination."""
     __tablename__ = "unifi_wlan_stats"
 
-    id: Mapped[str] = mapped_column(String(36), primary_key=True, default=lambda: str(uuid.uuid4()))
+    id: Mapped[str] = mapped_column(String(36), primary_key=True, default=time_ordered_id)
     scraped_at: Mapped[datetime] = mapped_column(DateTime(timezone=True), nullable=False, default=lambda: datetime.now(timezone.utc))
     ssid: Mapped[str] = mapped_column(String(255), nullable=False)
     radio: Mapped[str | None] = mapped_column(String(8), nullable=True)    # ng=2.4GHz, na=5GHz, 6e=6GHz
@@ -56,7 +56,7 @@ class UnifiDpiSnapshot(Base):
     """DPI application/category traffic snapshot — one row per scrape (JSON blob)."""
     __tablename__ = "unifi_dpi_snapshots"
 
-    id: Mapped[str] = mapped_column(String(36), primary_key=True, default=lambda: str(uuid.uuid4()))
+    id: Mapped[str] = mapped_column(String(36), primary_key=True, default=time_ordered_id)
     scraped_at: Mapped[datetime] = mapped_column(DateTime(timezone=True), nullable=False, default=lambda: datetime.now(timezone.utc))
     # JSON: [{"cat_id", "cat_name", "rx_bytes", "tx_bytes"}] aggregated across all clients
     by_category_json: Mapped[str] = mapped_column(Text, nullable=False, default="[]")

steward/core/ids.py

@@ -0,0 +1,25 @@
+"""Row ids for tables that grow by time.
+
+A random uuid4 primary key puts every new row on a random page of the key's
+index; once that index outgrows memory, each insert waits for a disk read.
+Measured on the live instance (#5149): plugin_metrics took ~9 ms a row, about
+110 rows/s, so a host agent's post could not finish inside its 10 s timeout.
+A time-ordered id lands every new row at the index's right edge instead.
+"""
+from __future__ import annotations
+
+import os
+import time
+import uuid
+
+
+def time_ordered_id() -> str:
+    """A UUIDv7-layout id (RFC 9562) as a 36-character string: a 48-bit
+    millisecond timestamp, then 74 random bits. Same shape and column type as
+    the uuid4 ids already stored, so no table changes; Python's own uuid7()
+    arrives only in 3.14."""
+    ms = time.time_ns() // 1_000_000
+    value = (ms & 0xFFFF_FFFF_FFFF) << 80 | int.from_bytes(os.urandom(10), "big")
+    value = (value & ~(0xF << 76)) | (0x7 << 76)     # version 7
+    value = (value & ~(0x3 << 62)) | (0x2 << 62)     # RFC 9562 variant
+    return str(uuid.UUID(int=value))

steward/models/audit.py

@@ -1,15 +1,15 @@
 from __future__ import annotations
-import uuid
 from datetime import datetime, timezone
 from sqlalchemy import DateTime, ForeignKey, String, Text
 from sqlalchemy.orm import Mapped, mapped_column
 from .base import Base
+from steward.core.ids import time_ordered_id
 
 
 class AuditEvent(Base):
     __tablename__ = "audit_events"
 
-    id: Mapped[str] = mapped_column(String(36), primary_key=True, default=lambda: str(uuid.uuid4()))
+    id: Mapped[str] = mapped_column(String(36), primary_key=True, default=time_ordered_id)
     timestamp: Mapped[datetime] = mapped_column(
         DateTime(timezone=True), nullable=False, default=lambda: datetime.now(timezone.utc)
     )

steward/models/metrics.py

@@ -1,15 +1,15 @@
 from __future__ import annotations
-import uuid
 from datetime import datetime, timezone
 from sqlalchemy import DateTime, Float, Index, Integer, String, UniqueConstraint
 from sqlalchemy.orm import Mapped, mapped_column
 from .base import Base
+from steward.core.ids import time_ordered_id
 
 
 class PluginMetric(Base):
     __tablename__ = "plugin_metrics"
 
-    id: Mapped[str] = mapped_column(String(36), primary_key=True, default=lambda: str(uuid.uuid4()))
+    id: Mapped[str] = mapped_column(String(36), primary_key=True, default=time_ordered_id)
     source_module: Mapped[str] = mapped_column(String(64), nullable=False)
     resource_name: Mapped[str] = mapped_column(String(255), nullable=False)
     metric_name: Mapped[str] = mapped_column(String(128), nullable=False)
@@ -40,7 +40,7 @@ class PluginMetricHourly(Base):
     """
     __tablename__ = "plugin_metrics_hourly"
 
-    id: Mapped[str] = mapped_column(String(36), primary_key=True, default=lambda: str(uuid.uuid4()))
+    id: Mapped[str] = mapped_column(String(36), primary_key=True, default=time_ordered_id)
     source_module: Mapped[str] = mapped_column(String(64), nullable=False)
     resource_name: Mapped[str] = mapped_column(String(255), nullable=False)
     metric_name: Mapped[str] = mapped_column(String(128), nullable=False)

steward/models/monitors.py

@@ -8,6 +8,7 @@ from sqlalchemy import (
 )
 from sqlalchemy.orm import Mapped, mapped_column
 from .base import Base
+from steward.core.ids import time_ordered_id
 
 
 class MonitorType(str, enum.Enum):
@@ -93,7 +94,7 @@ class MonitorResult(Base):
     __tablename__ = "monitor_results"
 
     id: Mapped[str] = mapped_column(
-        String(36), primary_key=True, default=lambda: str(uuid.uuid4())
+        String(36), primary_key=True, default=time_ordered_id
     )
     monitor_id: Mapped[str] = mapped_column(
         String(36), ForeignKey("monitors.id", ondelete="CASCADE"),

tests/core/test_ids.py

@@ -0,0 +1,34 @@
+"""Time-series rows get time-ordered ids, so a new row lands at the right edge
+of the primary-key index rather than on a random page of it (#5149)."""
+import uuid
+
+from steward.core import ids
+from steward.core.ids import time_ordered_id
+from steward.models.metrics import PluginMetric
+
+
+def test_the_id_is_a_version_7_uuid_string():
+    raw = time_ordered_id()
+    u = uuid.UUID(raw)
+    assert len(raw) == 36 and str(u) == raw
+    assert u.version == 7 and u.variant == uuid.RFC_4122
+
+
+def test_ids_sort_by_the_millisecond_they_were_made(monkeypatch):
+    made = []
+    for ms in (1_791_327_000_000, 1_791_327_000_001, 1_791_327_060_000):
+        monkeypatch.setattr(ids.time, "time_ns", lambda ms=ms: ms * 1_000_000)
+        made.append(time_ordered_id())
+    assert made == sorted(made)
+    assert len({m[:13] for m in made}) == 3     # the timestamp leads the string
+
+
+def test_two_ids_in_one_millisecond_differ(monkeypatch):
+    monkeypatch.setattr(ids.time, "time_ns", lambda: 1_791_327_000_000 * 1_000_000)
+    assert time_ordered_id() != time_ordered_id()
+
+
+def test_plugin_metrics_use_it():
+    # SQLAlchemy wraps a no-argument default as fn(context); call it as it would.
+    made = PluginMetric.__table__.c.id.default.arg(None)
+    assert uuid.UUID(made).version == 7

tests/plugins/host_agent/test_agent_build_payload.py

@@ -113,11 +113,18 @@ def test_post_payload_network_error_returns_none_status():
     assert status is None
 
 
-def test_backoff_schedule():
+def test_backoff_schedule_stays_inside_the_stale_window():
     from plugins.host_agent.agent import next_backoff
     assert next_backoff(0) == 30
     assert next_backoff(30) == 60
-    assert next_backoff(60) == 120
-    assert next_backoff(120) == 240
-    assert next_backoff(240) == 300  # capped
-    assert next_backoff(300) == 300
+    assert next_backoff(60) == 60    # capped below Steward's 180 s stale window (#5154)
+
+
+def test_a_backlog_drains_a_few_samples_a_post_oldest_first():
+    from plugins.host_agent.agent import MAX_SAMPLES_PER_POST, split_backlog
+    buffered = list(range(20))
+    send, held = split_backlog(buffered)
+    assert send == [0, 1, 2, 3] and held == list(range(4, 20))
+    assert len(send) + 1 == MAX_SAMPLES_PER_POST    # room for the new sample
+    assert split_backlog([7]) == ([7], [])
+    assert split_backlog([]) == ([], [])

tests/plugins/host_agent/test_agent_docker.py

@@ -706,3 +706,39 @@ def test_read_config_parses_docker_log_exclude(tmp_path):
 ])
 def test_docker_started_at(insp, started):
     assert a._docker_started_at(insp) == started
+
+
+def test_collect_docker_past_its_deadline_says_so_and_lists_nothing(monkeypatch):
+    # A partial list would read as removals; a record without inspect as restarts.
+    import threading
+    release = threading.Event()
+
+    def one(socket_path, c):
+        if c["Names"] == ["/stuck"]:
+            release.wait(2)
+        return {"name": c["Names"][0].lstrip("/")}
+
+    listing = [{"Id": "a" * 16, "Names": ["/fine"]}, {"Id": "b" * 16, "Names": ["/stuck"]}]
+    monkeypatch.setattr(a, "_docker_request", lambda s, p, timeout=a.DOCKER_API_TIMEOUT: listing)
+    monkeypatch.setattr(a, "_collect_one_container", one)
+    monkeypatch.setattr(a, "DOCKER_DEADLINE_SECONDS", 0.05)
+    try:
+        assert a.collect_docker("/s") == ("error", "1 of 2 containers not read within 0.05 s", [])
+    finally:
+        release.set()
+
+
+def test_disk_usage_is_asked_on_its_own_cadence(monkeypatch):
+    calls = []
+    clock = {"t": 1000.0}
+    monkeypatch.setattr(a.time, "monotonic", lambda: clock["t"])
+    monkeypatch.setattr(a, "collect_docker", lambda _s: ("ok", None, []))
+    monkeypatch.setattr(a, "collect_swarm", lambda _s: (None, None))
+    monkeypatch.setattr(a, "collect_disk_usage", lambda _s: calls.append(clock["t"]) or {"images_total": 1})
+    state = {}
+    seen = []
+    for t in (1000.0, 1030.0, 1000.0 + a.DOCKER_DF_INTERVAL_SECONDS):
+        clock["t"] = t
+        seen.append("docker_disk" in a.build_sample(["/"], state, "/s"))
+    assert seen == [True, False, True]
+    assert calls == [1000.0, 1000.0 + a.DOCKER_DF_INTERVAL_SECONDS]