From b47ad9c60f960dc8bcc8502426844e9c9285ea2c Mon Sep 17 00:00:00 2001 From: ciregenz Date: Sun, 9 Aug 2026 14:08:34 -0700 Subject: [PATCH] [eric] agents: active time is stall-capped inter-event work, so one wedged turn can't book 54 hours of 'agent time' --- backend/apps/agents/manager/run/TurnRunner.py | 7 +++++ .../apps/agents/manager/streaming/state.py | 4 +++ .../apps/agents/manager/streaming/thinking.py | 9 ++++--- backend/tests/test_agent_active_time.py | 26 +++++++++++++++++++ 4 files changed, 43 insertions(+), 3 deletions(-) create mode 100644 backend/tests/test_agent_active_time.py diff --git a/backend/apps/agents/manager/run/TurnRunner.py b/backend/apps/agents/manager/run/TurnRunner.py index cc247713..633017e4 100644 --- a/backend/apps/agents/manager/run/TurnRunner.py +++ b/backend/apps/agents/manager/run/TurnRunner.py @@ -107,6 +107,13 @@ class TurnRunner(AgentManagerProtocol): flight_recorder.crumb(session_id, "first-event", kind=type(message).__name__) 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.) if isinstance(message, SystemMessage): raw = message.__dict__ if hasattr(message, '__dict__') else str(message) diff --git a/backend/apps/agents/manager/streaming/state.py b/backend/apps/agents/manager/streaming/state.py index ae1b8562..77afc4fd 100644 --- a/backend/apps/agents/manager/streaming/state.py +++ b/backend/apps/agents/manager/streaming/state.py @@ -45,6 +45,10 @@ class TurnState(BaseModel): tool_count: int = 0 started_ts: Optional[float] = None 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 assistant_text_chars: int = 0 tool_input_chars: int = 0 diff --git a/backend/apps/agents/manager/streaming/thinking.py b/backend/apps/agents/manager/streaming/thinking.py index aa788e34..8d4c4635 100644 --- a/backend/apps/agents/manager/streaming/thinking.py +++ b/backend/apps/agents/manager/streaming/thinking.py @@ -86,11 +86,14 @@ async def emit_consolidated_thinking(thinking: ThinkingState, turn: TurnState, s pass if turn.started_ts is not None: 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: - 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" - 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: pass if thinking.msg_id is None: diff --git a/backend/tests/test_agent_active_time.py b/backend/tests/test_agent_active_time.py new file mode 100644 index 00000000..20fb2832 --- /dev/null +++ b/backend/tests/test_agent_active_time.py @@ -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