From 70a31aa6a0d47ebcf28c74444e39d150af8ec172 Mon Sep 17 00:00:00 2001
From: Peter Lord <im@ptrlrd.com>
Date: Fri, 10 Jul 2026 00:13:41 -0700
Subject: [PATCH] Log refresh-cycle steps and snapshot-rebuild phases
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

The entity-stats snapshot rebuild is silent until it completes, so a rebuild that
never finishes (prod is stuck serving a stale snapshot) is undiagnosable from the
logs. Add INFO logs that time each refresh-cycle step (charts prewarm, stats
summary, leaderboard summary, then the snapshot rebuild) and each phase of the
rebuild itself (loading run rows from the DB, walking the blob files, finalizing
the Codex Elo fits). Whichever "done" log never arrives pinpoints where a stalled
rebuild is stuck. Logging only — no behavior change.
---
 backend/app/routers/runs.py              | 12 ++++++++++++
 backend/app/services/run_entity_stats.py | 19 +++++++++++++++++++
 2 files changed, 31 insertions(+)

diff --git a/backend/app/routers/runs.py b/backend/app/routers/runs.py
index 3dffb8bf..4a09ea7f 100644
--- a/backend/app/routers/runs.py
+++ b/backend/app/routers/runs.py
@@ -1182,6 +1182,11 @@ def _run_refresh_cycle() -> None:
         )
         from ..services.run_entity_stats import refresh_entity_stats_snapshot
 
+        # Per-step timing: a rebuild that never completes shows up here as a step
+        # whose "done" log never arrives, so we can see which step starves it.
+        _cyc0 = time.time()
+        logger.info("refresh cycle: starting (leader)")
+
         # Warm the /charts page FIRST so the default no-filter view of each chart
         # is in Redis within seconds of a deploy, instead of waiting behind the
         # entity-stats snapshot walk below (which can run for minutes). Frame
@@ -1194,11 +1199,13 @@ def _run_refresh_cycle() -> None:
                 prewarm_charts()
         except Exception:
             logger.warning("charts prewarm failed", exc_info=True)
+        logger.info("refresh cycle: charts prewarm done at %.1fs", time.time() - _cyc0)
 
         try:
             refresh_stats_summary()
         except Exception:
             logger.warning("stats summary refresh failed", exc_info=True)
+        logger.info("refresh cycle: stats summary done at %.1fs", time.time() - _cyc0)
         # Pre-compute the default (category, character) ladder
         # views into leaderboard_summary. Reads for the common
         # combos become O(1) find_one instead of a 500ms
@@ -1207,6 +1214,11 @@ def _run_refresh_cycle() -> None:
             refresh_leaderboard_summary()
         except Exception:
             logger.warning("leaderboard summary refresh failed", exc_info=True)
+        logger.info(
+            "refresh cycle: leaderboard summary done at %.1fs, entering snapshot "
+            "rebuild",
+            time.time() - _cyc0,
+        )
         # Rebuild the shared entity-stats snapshot (tier-list
         # / Codex Score source) on the same leader-only loop.
         # Internally throttled, so this is a no-op find_one
diff --git a/backend/app/services/run_entity_stats.py b/backend/app/services/run_entity_stats.py
index e3b5986f..96fa9688 100644
--- a/backend/app/services/run_entity_stats.py
+++ b/backend/app/services/run_entity_stats.py
@@ -839,6 +839,12 @@ def _build_cache_data() -> tuple[dict, dict, dict, dict]:
     (solo/2p/3p/4p/a10/daily/custom); those land nested under each entity's
     ``brackets`` key, and `bracket_meta` carries their baselines + totals.
     """
+    # Phase timing so a stalled rebuild is diagnosable from the logs (the walk is
+    # otherwise silent until it completes). Which phase the last log names tells
+    # us where a rebuild that never finishes is stuck.
+    _t0 = time.time()
+    logger.info("snapshot rebuild: starting (loading run rows from the DB)")
+
     new_cache: dict[tuple[str, str], dict[str, Any]] = {}
     new_totals = {"total_runs": 0, "total_wins": 0}
 
@@ -909,6 +915,12 @@ def _build_cache_data() -> tuple[dict, dict, dict, dict]:
             ).fetchall()
             rows = [dict(r) for r in rows]
 
+    logger.info(
+        "snapshot rebuild: loaded %d run rows in %.1fs, now walking blob files",
+        len(rows),
+        time.time() - _t0,
+    )
+
     official_chars = _official_character_ids()
 
     # Per-username overall win rate (fraction, 5-run floor) for the skill-bracket
@@ -1222,6 +1234,13 @@ def _build_cache_data() -> tuple[dict, dict, dict, dict]:
                     skipped_ids,
                 )
 
+    logger.info(
+        "snapshot rebuild: blob walk done in %.1fs (%d entities), finalizing "
+        "(Codex Elo fits + bracket serialization)",
+        time.time() - _t0,
+        len(new_cache),
+    )
+
     # Fold the card-reward pick stats + fitted Codex Elo into the cache.
     # Cards that were offered but never decked still get an entry (picks=0
     # → no Win%/Score, but a valid Pick%/Elo). Starter cards that are