perf: cap the cost stage, log what it left, and let continuity run on a split

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 |

docs/comparison_objective_terms.md

@@ -42,5 +42,6 @@
   `c_min > 0`. It bounds both achieved objectives and each leveled grid peak separately, so fewer
   interruptions cannot compensate for worse economics, preferences, or peaks beyond numerical
   tolerances. This pass adds no term to either earlier objective. It runs only for fragmented
-  schedules, uses at most one second of solver time within the remaining request budget, and
-  retains the incumbent unless a valid schedule has fewer actual starts.
+  schedules, uses at most one second of solver time within the remaining request budget, is
+  skipped when the solve that produced the incumbent already took longer than that, and retains
+  the incumbent unless a valid schedule has fewer actual starts.

src/optimizer/app.py

@@ -41,20 +41,34 @@ def before_request_func():
             return jsonify({"message": str(e)}), 401
 
 
-def dump_slow_request(payload, elapsed):
-    """Persist requests that exhausted the solver time limit, they are the ones worth replaying.
+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)
+
+
+# money the capped cost stage may leave unproven between its schedule and CBC's bound before
+# the request is dumped for replay. The cap keeps requests short of the time limit, so the gap
+# is what marks the ones worth replaying at a longer clock.
+DUMP_GAP = 1.0
+
+
+def dump_slow_request(payload, elapsed, gap):
+    """Persist requests worth replaying: those that exhausted the solver time limit, and those
+    the cost stage left more than DUMP_GAP of money unproven on.
 
     The elapsed time covers model building as well as solving, so a request that only exceeds
     the limit while building is caught too. That one is equally worth looking at.
     """
     path, limit = settings.dump_slow_requests, settings.time_limit
-    if not path or limit is None or elapsed < limit:
+    slow = limit is not None and elapsed >= limit
+    unproven = gap is not None and gap > DUMP_GAP
+    if not path or not (slow or unproven):
         return
 
     # one line per request, carrying the same "request" key as test_cases/*.json so a line
     # can be replayed by the existing harness
     line = json.dumps({"ts": datetime.now(timezone.utc).isoformat(timespec="seconds"),
-                       "elapsed": round(elapsed, 3), "request": payload}) + "\n"
+                       "elapsed": round(elapsed, 3), "gap": money(gap), "request": payload}) + "\n"
     try:
         pathlib.Path(path).parent.mkdir(parents=True, exist_ok=True)
         with open(path, "a") as f:
@@ -277,11 +291,14 @@ def post(self):
                 "stages": optimizer.stage_seconds,
                 "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)
 
-            dump_slow_request(data, elapsed)
+            dump_slow_request(data, elapsed, optimizer.cost_stage_gap)
             return result
 
         except Exception as e:

src/optimizer/optimizer.py

@@ -1,3 +1,5 @@
+import os
+import re
 import shutil
 import time
 from contextlib import contextmanager
@@ -145,6 +147,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
@@ -236,6 +245,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
@@ -781,6 +793,26 @@ 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.
+        """
+        # no log, no solver run behind the values, see the faked stages in the tests
+        if not os.path.exists(log_path):
+            return None
+        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.
 
@@ -923,29 +955,29 @@ def _solve_continuity(self, tmpdir: str, deadline: float | None) -> None:
 
         A device reported as charging enters the horizon switched on, so keeping it on is free and
         interrupting it costs a start.
+
+        Leaves continuity_stage behind, the way the tie break leaves preference_stage: what the
+        stage did, or why it did nothing, one string per solve for the request log.
         """
         if (self.problem.sol_status not in (pulp.LpSolutionOptimal, pulp.LpSolutionIntegerFeasible)
                 or not _complete_solution(self.problem) or not self._is_integral()):
             return
 
         eligible = [i for i, active in self.variables['z_c'].items() if active is not None]
 
-        def charging_now(i: int) -> int:
-            return int(self.batteries[i].c_active)
-
         def count_starts() -> list[int]:
             counts = []
             for i in eligible:
                 active = np.array([pulp.value(v) for v in self.variables['c'][i]]) > CONTINUITY_TOLERANCE
-                counts.append(int(np.count_nonzero(active & ~np.r_[bool(charging_now(i)), active[:-1]])))
+                counts.append(int(np.count_nonzero(active & ~np.r_[self.batteries[i].c_active, active[:-1]])))
             return counts
 
         before = count_starts()
         # a device that is charging already can reach zero starts, one that is idle needs one
-        if all(count <= 1 - charging_now(i) for i, count in zip(eligible, before)):
+        if all(count <= 1 - self.batteries[i].c_active for i, count in zip(eligible, before)):
             return
-        remaining = CONTINUITY_TIME_LIMIT if deadline is None else min(CONTINUITY_TIME_LIMIT, deadline - time.monotonic())
-        if remaining <= 0:
+        remaining = self._continuity_clock(deadline)
+        if remaining is None:
             return
 
         solution = {var: var.varValue for var in self.problem.variables()}
@@ -968,7 +1000,7 @@ def count_starts() -> list[int]:
             active = self.variables['z_c'][i]
             for t in self.time_steps:
                 start = pulp.LpVariable(f'charge_start_{i}_{t}', lowBound=0, upBound=1)
-                candidate += start >= active[t] - (active[t - 1] if t else charging_now(i))
+                candidate += start >= active[t] - (active[t - 1] if t else int(self.batteries[i].c_active))
                 starts.append(start)
         candidate.setObjective(-pulp.lpSum(starts))
 
@@ -977,26 +1009,54 @@ def count_starts() -> list[int]:
             if deadline is not None:
                 remaining = min(remaining, deadline - time.monotonic())
                 if remaining <= 0:
+                    self.continuity_stage = 'no time'
                     return
-            candidate.solve(self._solver(tmpdir, timeLimit=remaining))
+            with self._timed('continuity'):
+                candidate.solve(self._solver(tmpdir, timeLimit=remaining))
+            self.continuity_stage = 'MILP ' + pulp.LpStatus[candidate.status] + ' unused'
             if (candidate.sol_status not in (pulp.LpSolutionOptimal, pulp.LpSolutionIntegerFeasible)
                     or not _complete_solution(candidate) or not self._is_integral()):
                 return
             # CBC writes its solution with 8 significant digits, so a balance row over a 40 kWh
             # SOC comes back off by up to 1e-3 and candidate.valid(1e-5) rejects every candidate
             # (#146). CBC already held the model rows; only the bounds added here need checking.
+            after = count_starts()
             improved = (pulp.value(self.cost_objective) >= cost - 2 * CONTINUITY_TOLERANCE
                         and pulp.value(preference) >= preferred - 2 * CONTINUITY_TOLERANCE
                         and all(pulp.value(self.variables[f'p_{side}_peak']) <= peak_values[side] + 2 * CONTINUITY_TOLERANCE
                                 for side in self.peak_sides)
-                        and sum(count_starts()) < sum(before))
+                        and sum(after) < sum(before))
+            if improved:
+                self.continuity_stage = f'improved {sum(before)} to {sum(after)}'
         except pulp.PulpSolverError:
-            return
+            self.continuity_stage = 'solver error'
         finally:
             if not improved:
                 for var, value in solution.items():
                     var.varValue = value
 
+    def _continuity_clock(self, deadline: float | None) -> float | None:
+        """Seconds the continuity candidate may spend, or None with continuity_stage saying why not.
+
+        The candidate is this model plus a start per step, under a bound on the cost it just
+        optimized, so it is the harder problem: it does not finish inside a second where the
+        incumbent took longer than that. Measured over five days of production, 14 % of joint
+        solves ran this stage and half of those sat on the cap with nothing to show (#146). The
+        incumbent's own clock says which ones they are before a second is spent: the probe on the
+        joint path, the cost stage on the split path. Not the probe there: it spent its clock on
+        the joint objective and failed, and alone it is PROBE_SHARE of the time limit, so counting
+        it skipped the stage on every split request (#170).
+        """
+        spent = self.stage_seconds.get('cost', self.stage_seconds.get('probe', 0.))
+        if spent > CONTINUITY_TIME_LIMIT:
+            self.continuity_stage = f'skipped, solve took {spent:.1f} s'
+            return None
+        remaining = CONTINUITY_TIME_LIMIT if deadline is None else min(CONTINUITY_TIME_LIMIT, deadline - time.monotonic())
+        if remaining <= 0:
+            self.continuity_stage = 'no time'
+            return None
+        return remaining
+
     def _probe_then_split(self, tmpdir, deadline) -> None:
         """
         Solve the whole objective if it can be proved quickly, otherwise fall back to the split.
@@ -1044,10 +1104,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' and self._is_feasible():
             # the cost stage is allowed to stop on its gap, so LpSolutionOptimal is not required of
@@ -1091,6 +1153,7 @@ def solve(self) -> Dict:
         """
 
         self.stage_seconds = {}
+        self.continuity_stage = 'not needed'
         if self.problem is None:
             with self._timed('build'):
                 self.create_model()

src/optimizer/settings.py

@@ -21,4 +21,5 @@ class OptimizerSettings(BaseSettings):
     time_limit: float | None = Field(default=None, description="Time limit for the optimization process in seconds")
     log_subject: bool = Field(default=False, description="Log the JWT subject of every request. Off by default, it names accounts in the logs")
     dump_slow_requests: str | None = Field(default=None,
-                                           description="JSON Lines file requests that exhaust the solver time limit are appended to. Unset disables the dump")
+                                           description="JSON Lines file requests that exhaust the solver time limit, or leave more than one currency "
+                                                       "unit unproven in the cost stage, are appended to. Unset disables the dump")

tests/test_app.py

@@ -7,6 +7,7 @@
 import pulp
 import pytest
 
+import optimizer.app as app_module
 from optimizer.app import app, settings
 
 
@@ -138,6 +139,25 @@ def test_slow_requests_are_dumped(tmp_path, monkeypatch):
     assert json.loads(lines[1])["elapsed"] > 0
 
 
+def test_requests_with_an_open_gap_are_dumped(tmp_path, monkeypatch):
+    request = json.loads(pathlib.Path('test_cases/026-attenuate-grid-peaks.json').read_text())["request"]
+    dump = tmp_path / "gap.jsonl"
+    client = app.test_client()
+    monkeypatch.setattr(settings, "dump_slow_requests", str(dump))
+    # the solver reads its own settings from the environment, so force the split there
+    monkeypatch.setenv("OPTIMIZER_PROBE_SECONDS", "0")
+
+    # a proven cost stage has no gap to replay for
+    client.post("/optimize/charge-schedule", json=request)
+    assert not dump.exists()
+
+    monkeypatch.setattr(app_module, "DUMP_GAP", -1.0)
+    client.post("/optimize/charge-schedule", json=request)
+    line = json.loads(dump.read_text())
+    assert line["gap"] == 0
+    assert line["request"] == request
+
+
 def test_every_request_logs_a_solve_line(capsys):
     # the key names are the Log Analytics contract: the dashboard's KQL queries parse this line,
     # so renaming one breaks production attribution silently
@@ -149,10 +169,10 @@ def test_every_request_logs_a_solve_line(capsys):
              if line.startswith('{"solve"')]
     assert len(lines) == 1, "every request logs exactly one solve line"
     solve = lines[0]["solve"]
-    assert {"client", "elapsed", "stages", "path", "preferences", "status", "steps"} <= set(solve)
+    assert {"client", "elapsed", "stages", "path", "preferences", "continuity", "status", "steps"} <= set(solve)
     assert solve["client"] == "evcc/0.311.1"
     assert solve["elapsed"] > 0
-    assert solve["stages"] and set(solve["stages"]) <= {"build", "probe", "cost", "tie_break"}
+    assert solve["stages"] and set(solve["stages"]) <= {"build", "probe", "cost", "tie_break", "continuity"}
     assert solve["steps"] == len(request["time_series"]["dt"])