diff --git a/README.md b/README.md index 0f28f5276..5d12369a4 100644 --- a/README.md +++ b/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 | diff --git a/docs/comparison_objective_terms.md b/docs/comparison_objective_terms.md index 56d3fef8c..a777a0eda 100644 --- a/docs/comparison_objective_terms.md +++ b/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. diff --git a/src/optimizer/app.py b/src/optimizer/app.py index 08d7dd811..ab1603045 100644 --- a/src/optimizer/app.py +++ b/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: diff --git a/src/optimizer/optimizer.py b/src/optimizer/optimizer.py index f5a26bb55..3a88ed489 100644 --- a/src/optimizer/optimizer.py +++ b/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,6 +955,9 @@ 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()): @@ -930,22 +965,19 @@ def _solve_continuity(self, tmpdir: str, deadline: float | None) -> None: 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() diff --git a/src/optimizer/settings.py b/src/optimizer/settings.py index 39c3ebf1b..34f72ddb1 100644 --- a/src/optimizer/settings.py +++ b/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") diff --git a/tests/test_app.py b/tests/test_app.py index 2699b387e..52325c1bb 100644 --- a/tests/test_app.py +++ b/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"]) diff --git a/tests/test_continuity.py b/tests/test_continuity.py index e28e246fe..4202c0825 100644 --- a/tests/test_continuity.py +++ b/tests/test_continuity.py @@ -6,7 +6,7 @@ import pulp import pytest -from optimizer.optimizer import BatteryConfig, GridConfig, OptimizationStrategy, Optimizer, TimeSeriesData +from optimizer.optimizer import CONTINUITY_TIME_LIMIT, BatteryConfig, GridConfig, OptimizationStrategy, Optimizer, TimeSeriesData def build(strategy: str = 'none') -> Optimizer: @@ -53,6 +53,49 @@ def test_equal_prices_prefer_one_session(monkeypatch: pytest.MonkeyPatch, probe_ assert starts(result['batteries'][0]['charging_power']) == 1 assert result['batteries'][0]['state_of_charge'][-1] == pytest.approx(1500, abs=0.1) assert pulp.value(model.cost_objective) == pytest.approx(-0.45, abs=1e-5) + assert model.continuity_stage == 'improved 3 to 1' + assert model.stage_seconds['continuity'] >= 0 + + +def test_hard_solve_skips_continuity(monkeypatch: pytest.MonkeyPatch): + # the candidate cannot beat the clock of the solve that produced the incumbent, so a solve + # that already took longer than the stage may spend gets no candidate at all + model = build() + seed_fragmented(model, monkeypatch) + seeded = model._probe_then_split + + def slow(tmpdir: str, deadline: float | None) -> None: + seeded(tmpdir, deadline) + model.stage_seconds['probe'] = CONTINUITY_TIME_LIMIT + 1 + + monkeypatch.setattr(model, '_probe_then_split', slow) + + result = model.solve() + + assert starts(result['batteries'][0]['charging_power']) == 3 + assert model.continuity_stage.startswith('skipped') + assert 'continuity' not in model.stage_seconds + + +def test_split_solve_is_judged_by_its_cost_stage(monkeypatch: pytest.MonkeyPatch): + # on the split path the probe spent its clock on the joint objective and failed, so it says + # nothing about the candidate; the cost stage it extends does. Counting the probe skipped the + # stage on every split request, the probe alone being PROBE_SHARE of the time limit (#170) + model = build() + seed_fragmented(model, monkeypatch) + seeded = model._probe_then_split + + def split(tmpdir: str, deadline: float | None) -> None: + seeded(tmpdir, deadline) + model.stage_seconds['probe'] = CONTINUITY_TIME_LIMIT + 1 + model.stage_seconds['cost'] = 0.1 + + monkeypatch.setattr(model, '_probe_then_split', split) + + result = model.solve() + + assert starts(result['batteries'][0]['charging_power']) == 1 + assert model.continuity_stage == 'improved 3 to 1' @pytest.mark.parametrize('schedule', [(0, 500, 0, 500, 0, 500), (0, 500, 500, 500, 0, 0)]) @@ -91,6 +134,7 @@ def test_price_gaps_keep_interruptions(monkeypatch: pytest.MonkeyPatch): assert starts(result['batteries'][0]['charging_power']) == 3 assert pulp.value(model.cost_objective) == pytest.approx(-0.45, abs=1e-5) + assert model.continuity_stage == 'MILP Optimal unused' def test_grid_shaping_takes_priority(monkeypatch: pytest.MonkeyPatch): diff --git a/tests/test_stage_timings.py b/tests/test_stage_timings.py index 5c2737429..0159149d9 100644 --- a/tests/test_stage_timings.py +++ b/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