JSON/YAML envelope `timing.duration_ms` always 0 — command execution time never measured #4106

New issue

Open

opened 2026-04-06 10:21:29 +00:00 by hurui200320 · 1 comment

hurui200320 commented

2026-04-06 10:21:29 +00:00

Member

Metadata

Branch: fix/cli-timing-duration-ms-measurement
Commit Message: fix(cli): measure wall-clock duration and populate timing.duration_ms in build_envelope()
Milestone: None (backlog)
Parent Epic: #933

Description

Background

When the JSON/YAML output envelope was introduced in src/cleveragents/cli/formatting.py
(tracked by #3431, closed, and #3618, open), the timing field was added to the envelope
structure but no actual wall-clock measurement was implemented. As a result,
timing.duration_ms is hardcoded to 0 for every command invocation.

The affected function is build_envelope() in
src/cleveragents/cli/formatting.py. It needs to accept a measured duration
and propagate it into the timing.duration_ms field. The CLI entry points must
capture time.monotonic() before and after command execution and pass the
elapsed milliseconds to build_envelope().

Current Behavior

timing.duration_ms is always 0 regardless of which command is run or how
long it actually takes:

agents --format json version      # "duration_ms": 0
agents --format json info         # "duration_ms": 0
agents --format json diagnostics  # "duration_ms": 0

Expected Behavior

Per the specification, timing.duration_ms must reflect the actual wall-clock
time of command execution. For example:

{ "timing": { "duration_ms": 8 } }    // agents version
{ "timing": { "duration_ms": 18 } }   // agents info
{ "timing": { "duration_ms": 600 } }  // agents diagnostics

Acceptance Criteria

timing.duration_ms in JSON/YAML output is a positive integer equal to the
measured wall-clock duration of the command in milliseconds
The measurement uses time.monotonic() (or equivalent) for accuracy
build_envelope() accepts a duration_ms: int parameter and stores it in
timing.duration_ms
All CLI entry points that call build_envelope() pass the measured duration
duration_ms is never 0 for any real command execution (unless the command
genuinely completes in under 0.5 ms, which is not expected in practice)

Subtasks

Add duration_ms: int parameter to build_envelope() in
src/cleveragents/cli/formatting.py
Record time.monotonic() start time at CLI entry (before command
dispatch) and compute elapsed milliseconds after command completes
Pass the computed duration_ms to build_envelope() at every call site
Tests: add/update Behave unit tests verifying timing.duration_ms is a
positive integer in JSON/YAML output for version, info, and diagnostics
commands
Run nox (all default sessions), fix any errors
Verify coverage >= 97% via nox -s coverage_report

Definition of Done

All subtasks above are completed and checked off
A Git commit is created where the first line of the commit message
matches the Commit Message in Metadata exactly
The commit is pushed to the branch from Metadata
PR submitted to master, reviewed, and merged
All nox stages pass
Coverage >= 97%

## Metadata - **Branch**: `fix/cli-timing-duration-ms-measurement` - **Commit Message**: `fix(cli): measure wall-clock duration and populate timing.duration_ms in build_envelope()` - **Milestone**: None (backlog) - **Parent Epic**: #933 ## Description ### Background When the JSON/YAML output envelope was introduced in `src/cleveragents/cli/formatting.py` (tracked by #3431, closed, and #3618, open), the `timing` field was added to the envelope structure but no actual wall-clock measurement was implemented. As a result, `timing.duration_ms` is hardcoded to `0` for every command invocation. The affected function is `build_envelope()` in `src/cleveragents/cli/formatting.py`. It needs to accept a measured duration and propagate it into the `timing.duration_ms` field. The CLI entry points must capture `time.monotonic()` before and after command execution and pass the elapsed milliseconds to `build_envelope()`. ### Current Behavior `timing.duration_ms` is always `0` regardless of which command is run or how long it actually takes: ``` agents --format json version # "duration_ms": 0 agents --format json info # "duration_ms": 0 agents --format json diagnostics # "duration_ms": 0 ``` ### Expected Behavior Per the specification, `timing.duration_ms` must reflect the actual wall-clock time of command execution. For example: ```json { "timing": { "duration_ms": 8 } } // agents version { "timing": { "duration_ms": 18 } } // agents info { "timing": { "duration_ms": 600 } } // agents diagnostics ``` ### Acceptance Criteria - `timing.duration_ms` in JSON/YAML output is a positive integer equal to the measured wall-clock duration of the command in milliseconds - The measurement uses `time.monotonic()` (or equivalent) for accuracy - `build_envelope()` accepts a `duration_ms: int` parameter and stores it in `timing.duration_ms` - All CLI entry points that call `build_envelope()` pass the measured duration - `duration_ms` is never `0` for any real command execution (unless the command genuinely completes in under 0.5 ms, which is not expected in practice) ## Subtasks - [ ] Add `duration_ms: int` parameter to `build_envelope()` in `src/cleveragents/cli/formatting.py` - [ ] Record `time.monotonic()` start time at CLI entry (before command dispatch) and compute elapsed milliseconds after command completes - [ ] Pass the computed `duration_ms` to `build_envelope()` at every call site - [ ] Tests: add/update Behave unit tests verifying `timing.duration_ms` is a positive integer in JSON/YAML output for `version`, `info`, and `diagnostics` commands - [ ] Run `nox` (all default sessions), fix any errors - [ ] Verify coverage >= 97% via `nox -s coverage_report` ## Definition of Done - [ ] All subtasks above are completed and checked off - [ ] A Git commit is created where the first line of the commit message matches the Commit Message in Metadata exactly - [ ] The commit is pushed to the branch from Metadata - [ ] PR submitted to `master`, reviewed, and merged - [ ] All nox stages pass - [ ] Coverage >= 97%

freemo commented

2026-04-06 10:22:10 +00:00

Owner

Thank you for filing this issue, @hurui200320. The timing.duration_ms always being 0 is a clear spec violation that affects all JSON/YAML output.

Triage assessment:

✅ Clear title and description
✅ Current vs expected behavior with examples
✅ Metadata (commit message, branch)
✅ Subtasks and Definition of Done
Priority: Priority/Backlog is appropriate — timing data is useful but not blocking
Story Points: S (2 points) — requires adding time.monotonic() measurement at CLI entry points and threading the duration through to build_envelope()
Parent Epic: #933 is appropriate

This issue is ready for verification and implementation.

Automated by CleverAgents Bot
Supervisor: Human Liaison | Agent: ca-human-liaison

Thank you for filing this issue, @hurui200320. The `timing.duration_ms` always being 0 is a clear spec violation that affects all JSON/YAML output. **Triage assessment:** - ✅ Clear title and description - ✅ Current vs expected behavior with examples - ✅ Metadata (commit message, branch) - ✅ Subtasks and Definition of Done - **Priority**: `Priority/Backlog` is appropriate — timing data is useful but not blocking - **Story Points**: S (2 points) — requires adding `time.monotonic()` measurement at CLI entry points and threading the duration through to `build_envelope()` - **Parent Epic**: #933 is appropriate This issue is ready for verification and implementation. --- **Automated by CleverAgents Bot** Supervisor: Human Liaison | Agent: ca-human-liaison

freemo added the

Points

label

2026-04-06 10:26:46 +00:00

freemo referenced this issue

2026-04-06 10:29:08 +00:00

[Automated] CleverAgents Build Session - 2026-04-06 #3775

freemo referenced this issue

2026-04-06 10:40:13 +00:00

[Automated] CleverAgents Build Session - 2026-04-06 #3775

freemo referenced this issue

2026-04-06 10:51:36 +00:00