Report what the server spent, beside the answer it sends - #725
Report what the server spent, beside the answer it sends#725v-positronic wants to merge 1 commit into
Conversation
A client times its own round trip and cannot see inside it: network and the server's own work arrive as one number. The server now reports what it spent — decode, queue, inference, encode, and the span bracketing them — in the answer's `timing` block, and the client stamps those onto the `policy.infer` span that timed the trip. Subtracting one from the other leaves the network, and both sides measured only their own elapsed time, so no clock has to agree with any other. A server that reports nothing leaves the round trip undivided, which is what a deployment that has not taken this change does. Ticket: Positronic-Robotics/internal#1168 #refs
ace4951 to
0a0c1ef
Compare
![chatgpt-codex-connector[bot]](https://avatars.githubusercontent.com/in/1144995?s=60&v=4){kind=small}
There was a problem hiding this comment.
💡 Codex Review
Here are some automated review suggestions for this pull request.
Reviewed commit: ace495136c
ℹ️ About Codex in GitHub
Codex has been enabled to automatically review pull requests in this repo. Reviews are triggered when you
- Open a pull request for review
- Mark a draft as ready
- Comment "@codex review".
If Codex has suggestions, it will comment; otherwise it will react with 👍.
When you sign up for Codex through ChatGPT, Codex can also answer questions or update the PR, like "@codex address that feedback".
| with timing.phase(protocol.TIMING_ENCODE): | ||
| answer = serialise({protocol.RESULT: actions, protocol.TIMING: timing.report()}) |
There was a problem hiding this comment.
Calling timing.report() while constructing the object passed to serialise() returns a copy before the TIMING_ENCODE phase closes, so every transmitted timing block lacks encode_ms; served_ms also stops before response serialization and send_bytes(). Consequently, subtracting served_ms from the client round trip systematically attributes server-side encoding and sending to the network, especially for large action payloads. Capture those costs before producing the final report, or redefine the wire contract so it does not claim they are included.
Useful? React with 👍 / 👎.
| response = deserialise(received) | ||
| self.served_timing = response.get(protocol.TIMING) or {} if isinstance(response, dict) else {} |
There was a problem hiding this comment.
After one successful inference, a later timeout, send failure, or deserialization failure exits before this assignment, leaving served_timing populated from the previous response. Because round_trip() records its span in a finally block, the failed round trip is then stamped with stale server timings, corrupting telemetry for partial and failed episodes. Reset the field before beginning each inference and populate it only after decoding the current response.
Useful? React with 👍 / 👎.
| # What the server reported spending on the last inference, for the caller that times the round | ||
| # trip. Empty against a server that reports nothing, which leaves that round trip undivided. |
There was a problem hiding this comment.
Rule diff-comments violated:
The comment on served_timing explains what its caller does with the value instead of stating the field's local meaning. Describe it as the timing block from the most recently decoded inference response, empty when absent.
AGENTS.md reference: AGENTS.md:L14-L22
Useful? React with 👍 / 👎.
| # The server's own durations ride on the span that timed the round trip holding them, so the | ||
| # reduce subtracts one from the other and reads the network off two clocks that never agree. |
There was a problem hiding this comment.
Rule diff-comments violated:
This comment describes what the downstream reducer supposedly does; repository-wide inspection of positronic/cli/eval/timing_report.py also shows that it does not currently perform this subtraction. State only the local invariant—that server timing fields are copied onto the round-trip span under the served. prefix—or remove the comment.
AGENTS.md reference: AGENTS.md:L14-L22
Useful? React with 👍 / 👎.
1 participant
What
Every answer now carries a
timingblock:served_ms, bracketingdecode_ms,queued_ms,infer_msandencode_ms, in milliseconds on the server's own clock. The client reads them off the response and stamps them onto thepolicy.inferspan under aserved.prefix, where the span that timed the round trip already sits.Why
A client times its own round trip and cannot see inside it: the network and the server's own work arrive as one number. On a live rollout that number is 1633 ms, of which our socket write is 0.9 ms — so essentially all of it is "sent, waiting", and nothing on our side can say how much is wire and how much is theirs.
Subtracting the server's
served_msfrom the client's round trip leaves the network. This needs no clock synchronisation, which is the point of the design: each side measures only its own elapsed time, and two clocks that disagree on the time of day still agree on how long something took. The alternative — synchronising a rig against a serverless container over the public internet — buys an offset of unknown size that neither side can verify at the moment it matters.queued_msis separated frominfer_msdeliberately: a request waiting for the inference slot is a queue, not compute, and a client that could not tell them apart would read a busy server as a slow model.A server that reports nothing leaves the round trip undivided, which is what any deployment that has not taken this change does. The client reads an absent block as an empty one and stamps nothing.
Verification
uv run --extra telemetry pytest positronic --ignore=positronic/simulator— 1254 passed, 8 skipped.ruff checkandruff format --checkclean.Not yet exercised end to end against a partner's server, because the partner has to take the change first — that is what makes the numbers useful rather than what makes them correct.
Base and review
This is based on
client-latency-spans(positronic#722), not onmain, and genuinely depends on it: the client half stamps span names that branch introduces. Codex only auto-reviews pull requests targeting the default branch, so this one likely needs retargeting tomainonce #722 merges.Refs
Positronic-Robotics/internal#1168.