feat(examples): add offline SDK-local per-control timing demo

engine/src/agent_control_engine/core.py

@@ -7,6 +7,7 @@
 import functools
 import logging
 import os
+import time
 from collections.abc import Sequence
 from dataclasses import dataclass
 from typing import Any, Literal, Protocol
@@ -201,6 +202,7 @@ class _EvalTask:
     item: ControlWithIdentity
     task: asyncio.Task[None] | None = None
     result: EvaluatorResult | None = None
+    execution_duration_ms: float | None = None
 
 
 @dataclass
@@ -673,6 +675,7 @@ async def process(
 
         async def evaluate_control(eval_task: _EvalTask) -> None:
             """Evaluate a single control, respecting cancellation and timeout."""
+            started_at = time.perf_counter()
             try:
                 evaluation = await self._evaluate_condition(
                     eval_task.item,
@@ -701,6 +704,9 @@ async def evaluate_control(eval_task: _EvalTask) -> None:
                     error_msg,
                     message_prefix="Condition evaluation failed",
                 )
+            finally:
+                if eval_task.result is not None:
+                    eval_task.execution_duration_ms = (time.perf_counter() - started_at) * 1000
 
         # Create and start all tasks
         for eval_task in eval_tasks:
@@ -753,6 +759,7 @@ async def wait_for_deny() -> None:
                         control_name=eval_task.item.name,
                         action=eval_task.item.control.action.decision,
                         result=eval_task.result,
+                        execution_duration_ms=eval_task.execution_duration_ms,
                         steering_context=eval_task.item.control.action.steering_context,
                     )
                 )
@@ -776,6 +783,7 @@ async def wait_for_deny() -> None:
                         control_name=eval_task.item.name,
                         action=eval_task.item.control.action.decision,
                         result=eval_task.result,
+                        execution_duration_ms=eval_task.execution_duration_ms,
                         steering_context=steer_ctx,
                     )
                 )
@@ -792,6 +800,7 @@ async def wait_for_deny() -> None:
                         control_name=eval_task.item.name,
                         action=eval_task.item.control.action.decision,
                         result=eval_task.result,
+                        execution_duration_ms=eval_task.execution_duration_ms,
                         steering_context=eval_task.item.control.action.steering_context,
                     )
                 )

engine/tests/test_execution_duration.py

@@ -0,0 +1,254 @@
+"""Public engine contract tests for per-control execution durations."""
+
+import asyncio
+from dataclasses import dataclass
+from typing import Any, Literal
+from unittest.mock import AsyncMock, Mock
+
+import pytest
+from agent_control_engine.core import ControlEngine
+from agent_control_evaluators import Evaluator, EvaluatorMetadata, register_evaluator
+from agent_control_models import ControlDefinition, EvaluationRequest, EvaluatorResult, Step
+from pydantic import BaseModel
+
+
+class DurationConfig(BaseModel):
+    matched: bool = False
+    raises_error: bool = False
+    blocks: bool = False
+
+
+class DurationEvaluator(Evaluator[DurationConfig]):
+    metadata = EvaluatorMetadata(
+        name="test-duration",
+        version="1.0.0",
+        description="Returns a configured outcome or waits for cancellation",
+    )
+    config_model = DurationConfig
+
+    async def evaluate(self, data: Any) -> EvaluatorResult:
+        # Yield once so concurrent controls all start before one completes.
+        await asyncio.sleep(0)
+        if self.config.blocks:
+            await asyncio.Event().wait()
+        if self.config.raises_error:
+            raise RuntimeError("evaluation failed")
+        return EvaluatorResult(matched=self.config.matched, confidence=1.0)
+
+
+@dataclass
+class DurationControl:
+    id: int
+    name: str
+    control: ControlDefinition
+
+
+@pytest.fixture(autouse=True)
+def register_duration_evaluator() -> None:
+    register_evaluator(DurationEvaluator)
+
+
+@pytest.fixture
+def evaluation_request() -> EvaluationRequest:
+    return EvaluationRequest(
+        agent_name="duration-test-agent",
+        step=Step(type="llm", name="test-step", input="test", output=None),
+        stage="pre",
+    )
+
+
+def make_control(
+    control_id: int = 1,
+    *,
+    context: Literal["server", "sdk"] = "server",
+    matched: bool = False,
+    raises_error: bool = False,
+    blocks: bool = False,
+    decision: Literal["observe", "deny"] = "observe",
+) -> DurationControl:
+    return DurationControl(
+        id=control_id,
+        name=f"duration-control-{control_id}",
+        control=ControlDefinition(
+            description="Duration test control",
+            enabled=True,
+            execution=context,
+            scope={"stages": ["pre"], "step_types": ["llm"]},
+            condition={
+                "selector": {"path": "input"},
+                "evaluator": {
+                    "name": "test-duration",
+                    "config": {
+                        "matched": matched,
+                        "raises_error": raises_error,
+                        "blocks": blocks,
+                    },
+                },
+            },
+            action={"decision": decision},
+        ),
+    )
+
+
+@pytest.mark.asyncio
+@pytest.mark.parametrize("context", ["server", "sdk"])
+@pytest.mark.parametrize("category", ["matches", "non_matches", "errors"])
+@pytest.mark.parametrize("elapsed_seconds", [0.0, 0.0125])
+async def test_completed_controls_report_elapsed_milliseconds(
+    monkeypatch: pytest.MonkeyPatch,
+    evaluation_request: EvaluationRequest,
+    context: Literal["server", "sdk"],
+    category: str,
+    elapsed_seconds: float,
+) -> None:
+    # Given: a completed control and a controlled clock instead of wall-clock assertions
+    control = make_control(
+        context=context,
+        matched=category == "matches",
+        raises_error=category == "errors",
+    )
+    clock = Mock(side_effect=[10.0, 10.0 + elapsed_seconds])
+    monkeypatch.setattr("agent_control_engine.core.time.perf_counter", clock)
+
+    # When: evaluating via the public engine entrypoint
+    response = await ControlEngine([control], context=context).process(evaluation_request)
+
+    # Then: all completed outcome categories retain their own duration, including zero
+    results = getattr(response, category)
+    assert results is not None
+    assert len(results) == 1
+    assert results[0].execution_duration_ms == pytest.approx(elapsed_seconds * 1000)
+    assert results[0].result.matched is (category == "matches")
+    assert bool(results[0].result.error) is (category == "errors")
+    assert response.is_safe is True
+
+
+@pytest.mark.asyncio
+async def test_parallel_controls_keep_individual_durations(
+    monkeypatch: pytest.MonkeyPatch, evaluation_request: EvaluationRequest
+) -> None:
+    # Given: parallel controls start together and complete at different clock readings
+    clock = Mock(side_effect=[10.0, 10.0, 10.0125, 10.025])
+    monkeypatch.setattr("agent_control_engine.core.time.perf_counter", clock)
+    controls = [make_control(1), make_control(2)]
+
+    # When: evaluating both controls in the same engine request
+    response = await ControlEngine(controls).process(evaluation_request)
+
+    # Then: each control reports its own elapsed time rather than the batch duration
+    assert response.non_matches is not None
+    durations = {result.control_id: result.execution_duration_ms for result in response.non_matches}
+    assert durations == pytest.approx({1: 12.5, 2: 25.0})
+
+
+@pytest.mark.asyncio
+async def test_condition_traversal_error_retains_elapsed_duration(
+    monkeypatch: pytest.MonkeyPatch, evaluation_request: EvaluationRequest
+) -> None:
+    # Given: an internal traversal failure forced to exercise the outer error handler
+    engine = ControlEngine([make_control(decision="deny")])
+    monkeypatch.setattr(
+        engine, "_evaluate_condition", AsyncMock(side_effect=ValueError("condition failed"))
+    )
+    clock = Mock(side_effect=[10.0, 10.007])
+    monkeypatch.setattr("agent_control_engine.core.time.perf_counter", clock)
+
+    # When: evaluating via the public engine entrypoint
+    response = await engine.process(evaluation_request)
+
+    # Then: the completed error is timed and still fails closed
+    assert response.is_safe is False
+    assert response.errors is not None
+    assert len(response.errors) == 1
+    assert response.errors[0].execution_duration_ms == pytest.approx(7.0)
+    assert response.errors[0].result.error == "ValueError: condition failed"
+
+
+@pytest.mark.asyncio
+async def test_timed_out_evaluation_retains_elapsed_duration(
+    monkeypatch: pytest.MonkeyPatch, evaluation_request: EvaluationRequest
+) -> None:
+    # Given: a blocking evaluator with a bounded timeout and a controlled elapsed clock
+    monkeypatch.setattr(DurationEvaluator, "get_timeout_seconds", lambda self: 0.001)
+    clock = Mock(side_effect=[10.0, 10.001])
+    monkeypatch.setattr("agent_control_engine.core.time.perf_counter", clock)
+
+    # When: the evaluator times out without producing a normal result
+    response = await ControlEngine([make_control(blocks=True, decision="deny")]).process(
+        evaluation_request
+    )
+
+    # Then: the timeout error is a completed evaluation with an elapsed duration
+    assert response.is_safe is False
+    assert response.errors is not None
+    assert len(response.errors) == 1
+    assert response.errors[0].execution_duration_ms == pytest.approx(1.0)
+    assert response.errors[0].result.error is not None
+    assert response.errors[0].result.error.startswith("TimeoutError:")
+
+
+@pytest.mark.asyncio
+async def test_cancelled_controls_do_not_report_partial_durations(
+    monkeypatch: pytest.MonkeyPatch, evaluation_request: EvaluationRequest
+) -> None:
+    # Given: a blocking control that is cancelled by a completed deny control
+    clock = Mock(side_effect=[10.0, 10.0, 10.020])
+    monkeypatch.setattr("agent_control_engine.core.time.perf_counter", clock)
+    controls = [make_control(1, blocks=True), make_control(2, matched=True, decision="deny")]
+
+    # When: a deny match cancels the unfinished evaluation
+    response = await ControlEngine(controls).process(evaluation_request)
+
+    # Then: only the completed deny is returned, with no fabricated cancelled result
+    assert response.is_safe is False
+    assert response.matches is not None
+    assert len(response.matches) == 1
+    assert response.matches[0].control_id == 2
+    assert response.matches[0].execution_duration_ms == pytest.approx(20.0)
+    assert response.non_matches is None
+    assert response.errors is None
+    assert clock.call_count == 3
+
+
+@pytest.mark.asyncio
+async def test_skipped_control_does_not_start_duration_measurement(
+    monkeypatch: pytest.MonkeyPatch, evaluation_request: EvaluationRequest
+) -> None:
+    # Given: a disabled control that must not evaluate
+    control = make_control()
+    control.control.enabled = False
+    clock = Mock(side_effect=AssertionError("skipped control must not be timed"))
+    monkeypatch.setattr("agent_control_engine.core.time.perf_counter", clock)
+
+    # When: processing a request without applicable controls
+    response = await ControlEngine([control]).process(evaluation_request)
+
+    # Then: there are no results or clock reads for the skipped control
+    assert response.matches is None
+    assert response.non_matches is None
+    assert response.errors is None
+    clock.assert_not_called()
+
+
+@pytest.mark.asyncio
+async def test_precheck_error_has_no_execution_duration(
+    monkeypatch: pytest.MonkeyPatch, evaluation_request: EvaluationRequest
+) -> None:
+    # Given: validation is bypassed to exercise the defensive invalid-regex precheck
+    control = make_control()
+    payload = control.control.model_dump()
+    payload["scope"]["step_name_regex"] = "[invalid(regex"
+    control.control = ControlDefinition.model_validate(
+        payload, context={"allow_invalid_step_name_regex": True}
+    )
+    clock = Mock(side_effect=AssertionError("precheck failure must not be timed"))
+    monkeypatch.setattr("agent_control_engine.core.time.perf_counter", clock)
+
+    # When: processing a control that fails before evaluation
+    response = await ControlEngine([control]).process(evaluation_request)
+
+    # Then: the error retains an unknown duration rather than zero
+    assert response.errors is not None
+    assert len(response.errors) == 1
+    assert response.errors[0].execution_duration_ms is None
+    clock.assert_not_called()

examples/README.md

@@ -14,6 +14,7 @@ This directory contains runnable examples for Agent Control. Each example has it
 | Customer Support Agent | Enterprise scenario with PII protection, prompt-injection defense, and multiple tools. | https://docs.agentcontrol.dev/examples/customer-support |
 | DeepEval | Build a custom evaluator using DeepEval GEval metrics. | https://docs.agentcontrol.dev/examples/deepeval |
 | Galileo Luna Direct | Direct Luna scorer invoke evaluation (`scorer_id` required; `scorer_label`/`scorer_version_id` optional) with a composite Agent Control condition. | `examples/galileo_luna/` |
+| SDK-local timing | Compare per-control duration with whole SDK call time using synthetic local controls and no network. | `examples/sdk_local_timing/` |
 | LangChain SQL Agent | Protect a SQL agent from dangerous queries with server-side controls. | https://docs.agentcontrol.dev/examples/langchain-sql |
 | Steer Action Demo | Banking transfer agent showcasing observe, deny, and steer actions. | https://docs.agentcontrol.dev/examples/steer-action-demo |
 | Target Context | Bind controls to opaque external targets (e.g. `env=prod`) and let the SDK pin one target per session. | https://docs.agentcontrol.dev/examples/target-context |

examples/sdk_local_timing/README.md

@@ -0,0 +1,37 @@
+# SDK-local control timing example
+
+This example runs five synthetic controls through the Python SDK's real
+`check_evaluation_with_local` path. It covers list allow/block, regex steer,
+SQL block, and JSON validation. Each case uses one control, so its result and
+duration have a clear owner.
+
+PR #283 measures the full control condition evaluation. It includes evaluator
+work and any wait for an evaluator slot. It excludes control loading and SDK
+call overhead. The separate `sdk_call` distribution includes those costs.
+These values are not isolated evaluator-call timings.
+
+From the repository root:
+
+```bash
+make sync
+uv run --package agent-control-sdk python examples/sdk_local_timing/demo.py --iterations 100 --warmup 5
+```
+
+The default output is a small per-control p50/p95 table. Pass `--json` for
+counts, min, p50, p95 and max values in a machine-readable report. The
+`control` number comes from `ControlMatch.execution_duration_ms`; `sdk_call`
+is measured around the SDK call by this example.
+
+For a bounded SDK-local throughput smoke, add `--concurrency 8 --iterations 1000`.
+The table then includes observed SDK calls per second for each independent
+scenario. This uses one Python process and one event loop without a target
+request rate; it is not a production capacity number.
+
+The example disables SDK observability for its run and restores the previous
+settings afterward. An HTTP mock rejects all outbound requests. No account,
+API key, server, Luna scorer, or GPU is needed. The warmup runs are excluded
+from the reported nearest-rank p50 and p95 values.
+
+This example does not establish SDK capacity or server/Luna3 throughput. Those
+require a configured workload, stack, acceptance thresholds and a separate
+load test.