feat(agent): record per-request timings with --request-events-jsonl

Merged
FE
2d ago
+632-59

batchbench-agent reports only aggregate latency percentiles and per-trajectory lifecycle events, so a replayed request cannot be compared with the latency production recorded for the same source request. --request-events-jsonl <PATH> writes one JSON line per request (one per manifest request, or per synthetic invocation), success or failure, when the run ends.

Record

{"trajectory_id":"t-1","agent_id":0,"invocation":1,"sent_at_ms":0.27,"ttft_ms":62.72,"last_token_ms":133.24,"e2e_ms":134.13,"tpot_ms":23.51,"prompt_tokens":8,"completion_tokens":4,"cached_tokens":6,"attempts":1,"status":"ok","error":null,"http_status":200}
{"trajectory_id":"t-1","agent_id":0,"invocation":3,"sent_at_ms":251.24,"ttft_ms":null,"last_token_ms":null,"e2e_ms":3.93,"tpot_ms":null,"prompt_tokens":null,"completion_tokens":null,"cached_tokens":null,"attempts":1,"status":"error","error":"request failed (503 Service Unavailable) busy","http_status":503}
  • sent_at_ms: start of the first attempt, on the run clock that --agent-events-jsonl uses (closed loop: after the initial prompts are prepared; open loop: the admission clock).
  • ttft_ms / last_token_ms: from the first attempt's start to the first and last streamed chunks whose delta carries non-empty content, reasoning_content or tool_calls. The usage-only final chunk does not count. Null for non-streamed requests or when no such chunk arrived. For a retried request, the chunks come from the attempt that succeeded, but the times are still measured from the first attempt's start, which is the latency the client saw.
  • e2e_ms: the existing per-request latency (first attempt start to success, or to the last attempt's failure).
  • tpot_ms = (last_token_ms - ttft_ms) / (completion_tokens - 1) when completion_tokens >= 2, else null.
  • cached_tokens: usage.prompt_tokens_details.cached_tokens, null when absent.
  • http_status: status of the last attempt's response, null when no response arrived (connect error, timeout before headers).

A trajectory still stops at its first failed request; that request now also gets a record.

Changes

  • StreamedCompletion::absorb takes the arrival time of the network chunk a payload came in and keeps the first and last arrival times of chunks that carry output. Nothing else in the streaming path changes.
  • single_attempt is split into send_request and read_response so it can return the response status alongside the result. request_with_retries returns a RequestOutcome (first-attempt start, latency, attempts, last status, result).
  • The run-start Instant (closed-loop start, open-loop shared.start) is passed to the workers. Each worker collects AgentRequestRecords like failures, the accumulator merges them, and the report sorts them by agent and invocation. They are collected only when AgentLoopConfig::with_request_records(true) is set, which the CLI does when the option is given.
  • agent_cli writes the file with a shared write_jsonl helper (now also used by --agent-events-jsonl), and the results CSV gets a request_events_jsonl column next to agent_events_jsonl.
  • README: the option and its field list, in the Report section.

Testing

  • cargo test --manifest-path rust/Cargo.toml: 74 passed (4 new). The new tests cover:
    • SSE token timing: a role-only chunk with empty content, a reasoning-only first token, a tool-call delta as the last token, an empty tool_calls delta, and a usage-only final chunk.
    • The tpot formula.
    • JSONL output, with exact objects for an ok record and an error record.
    • An end-to-end run against a scripted local HTTP server: a 503 then a streamed 200 (attempts 2, cached tokens, ttft <= last token <= e2e), a second streamed request, then two 500s (an error record with status 500, after which the trajectory ends).
  • cargo clippy --all-targets: clean.
  • Python, as CI runs it (maturin develop, then python -m unittest discover -s tests): 19 passed, including the exported-manifest dry run through batchbench-agent. The CI smoke tests (Python API and CLI) also pass.
  • A manual CLI run against a local streaming mock server (with --results-csv) produced the records shown above.

šŸ¤– Generated with Claude Code

https://claude.ai/code/session_01VDPqeFzGgF3vkuiyimwMxX