diff --git a/src/optimizer/app.py b/src/optimizer/app.py index a355b2d1c..202bbb350 100644 --- a/src/optimizer/app.py +++ b/src/optimizer/app.py @@ -252,7 +252,20 @@ def post(self): started = time.perf_counter() result = optimizer.solve() - dump_slow_request(data, time.perf_counter() - started) + elapsed = time.perf_counter() - started + + # one JSON line per request, so Log Analytics can attribute the response time to the + # solve stages. The access log only carries the total. + print(json.dumps({"solve": { + "elapsed": round(elapsed, 3), + "stages": optimizer.stage_seconds, + "path": optimizer.solve_path, + "preferences": optimizer.preference_stage, + "status": result.get('status'), + "steps": optimizer.T, + }}), flush=True) + + dump_slow_request(data, elapsed) return result except Exception as e: diff --git a/src/optimizer/optimizer.py b/src/optimizer/optimizer.py index 4741414d8..44c4f0bfe 100644 --- a/src/optimizer/optimizer.py +++ b/src/optimizer/optimizer.py @@ -1,5 +1,6 @@ import shutil import time +from contextlib import contextmanager from dataclasses import dataclass from tempfile import TemporaryDirectory from typing import Dict, List, Optional @@ -202,6 +203,9 @@ def __init__(self, strategy: OptimizationStrategy, grid: GridConfig, batteries: self.cost_stage_value = 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 + # response time was spent on, where the access log only carries the total. + self.stage_seconds = {} # dictionary of optimizer variables self.variables = {} @@ -729,6 +733,19 @@ def _solver(self, tmpdir, **options): solver.tmpDir = tmpdir return solver + @contextmanager + def _timed(self, stage): + """Add the wall clock of the enclosed block to stage_seconds. + + Accumulating rather than assigning, because the tie break is two solves under one name. + """ + started = time.monotonic() + try: + yield + finally: + self.stage_seconds[stage] = round( + self.stage_seconds.get(stage, 0.) + time.monotonic() - started, 4) + def _pin_integers(self): """Freeze every integer variable on the value it currently holds, undo data returned. @@ -817,7 +834,8 @@ def keep(): # clock says and the strategies get something even when the search below never starts. pinned = self._pin_integers() try: - self.problem.solve(self._solver(tmpdir, timeLimit=LP_PREFERENCE_TIME_LIMIT)) + with self._timed('tie_break'): + self.problem.solve(self._solver(tmpdir, timeLimit=LP_PREFERENCE_TIME_LIMIT)) stages.append('LP ' + pulp.LpStatus[self.problem.status] + ('' if keep() else ' unused')) finally: self._unpin_integers(pinned) @@ -839,7 +857,8 @@ def keep(): # a single joint solve to the last digit. Fixed upstream, the same LP and the same start # file come back identical to the cold run on CBC 2.10.13, but the image ships 2.10.10 # and that one has not been checked, so this stays until it is. - self.problem.solve(self._solver(tmpdir, timeLimit=remaining)) + with self._timed('tie_break'): + self.problem.solve(self._solver(tmpdir, timeLimit=remaining)) stages.append('MILP ' + pulp.LpStatus[self.problem.status] + ('' if keep() else ' unused')) @@ -864,7 +883,8 @@ def _probe_then_split(self, tmpdir, deadline) -> None: if probe is None and self.settings.time_limit is not None: probe = self.settings.time_limit * PROBE_SHARE if probe != 0: - self.problem.solve(self._solver(tmpdir, timeLimit=probe)) + with self._timed('probe'): + self.problem.solve(self._solver(tmpdir, timeLimit=probe)) # sol_status, not status: pulp reports LpStatusOptimal whenever CBC came back with any # feasible solution, including one it stopped on at the time limit. Measured on a captured @@ -896,8 +916,9 @@ def _probe_then_split(self, tmpdir, deadline) -> None: 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) - self.problem.solve(self._solver(tmpdir, timeLimit=remaining, - gapAbs=None if gap_abs is None else gap_abs * scale)) + with self._timed('cost'): + self.problem.solve(self._solver(tmpdir, timeLimit=remaining, + gapAbs=None if gap_abs is None else gap_abs * scale)) if pulp.LpStatus[self.problem.status] == 'Optimal': # the cost stage is allowed to stop on its gap, so LpSolutionOptimal is not required of @@ -926,8 +947,10 @@ def solve(self) -> Dict: Returns a dictionary with the optimization results """ + self.stage_seconds = {} if self.problem is None: - self.create_model() + with self._timed('build'): + self.create_model() # both stages share one wall clock, so a second solve cannot double the response time deadline = None if self.settings.time_limit is None else time.monotonic() + self.settings.time_limit diff --git a/tests/test_app.py b/tests/test_app.py index 1bd31293d..3c4053212 100644 --- a/tests/test_app.py +++ b/tests/test_app.py @@ -138,6 +138,23 @@ def test_slow_requests_are_dumped(tmp_path, monkeypatch): assert json.loads(lines[1])["elapsed"] > 0 +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 + request = json.loads(pathlib.Path('test_cases/009-discharge-before-import.json').read_text())["request"] + client = app.test_client() + client.post("/optimize/charge-schedule", json=request) + + lines = [json.loads(line) for line in capsys.readouterr().out.splitlines() + if line.startswith('{"solve"')] + assert len(lines) == 1, "every request logs exactly one solve line" + solve = lines[0]["solve"] + assert {"elapsed", "stages", "path", "preferences", "status", "steps"} <= set(solve) + assert solve["elapsed"] > 0 + assert solve["stages"] and set(solve["stages"]) <= {"build", "probe", "cost", "tie_break"} + assert solve["steps"] == len(request["time_series"]["dt"]) + + def test_abort_returns_json_message(): # message-only api.abort(400, ...) must return a JSON body, not an empty response client = app.test_client() diff --git a/tests/test_stage_timings.py b/tests/test_stage_timings.py new file mode 100644 index 000000000..5c2737429 --- /dev/null +++ b/tests/test_stage_timings.py @@ -0,0 +1,30 @@ +"""The stage clock: every solve leaves behind where its wall time went. + +The access log only carries the total response time, so stage_seconds is what production +attributes latency with. These tests pin the keys each solve path must produce. +""" +from test_objective_split import build + +from optimizer.settings import OptimizerSettings + + +def test_joint_path_times_build_and_probe(): + # a small case the probe proves outright: no split, so no cost or tie break stage ran + optimizer = build('012-early-charging-not-perfect') + optimizer.solve() + + assert optimizer.solve_path == 'joint' + assert set(optimizer.stage_seconds) == {'build', 'probe'} + assert all(seconds >= 0 for seconds in optimizer.stage_seconds.values()) + + +def test_split_path_times_every_stage(): + # probe_seconds=0 forces the split, and this case carries a strategy so the tie break runs + optimizer = build('026-attenuate-grid-peaks') + optimizer.settings = OptimizerSettings(probe_seconds=0, time_limit=10) + optimizer.solve() + + assert optimizer.solve_path == 'split' + # 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())