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