perf: cap the cost stage at 3 s and log what it left on the table

README.md

@@ -48,13 +48,13 @@ The maximum is a single value out of the horizon, which leaves one gap: a load s
 
 ## How a request is solved
 
-One request is up to five solver runs under one wall clock, `OPTIMIZER_TIME_LIMIT` (10 s in production). Each stage keeps what the previous one found unless it can improve on it without spending money. The request log carries where the clock went (`stages`), which path was taken (`path`), and what the tie break (`preferences`) and the continuity pass (`continuity`) did.
+One request is up to five solver runs under one wall clock, `OPTIMIZER_TIME_LIMIT` (10 s in production). Each stage keeps what the previous one found unless it can improve on it without spending money. The request log carries where the clock went (`stages`), which path was taken (`path`), what the tie break (`preferences`) and the continuity pass (`continuity`) did, and what the cost stage found (`cost_stage_value`) against what it could not rule out (`cost_stage_gap`, currency, zero when proven).
 
 | Stage | Task | Runs when | Parameters |
 |---|---|---|---|
 | `build` | Build the MILP and scale its objective so the largest coefficient sits at `OBJECTIVE_TARGET`. | Always. | `OBJECTIVE_TARGET` 1e6 |
 | `probe` | Solve cost and preferences together. Proven optimal means the tie is decided in one solve: path `joint`, nothing else runs on the money. | Unless `OPTIMIZER_PROBE_SECONDS` is 0. | `OPTIMIZER_PROBE_SECONDS`, default `PROBE_SHARE` 0.2 of the limit |
-| `cost` | Money only, stopped on an absolute gap. Holds back a slice of the clock for the tie break instead of taking whatever is left. | The probe did not prove its answer: path `split`. | `OPTIMIZER_GAP_ABS` 0.01 currency, `PREFERENCE_TIME_SHARE` 0.25 of the limit reserved |
+| `cost` | Money only, stopped on an absolute gap. Holds back a slice of the clock for the tie break instead of taking whatever is left. | The probe did not prove its answer: path `split`. | `OPTIMIZER_GAP_ABS` 0.01 currency, `COST_TIME_LIMIT` 3 s, `PREFERENCE_TIME_SHARE` 0.25 of the limit reserved |
 | `tie_break`, LP | Pin the binaries the cost stage chose and move only the continuous variables, under a bound that keeps the cost found. Milliseconds, so it runs whatever the clock says. If CBC calls the bound infeasible the slack is widened tenfold per retry. | Path `split` and a strategy is configured. | `OPTIMIZER_PREFERENCE_BUDGET` 0, `COST_BOUND_SLACK` 1e-5 up to `COST_BOUND_SLACK_CEILING` 1e-2, `COST_BOUND_TOLERANCE` 1e-4, `LP_PREFERENCE_TIME_LIMIT` 1 s |
 | `tie_break`, MILP | Search the whole model under the same bound to beat the LP. Whichever is ahead is returned. | After the LP, clock permitting. | The reserved slice, capped at `MILP_PREFERENCE_TIME_LIMIT` 2.5 s; uncapped without a time limit |
 | `continuity` | Fewest charge starts for batteries with `c_min > 0`, bounded by the cost, the preference value and each levelled grid peak already reached. A preference, not a guarantee: prices, charge demands and grid shaping still win, and power may vary within a session. | A battery has more than one charging session, and the solve so far took less than the stage may spend. | `CONTINUITY_TIME_LIMIT` 1 s, `CONTINUITY_TOLERANCE` 1e-5 |

src/optimizer/app.py

@@ -41,6 +41,11 @@ def before_request_func():
             return jsonify({"message": str(e)}), 401
 
 
+def money(value):
+    """Currency for the request log, or None where a stage did not run."""
+    return None if value is None else round(value, 4)
+
+
 def dump_slow_request(payload, elapsed):
     """Persist requests that exhausted the solver time limit, they are the ones worth replaying.
 
@@ -276,6 +281,8 @@ def post(self):
                 "path": optimizer.solve_path,
                 "preferences": optimizer.preference_stage,
                 "continuity": optimizer.continuity_stage,
+                "cost_stage_value": money(optimizer.cost_stage_value),
+                "cost_stage_gap": money(optimizer.cost_stage_gap),
                 "status": result.get('status'),
                 "steps": optimizer.T,
             }}), flush=True)

src/optimizer/optimizer.py

@@ -1,3 +1,5 @@
+import os
+import re
 import shutil
 import time
 from contextlib import contextmanager
@@ -140,6 +142,13 @@ def _complete_solution(problem: pulp.LpProblem) -> bool:
 # Requests without a time limit stay uncapped, they asked to be solved out.
 MILP_PREFERENCE_TIME_LIMIT = 2.5
 
+# clock the cost stage may spend on a split. Absolute rather than what the reserve leaves of the
+# limit: the stage is anytime branch and bound and consumes whatever it is offered, so on the
+# production 10 s limit every split ran 5.4 s of it and 17 percent of them ended past the limit.
+# The split is 3 percent of the traffic and 38 percent of the CPU. Whether the seconds past 3 buy
+# money is what cost_stage_gap is logged to answer. Requests without a time limit stay uncapped.
+COST_TIME_LIMIT = 3.0
+
 # clock the pinned LP tie break may use. It is a linear program over a schedule that is already
 # feasible, worst measured 0.165 s over the stored cases, so this is a guard against a pathological
 # model rather than a budget. It runs even once the deadline is gone: without it a request that
@@ -230,6 +239,9 @@ def __init__(self, strategy: OptimizationStrategy, grid: GridConfig, batteries:
         # found before it ran. Everything below that value was given away deciding the tie.
         self.preference_stage = None
         self.cost_stage_value = None
+        # money the cost stage could not rule out above its schedule, in currency. Zero when it
+        # proved the value, None when it did not run.
+        self.cost_stage_gap = None
         # 'joint' when the probe proved the whole objective, 'split' when it fell back
         self.solve_path = None
         # wall clock per stage of the last solve(), keyed build/probe/cost/tie_break. What the
@@ -775,6 +787,23 @@ def _timed(self, stage):
             self.stage_seconds[stage] = round(
                 self.stage_seconds.get(stage, 0.) + time.monotonic() - started, 4)
 
+    @staticmethod
+    def _cbc_gap(log_path, scale) -> float | None:
+        """Distance between CBC's schedule and its bound, from the log, in currency.
+
+        The solution file carries no bound, only the log does: a proven solve prints none and the
+        gap is zero, a stopped one prints the bound it reached.
+        """
+        with open(log_path) as log:
+            text = log.read()
+        value = re.search(r'^Objective value:\s+(\S+)', text, re.MULTILINE)
+        if value is None:
+            return None
+        bound = re.search(r'^(?:Lower|Upper) bound:\s+(\S+)', text, re.MULTILINE)
+        if bound is None:
+            return 0.
+        return abs(float(bound.group(1)) - float(value.group(1))) / scale
+
     def _pin_integers(self):
         """Freeze every integer variable on the value it currently holds, undo data returned.
 
@@ -1048,10 +1077,12 @@ def _probe_then_split(self, tmpdir, deadline) -> None:
         # use, see PREFERENCE_TIME_SHARE
         reserve = (0. if self.settings.time_limit is None
                    else self.settings.time_limit * PREFERENCE_TIME_SHARE)
-        remaining = None if deadline is None else max(deadline - reserve - time.monotonic(), 0.1)
+        remaining = None if deadline is None else max(min(COST_TIME_LIMIT, deadline - reserve - time.monotonic()), 0.1)
+        log_path = os.path.join(tmpdir, 'cost.log')
         with self._timed('cost'):
-            self.problem.solve(self._solver(tmpdir, timeLimit=remaining,
+            self.problem.solve(self._solver(tmpdir, timeLimit=remaining, logPath=log_path,
                                             gapAbs=None if gap_abs is None else gap_abs * scale))
+        self.cost_stage_gap = self._cbc_gap(log_path, scale)
 
         if pulp.LpStatus[self.problem.status] == 'Optimal':
             # the cost stage is allowed to stop on its gap, so LpSolutionOptimal is not required of

tests/test_stage_timings.py

@@ -15,6 +15,8 @@ def test_joint_path_times_build_and_probe():
 
     assert optimizer.solve_path == 'joint'
     assert set(optimizer.stage_seconds) == {'build', 'probe'}
+    # no cost stage ran, so there is no gap to report
+    assert optimizer.cost_stage_gap is None
     assert all(seconds >= 0 for seconds in optimizer.stage_seconds.values())
 
 
@@ -28,3 +30,7 @@ def test_split_path_times_every_stage():
     # no probe ran, so no probe key: an absent stage must be absent, not zero
     assert set(optimizer.stage_seconds) == {'build', 'cost', 'tie_break'}
     assert all(seconds >= 0 for seconds in optimizer.stage_seconds.values())
+    # the cost stage leaves behind what it found and what CBC could not rule out above it
+    assert optimizer.cost_stage_value is not None
+    assert optimizer.cost_stage_gap is not None
+    assert optimizer.cost_stage_gap >= 0