feat: log where each solve spent its clock

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:

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

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()

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())