Deep CFR evaluation 프로파일링 메트릭 추가

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.

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_<opponent>_<metric_name>`.
+
+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.

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(