diff --git a/docs/deep-cfr-evaluation-profile-2026-05-07.md b/docs/deep-cfr-evaluation-profile-2026-05-07.md new file mode 100644 index 0000000..0495c69 --- /dev/null +++ b/docs/deep-cfr-evaluation-profile-2026-05-07.md @@ -0,0 +1,64 @@ +# Deep CFR Evaluation Profile 2026-05-07 + +Run directory: + +`/mnt/2tbhdd/coolrl-lost-cities-runs/2026-05-07_030634_deep_cfr_profile_eval_breakdown_10iter` + +Command: + +```bash +uv run python -m coolrl_lost_cities.games.classic.deep_cfr.cli train \ + --config configs/deep_cfr/deep_cfr_selfplay_full_depth_slot_playability.yaml \ + --checkpoint-dir /mnt/2tbhdd/coolrl-lost-cities-runs/2026-05-07_030634_deep_cfr_profile_eval_breakdown_10iter \ + --max-iterations 10 \ + --save-latest-only +``` + +## Summary + +The run completed 10 iterations. Loss values stayed finite. + +Evaluation ran on iterations 5 and 10. + +| Iteration | `iteration_seconds` | `evaluation_seconds` | +| ---: | ---: | ---: | +| 5 | 16.473433 | 11.055458 | +| 10 | 16.835262 | 10.855797 | + +## Opponent Averages + +Values below are averaged across iterations 5 and 10. + +| Opponent | elapsed | avg len | policy select | network | postprocess | encoding | legal mask | opponent act | +| --- | ---: | ---: | ---: | ---: | ---: | ---: | ---: | ---: | +| `safe_heuristic_strict` | 2.184393 | 158.13 | 1.628546 | 1.279717 | 0.175923 | 0.043837 | 0.038600 | 0.518953 | +| `random` | 2.072657 | 186.11 | 1.918007 | 1.515231 | 0.207319 | 0.051491 | 0.037316 | 0.112155 | +| `safe_heuristic` | 1.942907 | 143.23 | 1.471839 | 1.155444 | 0.159592 | 0.039683 | 0.035180 | 0.435870 | +| `noisy_safe` | 1.904932 | 143.71 | 1.493521 | 1.174909 | 0.161256 | 0.039845 | 0.034331 | 0.374162 | +| `safe_heuristic_loose` | 1.829347 | 136.13 | 1.400569 | 1.099200 | 0.151752 | 0.037722 | 0.033497 | 0.394891 | +| `passive_discard` | 1.014156 | 96.82 | 0.982162 | 0.774097 | 0.105579 | 0.026702 | 0.021929 | 0.006383 | + +Other averaged step costs were small: + +| Opponent | apply action | diagnostics | final scoring | +| --- | ---: | ---: | ---: | +| `safe_heuristic_strict` | 0.005185 | 0.008161 | 0.000569 | +| `random` | 0.006229 | 0.009001 | 0.000632 | +| `safe_heuristic` | 0.004748 | 0.007636 | 0.000581 | +| `noisy_safe` | 0.004818 | 0.007761 | 0.000584 | +| `safe_heuristic_loose` | 0.004473 | 0.007438 | 0.000592 | +| `passive_discard` | 0.002911 | 0.005156 | 0.000477 | + +## Notes + +`policy_select_seconds` dominated every opponent. + +Inside policy selection, `policy_network_seconds` was the largest component. +`policy_postprocess_seconds` was second. `policy_encoding_seconds` and +`policy_legal_mask_seconds` were much smaller. + +`opponent_act_seconds` was meaningful for safe heuristic opponents, but was +still smaller than policy network time. + +`apply_action_seconds`, `diagnostics_seconds`, and `final_scoring_seconds` were +small in this run. diff --git a/docs/deep-cfr-evaluation-profile-plan.md b/docs/deep-cfr-evaluation-profile-plan.md new file mode 100644 index 0000000..c3c763e --- /dev/null +++ b/docs/deep-cfr-evaluation-profile-plan.md @@ -0,0 +1,50 @@ +# Deep CFR Evaluation Profile Plan + +Goal: split evaluation runtime into the main per-step costs so eval iteration +spikes can be explained without guessing. + +The profiling run should keep the normal full config and `eval_every: 5`, then +compare iterations 5 and 10. + +## Metrics + +Each metric is emitted with the existing opponent prefix: +`eval__`. + +Top-level counters: + +- `policy_turns` +- `opponent_turns` +- `avg_game_length` +- `elapsed_seconds` +- `games_per_second` +- `steps_per_second` + +Step-level runtime: + +- `policy_select_seconds` +- `opponent_act_seconds` +- `apply_action_seconds` +- `diagnostics_seconds` +- `final_scoring_seconds` + +Policy select breakdown: + +- `policy_legal_mask_seconds` +- `policy_encoding_seconds` +- `policy_network_seconds` +- `policy_postprocess_seconds` + +## Interpretation + +If `policy_network_seconds` dominates, evaluation is mostly batch-size-1 model +inference overhead. + +If `policy_encoding_seconds` or `policy_legal_mask_seconds` dominates, the eval +policy path is paying per-turn state feature/mask construction costs. + +If `opponent_act_seconds` dominates, the opponent bot implementation is the +main eval cost for that opponent. + +If `apply_action_seconds` dominates, the game step path itself is the eval +bottleneck. diff --git a/src/coolrl_lost_cities/games/classic/deep_cfr/evaluate.py b/src/coolrl_lost_cities/games/classic/deep_cfr/evaluate.py index b2e91ec..fd6b811 100644 --- a/src/coolrl_lost_cities/games/classic/deep_cfr/evaluate.py +++ b/src/coolrl_lost_cities/games/classic/deep_cfr/evaluate.py @@ -15,6 +15,49 @@ from coolrl_lost_cities.games.classic.game import GameState, LostCitiesConfig from coolrl_lost_cities.games.classic.policy import LostCitiesPolicy, PolicyInput +@dataclass +class EvalRuntimeCounters: + policy_turns: int = 0 + opponent_turns: int = 0 + policy_select_seconds: float = 0.0 + policy_legal_mask_seconds: float = 0.0 + policy_encoding_seconds: float = 0.0 + policy_network_seconds: float = 0.0 + policy_postprocess_seconds: float = 0.0 + opponent_act_seconds: float = 0.0 + apply_action_seconds: float = 0.0 + diagnostics_seconds: float = 0.0 + final_scoring_seconds: float = 0.0 + + def accumulate(self, other: EvalRuntimeCounters) -> None: + self.policy_turns += other.policy_turns + self.opponent_turns += other.opponent_turns + self.policy_select_seconds += other.policy_select_seconds + self.policy_legal_mask_seconds += other.policy_legal_mask_seconds + self.policy_encoding_seconds += other.policy_encoding_seconds + self.policy_network_seconds += other.policy_network_seconds + self.policy_postprocess_seconds += other.policy_postprocess_seconds + self.opponent_act_seconds += other.opponent_act_seconds + self.apply_action_seconds += other.apply_action_seconds + self.diagnostics_seconds += other.diagnostics_seconds + self.final_scoring_seconds += other.final_scoring_seconds + + def to_dict(self) -> dict[str, float | int]: + return { + "policy_turns": self.policy_turns, + "opponent_turns": self.opponent_turns, + "policy_select_seconds": self.policy_select_seconds, + "policy_legal_mask_seconds": self.policy_legal_mask_seconds, + "policy_encoding_seconds": self.policy_encoding_seconds, + "policy_network_seconds": self.policy_network_seconds, + "policy_postprocess_seconds": self.policy_postprocess_seconds, + "opponent_act_seconds": self.opponent_act_seconds, + "apply_action_seconds": self.apply_action_seconds, + "diagnostics_seconds": self.diagnostics_seconds, + "final_scoring_seconds": self.final_scoring_seconds, + } + + @dataclass class PolicyEvalDiagnostics: games: int = 0 @@ -51,13 +94,14 @@ class PolicyEvalDiagnostics: negative_expedition_scores: list[int] = field(default_factory=list) first_open_positive_recoverable_scores: list[float] = field(default_factory=list) first_open_negative_recoverable_scores: list[float] = field(default_factory=list) + runtime: EvalRuntimeCounters = field(default_factory=EvalRuntimeCounters) def to_dict(self, elapsed_seconds: float) -> dict[str, float | int]: games = max(1, self.games) total_steps = sum(self.lengths) opened_expeditions = len(self.final_expedition_scores) total_policy_actions = max(1, self.policy_actions) - return { + data: dict[str, float | int] = { "games": self.games, "wins0": self.wins, "wins1": self.losses, @@ -111,6 +155,8 @@ class PolicyEvalDiagnostics: self.first_open_negative_recoverable_scores ), } + data.update(self.runtime.to_dict()) + return data class StrategyNetPolicy(LostCitiesPolicy): @@ -128,25 +174,36 @@ class StrategyNetPolicy(LostCitiesPolicy): self.sample = sample self.rng = np.random.default_rng(seed) self.encoding = encoding + self.runtime = EvalRuntimeCounters() def action_distribution(self, state: GameState) -> tuple[np.ndarray, np.ndarray]: + started = time.perf_counter() legal = np.asarray(state.unified_legal_mask(), dtype=bool) legal_actions = np.flatnonzero(legal) + self.runtime.policy_legal_mask_seconds += time.perf_counter() - started if len(legal_actions) == 0: raise RuntimeError("no legal action available") + started = time.perf_counter() info = encode_info_state(state, state.current_player, self.encoding) + self.runtime.policy_encoding_seconds += time.perf_counter() - started + started = time.perf_counter() with torch.inference_mode(): x = torch.as_tensor(info, dtype=torch.float32, device=self.device).unsqueeze(0) logits = self.strategy_network(x).squeeze(0).detach().cpu().numpy() + self.runtime.policy_network_seconds += time.perf_counter() - started + started = time.perf_counter() masked = np.where(legal, logits, -np.inf) stable = masked[legal_actions] - np.max(masked[legal_actions]) probs = np.exp(stable) probs = probs / probs.sum() distribution = np.zeros_like(masked, dtype=np.float32) distribution[legal_actions] = probs.astype(np.float32) + self.runtime.policy_postprocess_seconds += time.perf_counter() - started return legal_actions, distribution def select_action(self, state: GameState) -> tuple[int, float]: + started = time.perf_counter() + self.runtime.policy_turns += 1 legal_actions, distribution = self.action_distribution(state) probs = distribution[legal_actions] entropy = _entropy(probs) @@ -154,7 +211,9 @@ class StrategyNetPolicy(LostCitiesPolicy): unified = int(self.rng.choice(legal_actions, p=probs)) else: unified = int(legal_actions[int(np.argmax(probs))]) - return state.from_unified_action(unified), entropy + action = state.from_unified_action(unified) + self.runtime.policy_select_seconds += time.perf_counter() - started + return action, entropy def act(self, obs_or_state: PolicyInput) -> int: if not isinstance(obs_or_state, GameState): @@ -225,6 +284,7 @@ def _evaluate_strategy_network_with_diagnostics( seed=game_seed, max_steps=max_steps, ) + game_diag.runtime.accumulate(policy.runtime) _accumulate_game_diagnostics(diagnostics, game_diag) return diagnostics.to_dict(time.perf_counter() - started) @@ -249,15 +309,23 @@ def _evaluate_one_game( if current_player == policy_player and isinstance(policy, StrategyNetPolicy): action, entropy = policy.select_action(state) diagnostics.entropies.append(entropy) + diagnostics_started = time.perf_counter() _record_policy_action(diagnostics, state, action, first_open_recoverable_by_color) + diagnostics.runtime.diagnostics_seconds += time.perf_counter() - diagnostics_started else: + diagnostics.runtime.opponent_turns += 1 + opponent_started = time.perf_counter() action = policy.act(state) + diagnostics.runtime.opponent_act_seconds += time.perf_counter() - opponent_started + apply_started = time.perf_counter() state.apply_action(action) + diagnostics.runtime.apply_action_seconds += time.perf_counter() - apply_started steps += 1 timed_out = not state.terminal if timed_out: steps = max_steps + final_started = time.perf_counter() _record_final_game_state( diagnostics, state, @@ -266,6 +334,7 @@ def _evaluate_one_game( timed_out, first_open_recoverable_by_color, ) + diagnostics.runtime.final_scoring_seconds += time.perf_counter() - final_started return diagnostics @@ -427,6 +496,7 @@ def _accumulate_game_diagnostics( target.first_open_negative_recoverable_scores.extend( source.first_open_negative_recoverable_scores ) + target.runtime.accumulate(source.runtime) def _visible_recoverable_summary(