Skip to content

Commit d1b9d21

Browse files
authored
feat(engine): capture per-control execution duration [SAO-18023] (#283)
## Summary - Implements [SAO-18023: Capture per-control execution duration in observability events](https://splunk.atlassian.net/browse/SAO-18023). - Measures each completed control's condition evaluation with a monotonic clock and carries its duration through the evaluation response and Python SDK observability event. <img width="1920" height="1008" alt="image" src="https://github.com/user-attachments/assets/a75344d1-6849-48be-b62a-d80c4d829d2b" /> Both DevStacks ran the same control test. On the left, metrics.duration_ns is 0 because the previous version did not provide a per-control duration; it does not mean the control took zero time. On the right, PR #283 supplies the measured duration through the SDK and Agent Observability: 96,576,040 ns, displayed by Tiffany’s UI as 96.58 ms on the control row. ## Scope - User-facing/API changes: optional top-level `ControlMatch.execution_duration_ms` in `matches`, `non_matches`, and `errors`; TypeScript clients expose `executionDurationMs`. - Internal changes: engine timing, Python SDK event mapping, decorator serialization/debug logging, contract documentation, and regression coverage. - Timing includes condition traversal, visited leaves, evaluator work, and waiting for an evaluator concurrency slot. Control loading and request/response overhead are outside the measurement. - Completed results, including handled evaluation errors/timeouts, have nonnegative durations. Precheck errors retain `null`; cancelled evaluations without results stay omitted. Older responses without the field remain valid, and measured zero stays distinct from unknown timing. - Out of scope: the FE work tracked in [SAO-18028](https://splunk.atlassian.net/browse/SAO-18028), Orbit ingestion changes, production deployment, and load/capacity benchmarks. ## Risk and Rollout - Risk level: low. The response field is optional and evaluation decisions are unchanged. - Rollback plan: revert this commit; existing SDK/model consumers continue to accept responses without the duration field. - Follow-up: Python Orbit OTEL v2 ingestion currently drops the explicit `agent_control.execution_duration_ms` attribute. Its passthrough needs a separate change for that AO path. This PR does not establish end-to-end AO UI behavior. ## Testing - [x] Added or updated automated tests: per-control outcomes/errors/timeouts, cancellation/prechecks, legacy compatibility, HTTP serialization/error redaction, SDK event/decorator propagation, OTEL conversion, and TypeScript response mapping. - [x] Ran the repository's `make prepush` gate locally and full `make check` in [Python CI](https://github.com/agentcontrol/agent-control/actions/runs/37391050258/job/112035944219); both passed. Local focused HTTP tests require no database; CI also exercised the full database-backed suite with Postgres. - Python checks: 76 model tests, 138 engine tests, 151 relevant Python SDK tests, and 3 HTTP contract tests passed (368 total). - TypeScript checks: `make sdk-ts-lint sdk-ts-typecheck sdk-ts-test sdk-ts-build` passed; 15 tests passed. - Ruff lint/format checks passed for all four new Python test files; `git diff --check` passed. - Local OpenAPI generation completed; local Speakeasy generation required an account login. CI subsequently regenerated the SDK successfully and confirmed the committed generated model matches exact generator output. The complete [TypeScript SDK CI job](https://github.com/agentcontrol/agent-control/actions/runs/37391050258/job/112035944315), including `make sdk-ts-generate-check` and naming checks, passed. - [x] Manually verified behavior in an isolated DevStack; see evidence below. ## DevStack validation — 2026-10-05 - Isolated GCP DevStack: `josjeon-sao18023-pr283`, UUID `c94170b6-7a6b-4f7e-945c-8351693d41bc`, standard / capacity_s. - BE source: `3690373c3c6a182a2647bd3b894a648bb6fc66bd`; all six Agent Control package refs in the Orbit integration branch pin this immutable commit. - Verified Orbit checkout in the [successful image build](https://github.com/rungalileo/galileo-infra-automation/actions/runs/37394261717/job/112046360923): `6b8b3a8aa98b96386a7738f06b0ded75093e4b31`. - Image tag: `gcr.io/rungalileo-dev/agent-control:codex-sao-18023-devstack-pr283`; pushed manifest digest: `sha256:8974bf0f30e206b547e824731d3995b5d311233a8d3c2a3d39283dd9d125ece2`. - [Provision](https://github.com/rungalileo/galileo-infra-automation/actions/runs/37392938858) and [custom update](https://github.com/rungalileo/galileo-infra-automation/actions/runs/37394261717) workflows succeeded. Aegis subsequently reported `running`, the custom Agent Control version, and zero failed/pending pods. The digest is build/push evidence; an in-pod digest/source-hash inspection was not performed. | Requirement | Deployed test evidence | | --- | --- | | Runtime auth / readiness | API, PostgreSQL and AC health returned 200. Missing auth returned 401 requiring `Authorization`; Bearer runtime-token exchange and evaluation succeeded. | | Match, non-match, handled error timing | Two successful evaluation responses: one raw HTTP call and one public exact-head Python SDK call. Each had one entry per category with finite, nonnegative top-level `execution_duration_ms` (six completed entries total). | | Safe errors / scope skip | Internal evaluator error was sanitized, deny error failed closed, and post-only control was absent during the pre stage. | | SDK propagation | All three typed results and three recorded events preserved the exact values captured from that same SDK HTTP response. Timing stayed outside evaluator result/event metadata. | | OTEL mapping | Local conversion preserved the duration attribute and exact nanosecond span delta. Events were recorded in a local sink; AO ingestion was not exercised. | | Legacy compatibility | Local omitted/null/zero replays passed; these are compatibility checks, not live timing measurements. | | Orbit integration | Dependency compilation, module-lock generation, 24 launcher tests and mypy passed. | Observed functional samples (separate requests, milliseconds): | Category | Raw API | SDK | | --- | ---: | ---: | | Match | 0.130080 | 0.114650 | | Non-match | 0.250990 | 0.293050 | | Handled error | 90.031554 | 88.694064 | The probe completed with exit 0 and `status=passed`. Successful SDK responses were counted; total HTTP attempts were not counted because its authentication path can retry. This is bounded functional validation, not a load test or latency/capacity acceptance result. Deployed TypeScript/FE, Luna/external evaluators, and AO ingestion remain outside this validation. Timeout/precheck/cancellation coverage is automated, not live here. The first signup attempt rejected a `+` email alias before creating an account. Correcting only the probe's address format allowed bootstrap and validation to pass. The probe received successful deletion acknowledgements for its own bindings/controls, project and temporary API key; no absence GET readback was performed. The dedicated stack was destroyed after testing with `retain_data=false`. Final Aegis readback is `destroyed`, with no last error; [teardown workflow](https://github.com/rungalileo/galileo-infra-automation/actions/runs/37395484152). ## Checklist - [x] Linked issue/spec. - [x] Updated docs for the new public field and timing boundaries. - [x] Included required follow-up tasks and completed SDK generation verification.
1 parent db9c667 commit d1b9d21

12 files changed

Lines changed: 725 additions & 1 deletion

File tree

‎engine/src/agent_control_engine/core.py‎

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -7,6 +7,7 @@
77
import functools
88
import logging
99
import os
10+
import time
1011
from collections.abc import Sequence
1112
from dataclasses import dataclass
1213
from typing import Any, Literal, Protocol
@@ -201,6 +202,7 @@ class _EvalTask:
201202
item: ControlWithIdentity
202203
task: asyncio.Task[None] | None = None
203204
result: EvaluatorResult | None = None
205+
execution_duration_ms: float | None = None
204206

205207

206208
@dataclass
@@ -673,6 +675,7 @@ async def process(
673675

674676
async def evaluate_control(eval_task: _EvalTask) -> None:
675677
"""Evaluate a single control, respecting cancellation and timeout."""
678+
started_at = time.perf_counter()
676679
try:
677680
evaluation = await self._evaluate_condition(
678681
eval_task.item,
@@ -701,6 +704,9 @@ async def evaluate_control(eval_task: _EvalTask) -> None:
701704
error_msg,
702705
message_prefix="Condition evaluation failed",
703706
)
707+
finally:
708+
if eval_task.result is not None:
709+
eval_task.execution_duration_ms = (time.perf_counter() - started_at) * 1000
704710

705711
# Create and start all tasks
706712
for eval_task in eval_tasks:
@@ -753,6 +759,7 @@ async def wait_for_deny() -> None:
753759
control_name=eval_task.item.name,
754760
action=eval_task.item.control.action.decision,
755761
result=eval_task.result,
762+
execution_duration_ms=eval_task.execution_duration_ms,
756763
steering_context=eval_task.item.control.action.steering_context,
757764
)
758765
)
@@ -776,6 +783,7 @@ async def wait_for_deny() -> None:
776783
control_name=eval_task.item.name,
777784
action=eval_task.item.control.action.decision,
778785
result=eval_task.result,
786+
execution_duration_ms=eval_task.execution_duration_ms,
779787
steering_context=steer_ctx,
780788
)
781789
)
@@ -792,6 +800,7 @@ async def wait_for_deny() -> None:
792800
control_name=eval_task.item.name,
793801
action=eval_task.item.control.action.decision,
794802
result=eval_task.result,
803+
execution_duration_ms=eval_task.execution_duration_ms,
795804
steering_context=eval_task.item.control.action.steering_context,
796805
)
797806
)
Lines changed: 254 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,254 @@
1+
"""Public engine contract tests for per-control execution durations."""
2+
3+
import asyncio
4+
from dataclasses import dataclass
5+
from typing import Any, Literal
6+
from unittest.mock import AsyncMock, Mock
7+
8+
import pytest
9+
from agent_control_engine.core import ControlEngine
10+
from agent_control_evaluators import Evaluator, EvaluatorMetadata, register_evaluator
11+
from agent_control_models import ControlDefinition, EvaluationRequest, EvaluatorResult, Step
12+
from pydantic import BaseModel
13+
14+
15+
class DurationConfig(BaseModel):
16+
matched: bool = False
17+
raises_error: bool = False
18+
blocks: bool = False
19+
20+
21+
class DurationEvaluator(Evaluator[DurationConfig]):
22+
metadata = EvaluatorMetadata(
23+
name="test-duration",
24+
version="1.0.0",
25+
description="Returns a configured outcome or waits for cancellation",
26+
)
27+
config_model = DurationConfig
28+
29+
async def evaluate(self, data: Any) -> EvaluatorResult:
30+
# Yield once so concurrent controls all start before one completes.
31+
await asyncio.sleep(0)
32+
if self.config.blocks:
33+
await asyncio.Event().wait()
34+
if self.config.raises_error:
35+
raise RuntimeError("evaluation failed")
36+
return EvaluatorResult(matched=self.config.matched, confidence=1.0)
37+
38+
39+
@dataclass
40+
class DurationControl:
41+
id: int
42+
name: str
43+
control: ControlDefinition
44+
45+
46+
@pytest.fixture(autouse=True)
47+
def register_duration_evaluator() -> None:
48+
register_evaluator(DurationEvaluator)
49+
50+
51+
@pytest.fixture
52+
def evaluation_request() -> EvaluationRequest:
53+
return EvaluationRequest(
54+
agent_name="duration-test-agent",
55+
step=Step(type="llm", name="test-step", input="test", output=None),
56+
stage="pre",
57+
)
58+
59+
60+
def make_control(
61+
control_id: int = 1,
62+
*,
63+
context: Literal["server", "sdk"] = "server",
64+
matched: bool = False,
65+
raises_error: bool = False,
66+
blocks: bool = False,
67+
decision: Literal["observe", "deny"] = "observe",
68+
) -> DurationControl:
69+
return DurationControl(
70+
id=control_id,
71+
name=f"duration-control-{control_id}",
72+
control=ControlDefinition(
73+
description="Duration test control",
74+
enabled=True,
75+
execution=context,
76+
scope={"stages": ["pre"], "step_types": ["llm"]},
77+
condition={
78+
"selector": {"path": "input"},
79+
"evaluator": {
80+
"name": "test-duration",
81+
"config": {
82+
"matched": matched,
83+
"raises_error": raises_error,
84+
"blocks": blocks,
85+
},
86+
},
87+
},
88+
action={"decision": decision},
89+
),
90+
)
91+
92+
93+
@pytest.mark.asyncio
94+
@pytest.mark.parametrize("context", ["server", "sdk"])
95+
@pytest.mark.parametrize("category", ["matches", "non_matches", "errors"])
96+
@pytest.mark.parametrize("elapsed_seconds", [0.0, 0.0125])
97+
async def test_completed_controls_report_elapsed_milliseconds(
98+
monkeypatch: pytest.MonkeyPatch,
99+
evaluation_request: EvaluationRequest,
100+
context: Literal["server", "sdk"],
101+
category: str,
102+
elapsed_seconds: float,
103+
) -> None:
104+
# Given: a completed control and a controlled clock instead of wall-clock assertions
105+
control = make_control(
106+
context=context,
107+
matched=category == "matches",
108+
raises_error=category == "errors",
109+
)
110+
clock = Mock(side_effect=[10.0, 10.0 + elapsed_seconds])
111+
monkeypatch.setattr("agent_control_engine.core.time.perf_counter", clock)
112+
113+
# When: evaluating via the public engine entrypoint
114+
response = await ControlEngine([control], context=context).process(evaluation_request)
115+
116+
# Then: all completed outcome categories retain their own duration, including zero
117+
results = getattr(response, category)
118+
assert results is not None
119+
assert len(results) == 1
120+
assert results[0].execution_duration_ms == pytest.approx(elapsed_seconds * 1000)
121+
assert results[0].result.matched is (category == "matches")
122+
assert bool(results[0].result.error) is (category == "errors")
123+
assert response.is_safe is True
124+
125+
126+
@pytest.mark.asyncio
127+
async def test_parallel_controls_keep_individual_durations(
128+
monkeypatch: pytest.MonkeyPatch, evaluation_request: EvaluationRequest
129+
) -> None:
130+
# Given: parallel controls start together and complete at different clock readings
131+
clock = Mock(side_effect=[10.0, 10.0, 10.0125, 10.025])
132+
monkeypatch.setattr("agent_control_engine.core.time.perf_counter", clock)
133+
controls = [make_control(1), make_control(2)]
134+
135+
# When: evaluating both controls in the same engine request
136+
response = await ControlEngine(controls).process(evaluation_request)
137+
138+
# Then: each control reports its own elapsed time rather than the batch duration
139+
assert response.non_matches is not None
140+
durations = {result.control_id: result.execution_duration_ms for result in response.non_matches}
141+
assert durations == pytest.approx({1: 12.5, 2: 25.0})
142+
143+
144+
@pytest.mark.asyncio
145+
async def test_condition_traversal_error_retains_elapsed_duration(
146+
monkeypatch: pytest.MonkeyPatch, evaluation_request: EvaluationRequest
147+
) -> None:
148+
# Given: an internal traversal failure forced to exercise the outer error handler
149+
engine = ControlEngine([make_control(decision="deny")])
150+
monkeypatch.setattr(
151+
engine, "_evaluate_condition", AsyncMock(side_effect=ValueError("condition failed"))
152+
)
153+
clock = Mock(side_effect=[10.0, 10.007])
154+
monkeypatch.setattr("agent_control_engine.core.time.perf_counter", clock)
155+
156+
# When: evaluating via the public engine entrypoint
157+
response = await engine.process(evaluation_request)
158+
159+
# Then: the completed error is timed and still fails closed
160+
assert response.is_safe is False
161+
assert response.errors is not None
162+
assert len(response.errors) == 1
163+
assert response.errors[0].execution_duration_ms == pytest.approx(7.0)
164+
assert response.errors[0].result.error == "ValueError: condition failed"
165+
166+
167+
@pytest.mark.asyncio
168+
async def test_timed_out_evaluation_retains_elapsed_duration(
169+
monkeypatch: pytest.MonkeyPatch, evaluation_request: EvaluationRequest
170+
) -> None:
171+
# Given: a blocking evaluator with a bounded timeout and a controlled elapsed clock
172+
monkeypatch.setattr(DurationEvaluator, "get_timeout_seconds", lambda self: 0.001)
173+
clock = Mock(side_effect=[10.0, 10.001])
174+
monkeypatch.setattr("agent_control_engine.core.time.perf_counter", clock)
175+
176+
# When: the evaluator times out without producing a normal result
177+
response = await ControlEngine([make_control(blocks=True, decision="deny")]).process(
178+
evaluation_request
179+
)
180+
181+
# Then: the timeout error is a completed evaluation with an elapsed duration
182+
assert response.is_safe is False
183+
assert response.errors is not None
184+
assert len(response.errors) == 1
185+
assert response.errors[0].execution_duration_ms == pytest.approx(1.0)
186+
assert response.errors[0].result.error is not None
187+
assert response.errors[0].result.error.startswith("TimeoutError:")
188+
189+
190+
@pytest.mark.asyncio
191+
async def test_cancelled_controls_do_not_report_partial_durations(
192+
monkeypatch: pytest.MonkeyPatch, evaluation_request: EvaluationRequest
193+
) -> None:
194+
# Given: a blocking control that is cancelled by a completed deny control
195+
clock = Mock(side_effect=[10.0, 10.0, 10.020])
196+
monkeypatch.setattr("agent_control_engine.core.time.perf_counter", clock)
197+
controls = [make_control(1, blocks=True), make_control(2, matched=True, decision="deny")]
198+
199+
# When: a deny match cancels the unfinished evaluation
200+
response = await ControlEngine(controls).process(evaluation_request)
201+
202+
# Then: only the completed deny is returned, with no fabricated cancelled result
203+
assert response.is_safe is False
204+
assert response.matches is not None
205+
assert len(response.matches) == 1
206+
assert response.matches[0].control_id == 2
207+
assert response.matches[0].execution_duration_ms == pytest.approx(20.0)
208+
assert response.non_matches is None
209+
assert response.errors is None
210+
assert clock.call_count == 3
211+
212+
213+
@pytest.mark.asyncio
214+
async def test_skipped_control_does_not_start_duration_measurement(
215+
monkeypatch: pytest.MonkeyPatch, evaluation_request: EvaluationRequest
216+
) -> None:
217+
# Given: a disabled control that must not evaluate
218+
control = make_control()
219+
control.control.enabled = False
220+
clock = Mock(side_effect=AssertionError("skipped control must not be timed"))
221+
monkeypatch.setattr("agent_control_engine.core.time.perf_counter", clock)
222+
223+
# When: processing a request without applicable controls
224+
response = await ControlEngine([control]).process(evaluation_request)
225+
226+
# Then: there are no results or clock reads for the skipped control
227+
assert response.matches is None
228+
assert response.non_matches is None
229+
assert response.errors is None
230+
clock.assert_not_called()
231+
232+
233+
@pytest.mark.asyncio
234+
async def test_precheck_error_has_no_execution_duration(
235+
monkeypatch: pytest.MonkeyPatch, evaluation_request: EvaluationRequest
236+
) -> None:
237+
# Given: validation is bypassed to exercise the defensive invalid-regex precheck
238+
control = make_control()
239+
payload = control.control.model_dump()
240+
payload["scope"]["step_name_regex"] = "[invalid(regex"
241+
control.control = ControlDefinition.model_validate(
242+
payload, context={"allow_invalid_step_name_regex": True}
243+
)
244+
clock = Mock(side_effect=AssertionError("precheck failure must not be timed"))
245+
monkeypatch.setattr("agent_control_engine.core.time.perf_counter", clock)
246+
247+
# When: processing a control that fails before evaluation
248+
response = await ControlEngine([control]).process(evaluation_request)
249+
250+
# Then: the error retains an unknown duration rather than zero
251+
assert response.errors is not None
252+
assert len(response.errors) == 1
253+
assert response.errors[0].execution_duration_ms is None
254+
clock.assert_not_called()

‎models/README.md‎

Lines changed: 14 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -17,6 +17,20 @@ agent = Agent(agent_name="support-bot", agent_description="Support agent")
1717
step = Step(type="llm", name="chat", input="hello")
1818
```
1919

20+
## Control execution duration
21+
22+
Evaluation responses include an optional top-level `execution_duration_ms` on each
23+
`ControlMatch` in `matches`, `non_matches`, and `errors`. It measures that control's
24+
condition evaluation in wall-clock milliseconds, including the visited condition
25+
leaves, evaluator work, and time waiting for an evaluator concurrency slot.
26+
Control loading and request/response overhead are outside this measurement.
27+
28+
Completed evaluations include a nonnegative value, including evaluator failures.
29+
Precheck failures have no duration, and canceled evaluations produce no result.
30+
Older responses without the field remain valid. The Python SDK copies the value
31+
to `ControlExecutionEvent.execution_duration_ms`; the TypeScript SDK exposes it as
32+
`executionDurationMs`.
33+
2034
## Tests
2135

2236
```bash

‎models/src/agent_control_models/controls.py‎

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -957,6 +957,11 @@ class ControlMatch(BaseModel):
957957
result: EvaluatorResult = Field(
958958
..., description="Evaluator result (confidence, message, metadata)"
959959
)
960+
execution_duration_ms: float | None = Field(
961+
default=None,
962+
ge=0,
963+
description="Control evaluation wall-clock duration in milliseconds, if executed",
964+
)
960965
steering_context: SteeringContext | None = Field(
961966
None,
962967
description="Steering context for steer actions if configured"

0 commit comments

Comments
 (0)