Skip to content

feat: log where each solve spent its clock - #141

Merged
andig merged 2 commits into
fix/reserve-the-tie-break-slicefrom
feat/stage-timing-logs
Aug 23, 2026
Merged

andig merged 2 commits into
fix/reserve-the-tie-break-slicefrom
feat/stage-timing-logs

Conversation

@andig

@andig andig commented Aug 22, 2026

Copy link
Copy Markdown
Member

Why

The p95 regression after the tie-break reserve deploy was diagnosed by reading code, not by measurement: the access log only carries the total response time, and the slow-request dump only catches requests that already exhausted the limit. Nothing in production says how the clock splits between probe, cost stage and tie break.

What

One JSON line per request on stdout, which Container Apps ships to Log Analytics:

{"solve": {"elapsed": 1.62, "stages": {"build": 0.21, "cost": 0.83, "tie_break": 0.55}, "path": "split", "preferences": "LP Optimal, MILP Optimal", "status": "Optimal", "steps": 245}}
  • Optimizer.stage_seconds: wall clock per stage via a small contextmanager around the existing solve calls. Accumulates rather than assigns - the tie break is two solves (LP floor, MILP proper) under one name. An absent stage is an absent key, not a zero, so a joint solve is distinguishable from a split that ran out of clock.
  • app.py: prints the line after solve(), mirroring the dump_slow_request style.

Per-stage percentiles split by solve path are then a KQL query over ContainerAppConsoleLogs. Ingestion cost is ~50 MB/day at current traffic.

Skipped: Prometheus endpoint (no scraper in Container Apps), sampling (volume trivial), settings toggle (add only if ingestion cost ever bites).

Stacked on #140, so the diff shows only this change.

🤖 Generated with Claude Code

andig and others added 2 commits August 22, 2026 14:37
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 <noreply@anthropic.com>
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 <noreply@anthropic.com>
@andig
andig merged commit 17a1e10 into fix/reserve-the-tie-break-slice Aug 23, 2026
@andig
andig deleted the feat/stage-timing-logs branch August 23, 2026 09:18
andig added a commit that referenced this pull request Aug 23, 2026
…eat it

Production logs after #141: the MILP consumes its full 4 s slice on essentially
every split (tb p50 4.06 s, p95 4.28 s) and improves the schedule on only half
of them. Measured over 16 captured splits, everything it finds arrives within
2.5 s - capping there returned the identical preference value on 15 of 16, the
16th lost 1.7e-6, and cuts-off lost quality on 6 so it stays on. The rest of
the slice bought proof, not schedule, and every deep tail request now gets it
back as response time (median elapsed 10.05 s to 8.66 s on the sample).

PREFERENCE_TIME_SHARE keeps reserving 0.4: that is what the cost stage may not
eat, and shrinking it is a separate decision about the cost stage's own budget.
Requests without a time limit stay uncapped.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant