mirror of
https://github.com/crewAIInc/crewAI.git
synced 2026-08-13 01:38:41 +00:00
feat(flow): record how long a flow ran
Adds a Flow Completed span carrying flow_name, duration_ms and outcome,
emitted when a flow finishes or fails. Elapsed time comes from a monotonic
stamp taken at flow start and cleared on use.
Kept separate from the Flow Execution span rather than holding that one open:
it is emitted and closed at start and the daily aggregate counts it, so
holding it would drop every run that is killed or crashes from the execution
count. A killed run now simply has no Flow Completed row, and the count is
unaffected.
Elapsed time is an explicit duration_ms attribute rather than the span's own
duration, which the ingestion pipeline stores as a suffixed string
("0.0000184s") that downstream aggregation parses to zero.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01ASfWmW3RGy4qAQm6s8U9jH
This commit is contained in:
@@ -1,6 +1,7 @@
|
||||
from __future__ import annotations
|
||||
|
||||
from io import StringIO
|
||||
import time
|
||||
from typing import TYPE_CHECKING, Any
|
||||
|
||||
from pydantic import Field, PrivateAttr
|
||||
@@ -307,11 +308,27 @@ class EventListener(BaseEventListener):
|
||||
def on_flow_created(_: Any, event: FlowCreatedEvent) -> None:
|
||||
self._telemetry.flow_creation_span(event.flow_name)
|
||||
|
||||
def _report_flow_duration(source: Any, flow_name: str, outcome: str) -> None:
|
||||
"""Emit the elapsed time for a flow that reached a terminal state.
|
||||
|
||||
A flow can finish without this listener having seen it start - a
|
||||
conversational turn re-emits completion for a restored run - so a
|
||||
missing stamp means "no duration to report", not an error.
|
||||
"""
|
||||
started_at = getattr(source, "_telemetry_started_at", None)
|
||||
if started_at is None:
|
||||
return
|
||||
source._telemetry_started_at = None
|
||||
self._telemetry.flow_completed_span(
|
||||
flow_name, (time.monotonic() - started_at) * 1000, outcome
|
||||
)
|
||||
|
||||
@crewai_event_bus.on(FlowStartedEvent)
|
||||
def on_flow_started(source: Any, event: FlowStartedEvent) -> None:
|
||||
self._telemetry.flow_execution_span(
|
||||
event.flow_name, list(source._methods.keys())
|
||||
)
|
||||
source._telemetry_started_at = time.monotonic()
|
||||
if not getattr(source, "suppress_flow_events", False):
|
||||
self.formatter.handle_flow_created(event.flow_name, str(source.flow_id))
|
||||
self.formatter.handle_flow_started(event.flow_name, str(source.flow_id))
|
||||
@@ -319,6 +336,7 @@ class EventListener(BaseEventListener):
|
||||
@crewai_event_bus.on(FlowFinishedEvent)
|
||||
def on_flow_finished(source: Any, event: FlowFinishedEvent) -> None:
|
||||
self._telemetry.feature_usage_span("flow:completed")
|
||||
_report_flow_duration(source, event.flow_name, "completed")
|
||||
|
||||
if not getattr(source, "suppress_flow_events", False):
|
||||
self.formatter.handle_flow_status(
|
||||
@@ -329,6 +347,7 @@ class EventListener(BaseEventListener):
|
||||
@crewai_event_bus.on(FlowFailedEvent)
|
||||
def on_flow_failed(source: Any, event: FlowFailedEvent) -> None:
|
||||
self._telemetry.feature_usage_span("flow:failed")
|
||||
_report_flow_duration(source, event.flow_name, "failed")
|
||||
|
||||
if not getattr(source, "suppress_flow_events", False):
|
||||
self.formatter.handle_flow_status(
|
||||
|
||||
@@ -719,6 +719,10 @@ class Flow(BaseModel, Generic[T], metaclass=FlowMeta):
|
||||
_method_call_counts: dict[FlowMethodName, int] = PrivateAttr(default_factory=dict)
|
||||
_is_execution_resuming: bool = PrivateAttr(default=False)
|
||||
_restored_from_checkpoint: bool = PrivateAttr(default=False)
|
||||
# Monotonic stamp set by the telemetry listener at flow start, so the
|
||||
# duration span emitted at the end does not need to hold a span open for
|
||||
# the life of the run.
|
||||
_telemetry_started_at: float | None = PrivateAttr(default=None)
|
||||
_event_futures: list[Future[None]] = PrivateAttr(default_factory=list)
|
||||
_pending_feedback_context: PendingFeedbackContext | None = PrivateAttr(default=None)
|
||||
_human_feedback_method_outputs: dict[str, Any] = PrivateAttr(default_factory=dict)
|
||||
|
||||
@@ -1013,6 +1013,39 @@ class Telemetry:
|
||||
|
||||
self._safe_telemetry_operation(_operation)
|
||||
|
||||
def flow_completed_span(
|
||||
self, flow_name: str, duration_ms: float, outcome: str
|
||||
) -> None:
|
||||
"""Records how long a flow ran and how it ended.
|
||||
|
||||
A separate span from ``Flow Execution`` rather than that span held open
|
||||
to completion: ``Flow Execution`` is emitted and closed at start, and
|
||||
the daily aggregate counts it, so holding it would drop every run that
|
||||
is killed or crashes from the execution count entirely.
|
||||
|
||||
The elapsed time is recorded as an explicit ``duration_ms`` attribute
|
||||
rather than left to the span's own duration, which the ingestion
|
||||
pipeline stores as a suffixed string ("0.0000184s") that downstream
|
||||
aggregation cannot parse.
|
||||
|
||||
Args:
|
||||
flow_name: Name of the flow that finished.
|
||||
duration_ms: Wall-clock milliseconds from flow start, measured on a
|
||||
monotonic clock.
|
||||
outcome: Either ``"completed"`` or ``"failed"``.
|
||||
"""
|
||||
|
||||
def _operation() -> None:
|
||||
tracer = self.provider.get_tracer(TRACER_NAME)
|
||||
span = tracer.start_span("Flow Completed")
|
||||
self._add_attribute(span, "crewai_version", version("crewai"))
|
||||
self._add_attribute(span, "flow_name", flow_name)
|
||||
self._add_attribute(span, "duration_ms", duration_ms)
|
||||
self._add_attribute(span, "outcome", outcome)
|
||||
close_span(span)
|
||||
|
||||
self._safe_telemetry_operation(_operation)
|
||||
|
||||
def env_context_span(self, tool: str) -> None:
|
||||
"""Records the coding tool environment context."""
|
||||
|
||||
|
||||
@@ -13,6 +13,7 @@ the input and conversation-failure events had no listener at all.
|
||||
from __future__ import annotations
|
||||
|
||||
import contextlib
|
||||
import time
|
||||
|
||||
import pytest
|
||||
|
||||
@@ -41,6 +42,24 @@ def _reregister_listener() -> None:
|
||||
listener_module.event_listener.setup_listeners(crewai_event_bus)
|
||||
|
||||
|
||||
@pytest.fixture
|
||||
def durations(monkeypatch: pytest.MonkeyPatch) -> list[tuple[str, float, str]]:
|
||||
"""Record every (flow_name, duration_ms, outcome) the listener reports."""
|
||||
from crewai.events import event_listener as listener_module
|
||||
|
||||
_reregister_listener()
|
||||
|
||||
recorded: list[tuple[str, float, str]] = []
|
||||
monkeypatch.setattr(
|
||||
listener_module.event_listener._telemetry,
|
||||
"flow_completed_span",
|
||||
lambda flow_name, duration_ms, outcome: recorded.append(
|
||||
(flow_name, duration_ms, outcome)
|
||||
),
|
||||
)
|
||||
return recorded
|
||||
|
||||
|
||||
@pytest.fixture
|
||||
def features(monkeypatch: pytest.MonkeyPatch) -> list[str]:
|
||||
"""Record every feature the listener reports for a real flow run.
|
||||
@@ -199,3 +218,88 @@ def test_no_user_authored_strings_are_recorded(features: list[str]) -> None:
|
||||
assert "my_secret_method_name" not in feature
|
||||
assert "secret error detail" not in feature
|
||||
assert "SecretNamedFlow" not in feature
|
||||
|
||||
|
||||
def test_completed_flow_reports_a_real_duration(
|
||||
durations: list[tuple[str, float, str]],
|
||||
) -> None:
|
||||
"""Elapsed time must be measured, not merely present."""
|
||||
|
||||
class SlowFlow(Flow):
|
||||
@start()
|
||||
def go(self) -> str:
|
||||
time.sleep(0.05)
|
||||
return "ok"
|
||||
|
||||
SlowFlow().kickoff()
|
||||
|
||||
assert len(durations) == 1
|
||||
flow_name, duration_ms, outcome = durations[0]
|
||||
assert flow_name == "SlowFlow"
|
||||
assert outcome == "completed"
|
||||
assert duration_ms >= 50
|
||||
|
||||
|
||||
def test_failed_flow_reports_its_duration_and_outcome(
|
||||
durations: list[tuple[str, float, str]],
|
||||
) -> None:
|
||||
class SlowBoomFlow(Flow):
|
||||
@start()
|
||||
def go(self) -> str:
|
||||
time.sleep(0.05)
|
||||
raise RuntimeError("boom")
|
||||
|
||||
with pytest.raises(RuntimeError, match="boom"):
|
||||
SlowBoomFlow().kickoff()
|
||||
|
||||
assert len(durations) == 1
|
||||
flow_name, duration_ms, outcome = durations[0]
|
||||
assert flow_name == "SlowBoomFlow"
|
||||
assert outcome == "failed"
|
||||
assert duration_ms >= 50
|
||||
|
||||
|
||||
def test_no_duration_is_reported_without_a_recorded_start(
|
||||
durations: list[tuple[str, float, str]],
|
||||
) -> None:
|
||||
"""A completion with no observed start reports nothing, and does not raise.
|
||||
|
||||
A conversational turn can re-emit completion for a restored run, so the
|
||||
stamp is genuinely absent rather than impossible.
|
||||
"""
|
||||
from crewai.events.event_bus import crewai_event_bus
|
||||
from crewai.events.types.flow_events import FlowFinishedEvent
|
||||
|
||||
class NeverStartedFlow(Flow):
|
||||
@start()
|
||||
def go(self) -> str:
|
||||
return "ok"
|
||||
|
||||
flow = NeverStartedFlow()
|
||||
crewai_event_bus.emit(
|
||||
flow,
|
||||
FlowFinishedEvent(flow_name="NeverStartedFlow", result="ok", state={}),
|
||||
)
|
||||
|
||||
assert durations == []
|
||||
|
||||
|
||||
def test_duration_is_reported_once_per_run(
|
||||
durations: list[tuple[str, float, str]],
|
||||
) -> None:
|
||||
"""The stamp is cleared on use, so a repeated completion cannot double-count."""
|
||||
from crewai.events.event_bus import crewai_event_bus
|
||||
from crewai.events.types.flow_events import FlowFinishedEvent
|
||||
|
||||
class OkFlow(Flow):
|
||||
@start()
|
||||
def go(self) -> str:
|
||||
return "ok"
|
||||
|
||||
flow = OkFlow()
|
||||
flow.kickoff()
|
||||
crewai_event_bus.emit(
|
||||
flow, FlowFinishedEvent(flow_name="OkFlow", result="ok", state={})
|
||||
)
|
||||
|
||||
assert len(durations) == 1
|
||||
|
||||
Reference in New Issue
Block a user