From a008a517d11fbe24fc89ac1c9f6cfbad1eb95dc3 Mon Sep 17 00:00:00 2001 From: andig Date: Sat, 22 Aug 2026 14:37:45 +0200 Subject: [PATCH 1/2] feat: log where each solve spent its clock One JSON line per request on stdout: elapsed, per stage wall time (build, probe, cost, tie_break), solve path, preference stage outcome, status and step count. Container Apps ships stdout to Log Analytics, so per stage percentiles become a KQL query away - the access log only carries the total, and the slow request dump only catches what already exhausted the limit. Stage clocks accumulate rather than assign, because the tie break is two solves (LP floor, MILP proper) under one name. An absent stage is an absent key, not a zero, so the joint path is distinguishable from a split that ran out of clock. Co-Authored-By: Claude Fable 5 --- src/optimizer/app.py | 15 ++++++++++++++- src/optimizer/optimizer.py | 35 +++++++++++++++++++++++++++++------ tests/test_stage_timings.py | 30 ++++++++++++++++++++++++++++++ 3 files changed, 73 insertions(+), 7 deletions(-) create mode 100644 tests/test_stage_timings.py 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_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()) From 3e55d6893107955598893067f1f530d415641365 Mon Sep 17 00:00:00 2001 From: andig Date: Sun, 23 Aug 2026 10:45:20 +0200 Subject: [PATCH 2/2] test: lock the solve log line's key names The dashboard's KQL queries parse this line, so a renamed key breaks production attribution silently. One request through the test client, one line on stdout, keys and stage names pinned. Co-Authored-By: Claude Fable 5 --- tests/test_app.py | 17 +++++++++++++++++ 1 file changed, 17 insertions(+) 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()