mirror of
https://github.com/pchuan98/codex.git
synced 2026-07-01 00:31:56 +08:00
TUI: use cumulative turn duration for worked-for separator (#19929)
## Why Fixes #19814. The TUI's current `Worked for ...` timing behavior is a leftover from #9599. At that point, models could emit multiple assistant messages in one turn for preambles/commentary, but the TUI did not yet have a reliable signal that an assistant message was the final answer when it started streaming. To avoid showing an ever-growing elapsed time on each preamble separator, #9599 made the separator timer incremental by tracking elapsed time since the previous separator. That workaround is no longer the right model for the final completed-turn display. Since then, #16638 added protocol-native turn timing, including `duration_ms` on turn completion. With that cumulative duration available at the point where the TUI renders the completed-turn separator, the UI can show the actual turn duration directly instead of carrying per-separator timing state. ## What Changed - Thread `duration_ms` into `ChatWidget::on_task_complete` from both legacy `TurnCompleteEvent` handling and app-server `TurnCompleted` notifications. - Use `duration_ms` for the final `Worked for ...` separator, falling back to the status indicator timer only when the protocol duration is unavailable. - Keep mid-turn separators before later assistant text as plain visual dividers instead of clocked `Worked for ...` separators. - Remove the old incremental separator timer state and helper (`last_separator_elapsed_secs` / `worked_elapsed_from`). - Add a snapshot regression test for a turn that runs a command and then completes with a final answer, verifying the final separator uses the cumulative turn duration. ## Verification - `cargo test -p codex-tui final_worked_for_uses_cumulative_turn_duration_snapshot` - `just fix -p codex-tui` Manual repro prompt: ```text Manual timing repro. First send a short preamble/commentary sentence before using tools. Then run exactly this shell command: sleep 75; echo MANUAL_TIMING_DONE. After the command finishes, give a final answer that says "done". Do not skip the preamble. ``` After this change, the mid-turn break before the final answer should be a plain divider, and the final completed-turn separator should show `Worked for ...` using the cumulative turn duration. Before: <img width="414" height="102" alt="Screenshot 2026-04-27 at 10 09 01 PM" src="https://github.com/user-attachments/assets/b9e2ce01-2460-40e4-a5c4-c9ba8add2557" /> After: <img width="485" height="149" alt="Screenshot 2026-04-27 at 10 09 07 PM" src="https://github.com/user-attachments/assets/d24089ae-d4e2-41b6-b966-07c98706ead4" />
This commit is contained in:
committed by
GitHub
Unverified
parent
5b7d6f5c4f
commit
087c9c1f1f
@@ -1002,13 +1002,12 @@ pub(crate) struct ChatWidget {
|
||||
// Whether the next streamed assistant content should be preceded by a final message separator.
|
||||
//
|
||||
// This is set whenever we insert a visible history cell that conceptually belongs to a turn.
|
||||
// The separator itself is only rendered if the turn recorded "work" activity (see
|
||||
// `had_work_activity`).
|
||||
// The separator itself is only rendered if the turn recorded "work" activity.
|
||||
needs_final_message_separator: bool,
|
||||
// Whether the current turn performed "work" (exec commands, MCP tool calls, patch applications).
|
||||
//
|
||||
// This gates rendering of the "Worked for …" separator so purely conversational turns don't
|
||||
// show an empty divider. It is reset when the separator is emitted.
|
||||
// show an empty divider.
|
||||
had_work_activity: bool,
|
||||
// Whether the current turn emitted a plan update.
|
||||
saw_plan_update_this_turn: bool,
|
||||
@@ -1022,11 +1021,6 @@ pub(crate) struct ChatWidget {
|
||||
plan_delta_buffer: String,
|
||||
// True while a plan item is streaming.
|
||||
plan_item_active: bool,
|
||||
// Status-indicator elapsed seconds captured at the last emitted final-message separator.
|
||||
//
|
||||
// This lets the separator show per-chunk work time (since the previous separator) rather than
|
||||
// the total task-running time reported by the status indicator.
|
||||
last_separator_elapsed_secs: Option<u64>,
|
||||
// Runtime metrics accumulated across delta snapshots for the active turn.
|
||||
turn_runtime_metrics: RuntimeMetricsSummary,
|
||||
last_rendered_width: std::cell::Cell<Option<usize>>,
|
||||
@@ -2727,6 +2721,7 @@ impl ChatWidget {
|
||||
self.saw_copy_source_this_turn = false;
|
||||
self.saw_plan_update_this_turn = false;
|
||||
self.saw_plan_item_this_turn = false;
|
||||
self.had_work_activity = false;
|
||||
self.latest_proposed_plan_markdown = None;
|
||||
self.plan_delta_buffer.clear();
|
||||
self.plan_item_active = false;
|
||||
@@ -2752,7 +2747,12 @@ impl ChatWidget {
|
||||
self.request_redraw();
|
||||
}
|
||||
|
||||
fn on_task_complete(&mut self, last_agent_message: Option<String>, from_replay: bool) {
|
||||
fn on_task_complete(
|
||||
&mut self,
|
||||
last_agent_message: Option<String>,
|
||||
duration_ms: Option<i64>,
|
||||
from_replay: bool,
|
||||
) {
|
||||
self.submit_pending_steers_after_interrupt = false;
|
||||
// Use `last_agent_message` from the turn-complete notification as the copy
|
||||
// source only when no earlier item-level event (AgentMessageItem, plan
|
||||
@@ -2797,13 +2797,18 @@ impl ChatWidget {
|
||||
self.collect_runtime_metrics_delta();
|
||||
let runtime_metrics =
|
||||
(!self.turn_runtime_metrics.is_empty()).then_some(self.turn_runtime_metrics);
|
||||
let show_work_separator = self.needs_final_message_separator && self.had_work_activity;
|
||||
let show_work_separator = self.had_work_activity
|
||||
&& (self.needs_final_message_separator || runtime_metrics.is_some());
|
||||
if show_work_separator || runtime_metrics.is_some() {
|
||||
let elapsed_seconds = if show_work_separator {
|
||||
self.bottom_pane
|
||||
.status_widget()
|
||||
.map(super::status_indicator_widget::StatusIndicatorWidget::elapsed_seconds)
|
||||
.map(|current| self.worked_elapsed_from(current))
|
||||
duration_ms
|
||||
.and_then(|duration_ms| u64::try_from(duration_ms).ok())
|
||||
.map(|duration_ms| duration_ms / 1_000)
|
||||
.or_else(|| {
|
||||
self.bottom_pane
|
||||
.status_widget()
|
||||
.map(super::status_indicator_widget::StatusIndicatorWidget::elapsed_seconds)
|
||||
})
|
||||
} else {
|
||||
None
|
||||
};
|
||||
@@ -5034,17 +5039,10 @@ impl ChatWidget {
|
||||
// If the previous turn inserted non-stream history (exec output, patch status, MCP
|
||||
// calls), render a separator before starting the next streamed assistant message.
|
||||
if self.needs_final_message_separator && self.had_work_activity {
|
||||
let elapsed_seconds = self
|
||||
.bottom_pane
|
||||
.status_widget()
|
||||
.map(super::status_indicator_widget::StatusIndicatorWidget::elapsed_seconds)
|
||||
.map(|current| self.worked_elapsed_from(current));
|
||||
self.add_to_history(history_cell::FinalMessageSeparator::new(
|
||||
elapsed_seconds,
|
||||
/*runtime_metrics*/ None,
|
||||
/*elapsed_seconds*/ None, /*runtime_metrics*/ None,
|
||||
));
|
||||
self.needs_final_message_separator = false;
|
||||
self.had_work_activity = false;
|
||||
} else if self.needs_final_message_separator {
|
||||
// Reset the flag even if we don't show separator (no work was done)
|
||||
self.needs_final_message_separator = false;
|
||||
@@ -5063,17 +5061,6 @@ impl ChatWidget {
|
||||
self.request_redraw();
|
||||
}
|
||||
|
||||
fn worked_elapsed_from(&mut self, current_elapsed: u64) -> u64 {
|
||||
let baseline = match self.last_separator_elapsed_secs {
|
||||
Some(last) if current_elapsed < last => 0,
|
||||
Some(last) => last,
|
||||
None => 0,
|
||||
};
|
||||
let elapsed = current_elapsed.saturating_sub(baseline);
|
||||
self.last_separator_elapsed_secs = Some(current_elapsed);
|
||||
elapsed
|
||||
}
|
||||
|
||||
/// Finalizes an exec call while preserving the active exec cell grouping contract.
|
||||
///
|
||||
/// Exec begin/end events usually pair through `running_commands`, but unified exec can emit an
|
||||
@@ -5631,7 +5618,6 @@ impl ChatWidget {
|
||||
last_plan_progress: None,
|
||||
plan_delta_buffer: String::new(),
|
||||
plan_item_active: false,
|
||||
last_separator_elapsed_secs: None,
|
||||
turn_runtime_metrics: RuntimeMetricsSummary::default(),
|
||||
last_rendered_width: std::cell::Cell::new(None),
|
||||
feedback,
|
||||
@@ -7295,7 +7281,11 @@ impl ChatWidget {
|
||||
match notification.turn.status {
|
||||
TurnStatus::Completed => {
|
||||
self.last_non_retry_error = None;
|
||||
self.on_task_complete(/*last_agent_message*/ None, replay_kind.is_some())
|
||||
self.on_task_complete(
|
||||
/*last_agent_message*/ None,
|
||||
notification.turn.duration_ms,
|
||||
replay_kind.is_some(),
|
||||
)
|
||||
}
|
||||
TurnStatus::Interrupted => {
|
||||
self.last_non_retry_error = None;
|
||||
@@ -7646,9 +7636,11 @@ impl ChatWidget {
|
||||
}
|
||||
}
|
||||
EventMsg::TurnComplete(TurnCompleteEvent {
|
||||
last_agent_message, ..
|
||||
last_agent_message,
|
||||
duration_ms,
|
||||
..
|
||||
}) => {
|
||||
self.on_task_complete(last_agent_message, from_replay);
|
||||
self.on_task_complete(last_agent_message, duration_ms, from_replay);
|
||||
}
|
||||
EventMsg::TokenCount(ev) => {
|
||||
self.set_token_info(ev.info);
|
||||
|
||||
+12
@@ -0,0 +1,12 @@
|
||||
---
|
||||
source: tui/src/chatwidget/tests/exec_flow.rs
|
||||
expression: combined
|
||||
---
|
||||
• Ran echo preparing
|
||||
└ preparing
|
||||
|
||||
────────────────────────────────────────────────────────────────────────────────
|
||||
|
||||
• Final response.
|
||||
|
||||
─ Worked for 2m 05s ────────────────────────────────────────────────────────────
|
||||
@@ -598,7 +598,9 @@ async fn unified_exec_end_after_task_complete_is_suppressed() {
|
||||
);
|
||||
drain_insert_history(&mut rx);
|
||||
|
||||
chat.on_task_complete(/*last_agent_message*/ None, /*from_replay*/ false);
|
||||
chat.on_task_complete(
|
||||
/*last_agent_message*/ None, /*duration_ms*/ None, /*from_replay*/ false,
|
||||
);
|
||||
end_exec(&mut chat, begin, "", "", /*exit_code*/ 0);
|
||||
|
||||
let cells = drain_insert_history(&mut rx);
|
||||
@@ -612,7 +614,9 @@ async fn unified_exec_end_after_task_complete_is_suppressed() {
|
||||
async fn unified_exec_interaction_after_task_complete_is_suppressed() {
|
||||
let (mut chat, mut rx, _op_rx) = make_chatwidget_manual(/*model_override*/ None).await;
|
||||
chat.on_task_started();
|
||||
chat.on_task_complete(/*last_agent_message*/ None, /*from_replay*/ false);
|
||||
chat.on_task_complete(
|
||||
/*last_agent_message*/ None, /*duration_ms*/ None, /*from_replay*/ false,
|
||||
);
|
||||
|
||||
chat.handle_codex_event(Event {
|
||||
id: "call-1".to_string(),
|
||||
@@ -712,6 +716,56 @@ async fn unified_exec_wait_before_streamed_agent_message_snapshot() {
|
||||
assert_chatwidget_snapshot!("unified_exec_wait_before_streamed_agent_message", combined);
|
||||
}
|
||||
|
||||
#[tokio::test]
|
||||
async fn final_worked_for_uses_cumulative_turn_duration_snapshot() {
|
||||
let (mut chat, mut rx, _op_rx) = make_chatwidget_manual(/*model_override*/ None).await;
|
||||
chat.handle_codex_event(Event {
|
||||
id: "turn-1".into(),
|
||||
msg: EventMsg::TurnStarted(TurnStartedEvent {
|
||||
turn_id: "turn-1".to_string(),
|
||||
started_at: None,
|
||||
model_context_window: None,
|
||||
collaboration_mode_kind: ModeKind::Default,
|
||||
}),
|
||||
});
|
||||
|
||||
let exec = begin_exec_with_source(
|
||||
&mut chat,
|
||||
"call-1",
|
||||
"echo preparing",
|
||||
ExecCommandSource::Agent,
|
||||
);
|
||||
end_exec(&mut chat, exec, "preparing\n", "", /*exit_code*/ 0);
|
||||
|
||||
complete_assistant_message(
|
||||
&mut chat,
|
||||
"msg-final",
|
||||
"Final response.",
|
||||
Some(MessagePhase::FinalAnswer),
|
||||
);
|
||||
chat.handle_codex_event(Event {
|
||||
id: "turn-1".into(),
|
||||
msg: EventMsg::TurnComplete(TurnCompleteEvent {
|
||||
turn_id: "turn-1".to_string(),
|
||||
last_agent_message: Some("Final response.".to_string()),
|
||||
completed_at: None,
|
||||
duration_ms: Some(125_000),
|
||||
time_to_first_token_ms: None,
|
||||
}),
|
||||
});
|
||||
|
||||
let cells = drain_insert_history(&mut rx);
|
||||
let combined = cells
|
||||
.iter()
|
||||
.map(|lines| lines_to_single_string(lines))
|
||||
.collect::<String>();
|
||||
assert!(
|
||||
combined.contains("Worked for 2m 05s"),
|
||||
"expected final separator to use cumulative turn duration, got:\n{combined}"
|
||||
);
|
||||
assert_chatwidget_snapshot!("final_worked_for_uses_cumulative_turn_duration", combined);
|
||||
}
|
||||
|
||||
#[tokio::test]
|
||||
async fn unified_exec_wait_status_header_updates_on_late_command_display() {
|
||||
let (mut chat, _rx, _op_rx) = make_chatwidget_manual(/*model_override*/ None).await;
|
||||
|
||||
@@ -292,7 +292,6 @@ pub(super) async fn make_chatwidget_manual(
|
||||
last_plan_progress: None,
|
||||
plan_delta_buffer: String::new(),
|
||||
plan_item_active: false,
|
||||
last_separator_elapsed_secs: None,
|
||||
turn_runtime_metrics: RuntimeMetricsSummary::default(),
|
||||
last_rendered_width: std::cell::Cell::new(None),
|
||||
feedback: codex_feedback::CodexFeedback::new(),
|
||||
|
||||
@@ -771,7 +771,11 @@ async fn plan_implementation_popup_skips_when_messages_queued() {
|
||||
chat.bottom_pane.set_task_running(/*running*/ true);
|
||||
chat.queue_user_message("Queued message".into());
|
||||
|
||||
chat.on_task_complete(Some("Plan details".to_string()), /*from_replay*/ false);
|
||||
chat.on_task_complete(
|
||||
Some("Plan details".to_string()),
|
||||
/*duration_ms*/ None,
|
||||
/*from_replay*/ false,
|
||||
);
|
||||
|
||||
let popup = render_bottom_popup(&chat, /*width*/ 80);
|
||||
assert!(
|
||||
@@ -796,7 +800,9 @@ async fn plan_implementation_popup_skips_without_proposed_plan() {
|
||||
status: StepStatus::Pending,
|
||||
}],
|
||||
});
|
||||
chat.on_task_complete(/*last_agent_message*/ None, /*from_replay*/ false);
|
||||
chat.on_task_complete(
|
||||
/*last_agent_message*/ None, /*duration_ms*/ None, /*from_replay*/ false,
|
||||
);
|
||||
|
||||
let popup = render_bottom_popup(&chat, /*width*/ 80);
|
||||
assert!(
|
||||
@@ -816,7 +822,9 @@ async fn plan_implementation_popup_shows_after_proposed_plan_output() {
|
||||
chat.on_task_started();
|
||||
chat.on_plan_delta("- Step 1\n- Step 2\n".to_string());
|
||||
chat.on_plan_item_completed("- Step 1\n- Step 2\n".to_string());
|
||||
chat.on_task_complete(/*last_agent_message*/ None, /*from_replay*/ false);
|
||||
chat.on_task_complete(
|
||||
/*last_agent_message*/ None, /*duration_ms*/ None, /*from_replay*/ false,
|
||||
);
|
||||
|
||||
let popup = render_bottom_popup(&chat, /*width*/ 80);
|
||||
assert!(
|
||||
@@ -857,7 +865,9 @@ async fn plan_implementation_popup_skips_when_steer_follows_proposed_plan() {
|
||||
}
|
||||
|
||||
complete_user_message(&mut chat, "user-1", "Please continue.");
|
||||
chat.on_task_complete(/*last_agent_message*/ None, /*from_replay*/ false);
|
||||
chat.on_task_complete(
|
||||
/*last_agent_message*/ None, /*duration_ms*/ None, /*from_replay*/ false,
|
||||
);
|
||||
|
||||
let popup = render_bottom_popup(&chat, /*width*/ 80);
|
||||
assert!(
|
||||
@@ -902,7 +912,9 @@ async fn plan_implementation_popup_shows_after_new_plan_follows_steer() {
|
||||
"
|
||||
.to_string(),
|
||||
);
|
||||
chat.on_task_complete(/*last_agent_message*/ None, /*from_replay*/ false);
|
||||
chat.on_task_complete(
|
||||
/*last_agent_message*/ None, /*duration_ms*/ None, /*from_replay*/ false,
|
||||
);
|
||||
|
||||
let popup = render_bottom_popup(&chat, /*width*/ 80);
|
||||
assert!(
|
||||
@@ -929,7 +941,9 @@ async fn plan_implementation_popup_skips_when_rate_limit_prompt_pending() {
|
||||
}],
|
||||
});
|
||||
chat.on_rate_limit_snapshot(Some(snapshot(/*percent*/ 92.0)));
|
||||
chat.on_task_complete(/*last_agent_message*/ None, /*from_replay*/ false);
|
||||
chat.on_task_complete(
|
||||
/*last_agent_message*/ None, /*duration_ms*/ None, /*from_replay*/ false,
|
||||
);
|
||||
|
||||
let popup = render_bottom_popup(&chat, /*width*/ 80);
|
||||
assert!(
|
||||
|
||||
@@ -199,16 +199,6 @@ async fn prefetch_rate_limits_is_gated_on_chatgpt_auth_provider() {
|
||||
assert!(!chat.should_prefetch_rate_limits());
|
||||
}
|
||||
|
||||
#[tokio::test]
|
||||
async fn worked_elapsed_from_resets_when_timer_restarts() {
|
||||
let (mut chat, _rx, _op_rx) = make_chatwidget_manual(/*model_override*/ None).await;
|
||||
assert_eq!(chat.worked_elapsed_from(/*current_elapsed*/ 5), 5);
|
||||
assert_eq!(chat.worked_elapsed_from(/*current_elapsed*/ 9), 4);
|
||||
// Simulate status timer resetting (e.g., status indicator recreated for a new task).
|
||||
assert_eq!(chat.worked_elapsed_from(/*current_elapsed*/ 3), 3);
|
||||
assert_eq!(chat.worked_elapsed_from(/*current_elapsed*/ 7), 4);
|
||||
}
|
||||
|
||||
#[tokio::test]
|
||||
async fn rate_limit_warnings_emit_thresholds() {
|
||||
let mut state = RateLimitWarningState::default();
|
||||
@@ -1933,7 +1923,9 @@ async fn runtime_metrics_websocket_timing_logs_and_final_separator_sums_totals()
|
||||
.expect("expected websocket timing log");
|
||||
assert!(second_log.contains("TTFT: 80ms (iapi)"));
|
||||
|
||||
chat.on_task_complete(/*last_agent_message*/ None, /*from_replay*/ false);
|
||||
chat.on_task_complete(
|
||||
/*last_agent_message*/ None, /*duration_ms*/ None, /*from_replay*/ false,
|
||||
);
|
||||
let mut final_separator = None;
|
||||
while let Ok(event) = rx.try_recv() {
|
||||
if let AppEvent::InsertHistoryCell(cell) = event {
|
||||
|
||||
@@ -2825,7 +2825,7 @@ pub struct FinalMessageSeparator {
|
||||
runtime_metrics: Option<RuntimeMetricsSummary>,
|
||||
}
|
||||
impl FinalMessageSeparator {
|
||||
/// Creates a separator; `elapsed_seconds` typically comes from the status indicator timer.
|
||||
/// Creates a separator; completed turns should pass protocol turn duration when available.
|
||||
pub(crate) fn new(
|
||||
elapsed_seconds: Option<u64>,
|
||||
runtime_metrics: Option<RuntimeMetricsSummary>,
|
||||
|
||||
Reference in New Issue
Block a user