source running command start timestamps

This commit is contained in:
Jeremy Rose
2026-05-01 11:36:20 -07:00
parent 70dbf4ab46
commit 1aed46863c
5 changed files with 30 additions and 19 deletions

View File

@@ -2443,6 +2443,7 @@ mod tests {
call_id: "exec-call".into(),
process_id: Some("pid-1".into()),
turn_id: turn_id.to_string(),
started_at_ms: None,
command: vec!["sleep".into(), "100".into()],
cwd: test_path_buf("/tmp").abs(),
parsed_cmd: vec![ParsedCommand::Unknown {

View File

@@ -1,5 +1,6 @@
use crate::outgoing_message::ConnectionId;
use crate::outgoing_message::ConnectionRequestId;
use chrono::Utc;
use codex_app_server_protocol::CommandExecutionStatus;
use codex_app_server_protocol::RequestId;
use codex_app_server_protocol::ThreadGoal;
@@ -18,7 +19,6 @@ use std::collections::HashMap;
use std::collections::HashSet;
use std::sync::Arc;
use std::sync::Weak;
use std::time::Instant;
use tokio::sync::Mutex;
use tokio::sync::mpsc;
use tokio::sync::oneshot;
@@ -27,8 +27,12 @@ use tracing::error;
type PendingInterruptQueue = Vec<ConnectionRequestId>;
fn elapsed_duration_ms(duration: std::time::Duration) -> i64 {
i64::try_from(duration.as_millis()).unwrap_or(i64::MAX)
fn now_unix_timestamp_ms() -> i64 {
Utc::now().timestamp_millis()
}
fn elapsed_duration_ms(started_at_ms: i64) -> i64 {
now_unix_timestamp_ms().saturating_sub(started_at_ms)
}
pub(crate) struct PendingThreadResumeRequest {
@@ -81,7 +85,7 @@ pub(crate) struct ThreadState {
pub(crate) cancel_tx: Option<oneshot::Sender<()>>,
pub(crate) experimental_raw_events: bool,
pub(crate) listener_generation: u64,
running_command_started_at: HashMap<String, Instant>,
running_command_started_at_ms: HashMap<String, i64>,
listener_command_tx: Option<mpsc::UnboundedSender<ThreadListenerCommand>>,
current_turn_history: ThreadHistoryBuilder,
listener_thread: Option<Weak<CodexThread>>,
@@ -147,10 +151,10 @@ impl ThreadState {
else {
continue;
};
let Some(started_at) = self.running_command_started_at.get(id) else {
let Some(started_at) = self.running_command_started_at_ms.get(id) else {
continue;
};
*duration_ms = Some(elapsed_duration_ms(started_at.elapsed()));
*duration_ms = Some(elapsed_duration_ms(*started_at));
}
}
}
@@ -161,12 +165,13 @@ impl ThreadState {
self.turn_summary.started_at = payload.started_at;
}
EventMsg::ExecCommandBegin(payload) => {
self.running_command_started_at
.entry(payload.call_id.clone())
.or_insert_with(Instant::now);
self.running_command_started_at_ms.insert(
payload.call_id.clone(),
payload.started_at_ms.unwrap_or_else(now_unix_timestamp_ms),
);
}
EventMsg::ExecCommandEnd(payload) => {
self.running_command_started_at.remove(&payload.call_id);
self.running_command_started_at_ms.remove(&payload.call_id);
}
_ => {}
}
@@ -468,7 +473,6 @@ mod tests {
use codex_utils_absolute_path::AbsolutePathBuf;
use pretty_assertions::assert_eq;
use std::path::PathBuf;
use std::time::Duration;
fn test_absolute_path(path: &str) -> AbsolutePathBuf {
AbsolutePathBuf::try_from(PathBuf::from(path)).expect("path must be absolute")
@@ -477,10 +481,9 @@ mod tests {
#[test]
fn refreshes_running_command_durations_for_live_turns() {
let mut state = ThreadState::default();
state.running_command_started_at.insert(
"exec-call".into(),
Instant::now() - Duration::from_millis(1_500),
);
state
.running_command_started_at_ms
.insert("exec-call".into(), now_unix_timestamp_ms() - 1_500);
let mut turns = vec![Turn {
id: "turn-1".into(),
items: vec![ThreadItem::CommandExecution {
@@ -516,10 +519,9 @@ mod tests {
#[test]
fn leaves_completed_command_duration_unchanged() {
let mut state = ThreadState::default();
state.running_command_started_at.insert(
"exec-call".into(),
Instant::now() - Duration::from_millis(1_500),
);
state
.running_command_started_at_ms
.insert("exec-call".into(), now_unix_timestamp_ms() - 1_500);
let mut turns = vec![Turn {
id: "turn-1".into(),
items: vec![ThreadItem::CommandExecution {

View File

@@ -1,6 +1,7 @@
use std::sync::Arc;
use std::time::Duration;
use chrono::Utc;
use codex_async_utils::CancelErr;
use codex_async_utils::OrCancelExt;
use codex_network_proxy::PROXY_ACTIVE_ENV_KEY;
@@ -164,6 +165,7 @@ pub(crate) async fn execute_user_shell_command(
call_id: call_id.clone(),
process_id: None,
turn_id: turn_context.sub_id.clone(),
started_at_ms: Some(Utc::now().timestamp_millis()),
command: display_command.clone(),
cwd: cwd.clone(),
parsed_cmd: parsed_cmd.clone(),

View File

@@ -3,6 +3,7 @@ use crate::session::session::Session;
use crate::session::turn_context::TurnContext;
use crate::tools::context::SharedTurnDiffTracker;
use crate::tools::sandboxing::ToolError;
use chrono::Utc;
use codex_protocol::error::CodexErr;
use codex_protocol::error::SandboxErr;
use codex_protocol::exec_output::ExecToolCallOutput;
@@ -77,6 +78,7 @@ pub(crate) async fn emit_exec_command_begin(
call_id: ctx.call_id.to_string(),
process_id: process_id.map(str::to_owned),
turn_id: ctx.turn.sub_id.clone(),
started_at_ms: Some(Utc::now().timestamp_millis()),
command: command.to_vec(),
cwd: cwd.clone(),
parsed_cmd: parsed_cmd.to_vec(),

View File

@@ -3057,6 +3057,10 @@ pub struct ExecCommandBeginEvent {
pub process_id: Option<String>,
/// Turn ID that this command belongs to.
pub turn_id: String,
/// Unix timestamp (in milliseconds) when command execution started.
#[serde(default, skip_serializing_if = "Option::is_none")]
#[ts(type = "number | null", optional)]
pub started_at_ms: Option<i64>,
/// The command to be executed.
pub command: Vec<String>,
/// The command's working directory if not the default cwd for the agent.