[eric] agents: active time is stall-capped inter-event work, so one wedged turn can't book 54 hours of 'agent time'

This commit is contained in:
ciregenz
2026-08-09 14:08:34 -07:00
parent 5eca1df72d
commit b47ad9c60f
4 changed files with 43 additions and 3 deletions
@@ -107,6 +107,13 @@ class TurnRunner(AgentManagerProtocol):
flight_recorder.crumb(session_id, "first-event", kind=type(message).__name__) flight_recorder.crumb(session_id, "first-event", kind=type(message).__name__)
turn.first_event = False turn.first_event = False
# Active-time ledger: count the gap since the previous event, capped so a stall
# (approval wait, paused workflow, provider backoff) can't book its wall-clock.
p_now_ts = time.time()
if turn.last_event_ts is not None:
turn.active_ms += int(min(p_now_ts - turn.last_event_ts, 30.0) * 1000)
turn.last_event_ts = p_now_ts
# Log system messages (MCP server status, errors, etc.) # Log system messages (MCP server status, errors, etc.)
if isinstance(message, SystemMessage): if isinstance(message, SystemMessage):
raw = message.__dict__ if hasattr(message, '__dict__') else str(message) raw = message.__dict__ if hasattr(message, '__dict__') else str(message)
@@ -45,6 +45,10 @@ class TurnState(BaseModel):
tool_count: int = 0 tool_count: int = 0
started_ts: Optional[float] = None started_ts: Optional[float] = None
total_ms: int = 0 total_ms: int = 0
# ACTIVE time: sum of inter-event deltas with stall gaps capped, so a turn that waits an hour
# on an approval or a wedged workflow books seconds of work, not the wall gap (ENG-189).
last_event_ts: Optional[float] = None
active_ms: int = 0
output_tokens: int = 0 output_tokens: int = 0
assistant_text_chars: int = 0 assistant_text_chars: int = 0
tool_input_chars: int = 0 tool_input_chars: int = 0
@@ -86,11 +86,14 @@ async def emit_consolidated_thinking(thinking: ThinkingState, turn: TurnState, s
pass pass
if turn.started_ts is not None: if turn.started_ts is not None:
turn.total_ms = int((time.time() - turn.started_ts) * 1000) turn.total_ms = int((time.time() - turn.started_ts) * 1000)
# Accumulate into session-level "agent active time" and the per-model breakdown so a session that spans multiple turns reports the total wall-clock time the agent was running. Per-model bucket uses the model active *now* (model can be switched mid-turn but the current value is the right attribution for the work just produced). # Session-level "agent active time" books ACTIVE ms (stall-capped inter-event deltas), not
# turn wall-clock: one 9-message session once booked 54 hours by waiting (ENG-189). Fallback
# to wall-clock only when no events accrued (a turn that died before its first event).
try: try:
session.agent_active_ms = int(getattr(session, "agent_active_ms", 0) or 0) + turn.total_ms p_worked_ms = turn.active_ms if turn.active_ms > 0 else turn.total_ms
session.agent_active_ms = int(getattr(session, "agent_active_ms", 0) or 0) + p_worked_ms
m = session.model or "unknown" m = session.model or "unknown"
session.time_per_model[m] = int(session.time_per_model.get(m, 0)) + turn.total_ms session.time_per_model[m] = int(session.time_per_model.get(m, 0)) + p_worked_ms
except Exception: except Exception:
pass pass
if thinking.msg_id is None: if thinking.msg_id is None:
+26
View File
@@ -0,0 +1,26 @@
"""ENG-189: agent_active_ms means time the agent was producing, not turn wall-clock. A stalled
gap between events books at most the 30s cap, so one wedged turn can't be 92% of the metric."""
from backend.apps.agents.manager.streaming.state import TurnState
def p_feed(turn: TurnState, ts: float) -> None:
if turn.last_event_ts is not None:
turn.active_ms += int(min(ts - turn.last_event_ts, 30.0) * 1000)
turn.last_event_ts = ts
def test_stalled_gap_books_the_cap_not_the_wall():
turn = TurnState()
p_feed(turn, 1000.0)
p_feed(turn, 1001.0) # 1s of work
p_feed(turn, 4601.0) # a 1-HOUR stall books 30s, not 3600s
p_feed(turn, 4602.5) # 1.5s more work
assert turn.active_ms == 1000 + 30_000 + 1500
def test_busy_turn_books_real_time():
turn = TurnState()
for i in range(11):
p_feed(turn, 100.0 + i * 0.5)
assert turn.active_ms == 5_000