From 22fc5bcfdbe699e168a5841ccf90f7055a461167 Mon Sep 17 00:00:00 2001 From: Joey Tong Date: Mon, 3 Aug 2026 17:08:52 +0800 Subject: [PATCH 01/10] [runtime][plan][python] Add built-in operational metrics Derive input-run, Action, LLM, Tool, Skill, and MCP metrics from runtime lifecycle boundaries. Rebuild current-count gauges from Flink state and align Java and Python retry metrics under the model resource scope. Co-Authored-By: Claude Code AI-Model: gpt-5 AI-Contributed/Feature: 1214/1214 AI-Contributed/UT: 653/653 --- docs/content/docs/operations/monitoring.md | 49 +++- .../agents/plan/actions/ChatModelAction.java | 22 +- .../actions/ChatModelActionRetryTest.java | 7 +- .../actions/ChatModelActionRoutingTest.java | 28 ++- .../plan/actions/chat_model_action.py | 156 ++++++------ .../actions/test_chat_model_action_retry.py | 17 +- .../flink/agents/runtime/CompileUtils.java | 7 +- .../runtime/metrics/BuiltInActionMetrics.java | 107 ++++++++- .../metrics/BuiltInExecutionMetrics.java | 95 ++++++++ .../metrics/BuiltInInputRunMetrics.java | 197 +++++++++++++++ .../runtime/metrics/BuiltInMetrics.java | 98 +++++++- .../runtime/metrics/CurrentCountGauge.java | 49 ++++ .../metrics/ExecutionMetricRecorder.java | 42 ++++ .../metrics/LlmExecutionMetricRecorder.java | 60 +++++ .../metrics/ToolExecutionMetricRecorder.java | 109 +++++++++ .../operator/ActionExecutionOperator.java | 202 +++++++++++----- .../operator/OperatorStateManager.java | 18 +- .../runtime/trace/ExecutionEventSink.java | 2 +- .../agents/runtime/CompileUtilsTest.java | 25 ++ .../metrics/BuiltInActionMetricsTest.java | 130 ++++++++++ .../metrics/BuiltInExecutionMetricsTest.java | 224 ++++++++++++++++++ .../metrics/BuiltInInputRunMetricsTest.java | 222 +++++++++++++++++ 22 files changed, 1686 insertions(+), 180 deletions(-) create mode 100644 runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetrics.java create mode 100644 runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInInputRunMetrics.java create mode 100644 runtime/src/main/java/org/apache/flink/agents/runtime/metrics/CurrentCountGauge.java create mode 100644 runtime/src/main/java/org/apache/flink/agents/runtime/metrics/ExecutionMetricRecorder.java create mode 100644 runtime/src/main/java/org/apache/flink/agents/runtime/metrics/LlmExecutionMetricRecorder.java create mode 100644 runtime/src/main/java/org/apache/flink/agents/runtime/metrics/ToolExecutionMetricRecorder.java create mode 100644 runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInActionMetricsTest.java create mode 100644 runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetricsTest.java create mode 100644 runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInInputRunMetricsTest.java diff --git a/docs/content/docs/operations/monitoring.md b/docs/content/docs/operations/monitoring.md index 652c9bfe9..394b3478b 100644 --- a/docs/content/docs/operations/monitoring.md +++ b/docs/content/docs/operations/monitoring.md @@ -26,7 +26,7 @@ under the License. ### Built-in Metrics -We offer data monitoring for built-in metrics, which includes events, actions, and token usage. +We offer data monitoring for built-in metrics, including input runs, events, actions, execution health, and token usage. #### Event and Action Metrics @@ -36,11 +36,54 @@ We offer data monitoring for built-in metrics, which includes events, actions, a | **Agent** | numOfEventProcessedPerSec | The number of Events this operator has processed per second. | Meter | | **Agent** | numOfActionsExecuted | The total number of actions this operator has executed. | Count | | **Agent** | numOfActionsExecutedPerSec | The number of actions this operator has executed per second. | Meter | +| **Agent** | numOfInputRunsSucceeded | The number of input runs that reached the run-completion boundary. | Count | +| **Agent** | numOfInputRunsFailed | The number of input runs terminated by an unhandled exception. | Count | +| **Agent** | inputRunLatencyMs | End-to-end input-run latency from entering the agent operator to completion or failure, including time queued behind another input with the same key. | Histogram | +| **Agent** | inputRunQueueLatencyMs | Time from entering the agent operator until the input run starts processing. | Histogram | +| **Agent** | inputRunProcessingLatencyMs | Time from the input-run start boundary until completion or failure. | Histogram | +| **Agent** | numOfPendingInputEvents | Current number of input Events buffered behind an active run with the same key. | Gauge | +| **Agent** | numOfActiveInputRuns | Current number of logical input runs that are processing or waiting for asynchronous work. | Gauge | | **Action** | action.\.numOfActionsExecuted | The total number of actions this operator has executed for a specific action name. | Count | | **Action** | action.\.numOfActionsExecutedPerSec | The number of actions this operator has executed per second for a specific action name. | Meter | +| **Action** | action.\.actionSchedulingLatencyMs | Time from enqueuing the initial Action task until it is selected for execution. | Histogram | +| **Action** | action.\.actionExecutionLatencyMs | End-to-end latency of one logical Action execution, including asynchronous waits and continuations. | Histogram | +| **Action** | action.\.numOfPendingActionTasks | Current number of physical Action task segments waiting to run, including continuations. | Gauge | +| **Action** | action.\.numOfActiveActionExecutions | Current number of logical Action executions that have started but have not reached a terminal state. | Gauge | | **Agent** | eventLogTruncatedEvents | Number of event log records whose payload was truncated at `STANDARD` level. Increments once per event, regardless of how many fields inside it were truncated. Use this to decide whether to raise truncation thresholds or move specific event types to `VERBOSE`. | Count | | **Agent** | eventLogWriteFailures | Number of Event Log write attempts for which `append`, `flush`, or both failed. Event Log writes are best-effort and do not fail the job. | Count | +For a locally observed input run, `inputRunLatencyMs` is split into queueing and processing time at the input-run start boundary. `numOfPendingInputEvents` counts buffered inputs, while `numOfActiveInputRuns` counts logical runs; an asynchronous run remains active while it is waiting for its continuation. + +An Action execution can be active while one of its continuation tasks is pending, so `numOfActiveActionExecutions` and `numOfPendingActionTasks` are independent. Action scheduling latency is recorded only for the initial task; continuation queueing does not create another scheduling sample. + +Input-run outcomes and all latency samples are process-local. Runs or Action executions already in flight when a task is restored do not produce latency samples because their original timestamps are unavailable. An input Event restored from the pending queue can still produce an outcome and processing-latency sample after it starts in the new task attempt, but it does not produce queue or end-to-end latency. Current-count gauges are rebuilt from Flink state after restore. + +#### Execution Metrics + +Execution metrics are derived from LLM and Tool execution lifecycle events. The `model_resource`, `tool`, `skill`, and `mcp_server` scopes are independent key-value scopes directly under an Action; none is nested under another. The existing `model` scope remains dedicated to model usage metrics. + +| Scope | Metrics | Description | Type | +|-------|---------|-------------|------| +| **Model Resource** | action.\.model_resource.\.numOfLlmCallsSucceeded | The number of framework-observed model invocations that returned successfully. | Count | +| **Model Resource** | action.\.model_resource.\.numOfLlmCallsFailed | The number of framework-observed model invocations that failed. | Count | +| **Model Resource** | action.\.model_resource.\.llmCallLatencyMs | Latency of each framework-observed model invocation, excluding structured-output parsing and retry wait time. | Histogram | +| **Model Resource** | action.\.model_resource.\.retryCount | The number of additional model invocations initiated by framework retry logic. Only recorded when at least one retry occurs. See [retry-wait-interval]({{< ref "docs/operations/configuration#core-options" >}}). | Count | +| **Model Resource** | action.\.model_resource.\.retryWaitSec | The total backoff time, in seconds, accumulated by framework-level retries. | Count | +| **Tool** | action.\.tool.\.numOfToolCallsSucceeded | The number of successful calls to the Tool. | Count | +| **Tool** | action.\.tool.\.numOfToolCallsFailed | The number of failed calls to the Tool. | Count | +| **Tool** | action.\.tool.\.toolCallLatencyMs | Tool call latency. | Histogram | +| **Skill** | action.\.skill.\.numOfSkillLoads | The number of completed explicit `load_skill` calls for the Skill. | Count | +| **Skill** | action.\.skill.\.skillLoadLatencyMs | Latency of explicit `load_skill` calls. | Histogram | +| **MCP Server** | action.\.mcp_server.\.numOfMcpToolCallsSucceeded | The number of successful Tool calls served by the MCP Server. | Count | +| **MCP Server** | action.\.mcp_server.\.numOfMcpToolCallsFailed | The number of failed Tool calls served by the MCP Server. | Count | +| **MCP Server** | action.\.mcp_server.\.mcpToolCallLatencyMs | Tool call latency aggregated across the MCP Server. | Histogram | + +An LLM metric represents one framework invocation of `ChatModel`. A framework retry that calls the model again produces another LLM outcome and latency sample; retries hidden inside a provider or connection are not observed. Every named Tool execution emits Tool metrics. Skill metrics are emitted only for explicit `load_skill` calls; subsequent Tool calls are not inferred to belong to a Skill. MCP metrics aggregate only Tool executions carrying an explicit MCP Server resource name. A `load_skill` or MCP Tool execution therefore contributes to both its Tool scope and the corresponding Skill or MCP Server scope. + +Tool outcomes follow the existing language-specific Tool contracts. In both Java and Python, resource preparation or invocation exceptions are failures and a normal return is successful. Java additionally treats an unsuccessful `ToolResponse` as a failed Tool execution. Python Tools return arbitrary values and currently have no equivalent explicit error-result type, so the runtime does not infer failure from a normally returned Python value. + +Execution latency tracking is process-local. A latency sample is recorded only when the execution start and terminal events are observed in the same task attempt; LLM and Tool terminal counters are still updated when a restored execution has no local start timestamp. + #### Token Usage Metrics Token usage metrics are automatically recorded when chat models are invoked through `ChatModelConnection`. These metrics help track LLM API usage and costs. @@ -49,8 +92,6 @@ Token usage metrics are automatically recorded when chat models are invoked thro |-----------|--------------------------------------------------------------|--------------------------------------------------------------------------------|-------| | **Model** | action.\.model.\.promptTokens | The total number of prompt tokens consumed by the model within an action. | Count | | **Model** | action.\.model.\.completionTokens | The total number of completion tokens generated by the model within an action. | Count | -| **Model** | action.\.model.\.retryCount | The total number of retries performed for model requests when using `ErrorHandlingStrategy.RETRY`. Only recorded when at least one retry occurs. See [retry-wait-interval]({{< ref "docs/operations/configuration#core-options" >}}). | Count | -| **Model** | action.\.model.\.retryWaitSec | The total wait time (in seconds) spent across retries for model requests when using `ErrorHandlingStrategy.RETRY`. | Count | ### How to add custom metrics @@ -116,7 +157,7 @@ public class MyAgent extends Agent { ### How to check the metrics with Flink executor -Flink agents enable the reporting of metrics to external systems by creating a metric identifier prefix in the format `.taskmanager....`. Agent-specific metrics use key-value metric groups (e.g., `action.`, `model.`) which are exposed as dimensions/labels in reporters that support them (such as Prometheus). Please refer to [Flink Metric Reporters](https://nightlies.apache.org/flink/flink-docs-release-1.20/docs/deployment/metric_reporters/) for more details. +Flink agents enable the reporting of metrics to external systems by creating a metric identifier prefix in the format `.taskmanager....`. For an agent operator, `` is the agent name. Agent-specific metrics use key-value metric groups (e.g., `action.`, `model.`) which are exposed as dimensions/labels in reporters that support them (such as Prometheus). Please refer to [Flink Metric Reporters](https://nightlies.apache.org/flink/flink-docs-release-1.20/docs/deployment/metric_reporters/) for more details. Additionally, we can check the metric results in the Flink Job WebUI using the metric identifier prefix `.`. diff --git a/plan/src/main/java/org/apache/flink/agents/plan/actions/ChatModelAction.java b/plan/src/main/java/org/apache/flink/agents/plan/actions/ChatModelAction.java index 57c191c75..cd4ec6edf 100644 --- a/plan/src/main/java/org/apache/flink/agents/plan/actions/ChatModelAction.java +++ b/plan/src/main/java/org/apache/flink/agents/plan/actions/ChatModelAction.java @@ -203,15 +203,16 @@ private static Map getRetryStats(MemoryObject sensoryMem, UUID ini } private static void recordRetryMetrics( - RunnerContext ctx, String model, int retryCount, int totalRetryWaitSec) { + RunnerContext ctx, String modelResource, int retryCount, int totalRetryWaitSec) { if (retryCount <= 0) { return; } FlinkAgentsMetricGroup metricGroup = ctx.getActionMetricGroup(); if (metricGroup != null) { - FlinkAgentsMetricGroup modelGroup = metricGroup.getSubGroup("model", model); - modelGroup.getCounter("retryCount").inc(retryCount); - modelGroup.getCounter("retryWaitSec").inc(totalRetryWaitSec); + FlinkAgentsMetricGroup modelResourceGroup = + metricGroup.getSubGroup("model_resource", modelResource); + modelResourceGroup.getCounter("retryCount").inc(retryCount); + modelResourceGroup.getCounter("retryWaitSec").inc(totalRetryWaitSec); } } @@ -412,7 +413,7 @@ private static void chat( recordAttemptRetryStats( ctx, initialRequestId, - result.chatModel, + result.model, result.retryCount, result.totalRetryWaitSec); if (selection.isRouter) { @@ -481,7 +482,7 @@ private static void chat( return; } catch (ChatModelInvoker.ChatAttemptFailed e) { recordAttemptRetryStats( - ctx, initialRequestId, e.chatModel, e.retryCount, e.totalRetryWaitSec); + ctx, initialRequestId, e.model, e.retryCount, e.totalRetryWaitSec); // Keep every candidate's failure: chain the previous error into the new one so // exhaustion surfaces A's and B's errors as suppressed of C's, not just C's. if (lastError != null && lastError != e.error) { @@ -525,7 +526,7 @@ private static void chat( private static void recordAttemptRetryStats( RunnerContext ctx, UUID initialRequestId, - BaseChatModelSetup chatModel, + String modelResource, int retryCount, int retryWaitSec) throws Exception { @@ -533,12 +534,7 @@ private static void recordAttemptRetryStats( return; } accumulateRetryStats(ctx.getSensoryMemory(), initialRequestId, retryCount, retryWaitSec); - String metricModel = chatModel == null ? null : chatModel.getConnectionName(); - recordRetryMetrics( - ctx, - metricModel == null || metricModel.isEmpty() ? "unknown" : metricModel, - retryCount, - retryWaitSec); + recordRetryMetrics(ctx, modelResource, retryCount, retryWaitSec); } /** diff --git a/plan/src/test/java/org/apache/flink/agents/plan/actions/ChatModelActionRetryTest.java b/plan/src/test/java/org/apache/flink/agents/plan/actions/ChatModelActionRetryTest.java index a1d7b0cf3..c9ee0513c 100644 --- a/plan/src/test/java/org/apache/flink/agents/plan/actions/ChatModelActionRetryTest.java +++ b/plan/src/test/java/org/apache/flink/agents/plan/actions/ChatModelActionRetryTest.java @@ -323,8 +323,8 @@ void chatRetriesWithExponentialBackoff() throws Exception { assertThat(responseEvent.getTotalRetryWaitSec()).isEqualTo(1); assertThat(elapsed).isGreaterThanOrEqualTo(1000L); - // Verify metrics recorded under connection name - verify(mockActionMetricGroup).getSubGroup("model", mockChatModel.getConnectionName()); + // Retry health belongs to the ChatModel resource, not the provider connection or model. + verify(mockActionMetricGroup).getSubGroup("model_resource", "test-model"); verify(mockRetryCountCounter).inc(1); verify(mockRetryWaitSecCounter).inc(1); } @@ -351,6 +351,9 @@ void chatExhaustsRetriesAndThrows() { .hasMessage("persistent error"); assertThat(sentEvents).isEmpty(); + verify(mockActionMetricGroup).getSubGroup("model_resource", "test-model"); + verify(mockRetryCountCounter).inc(2); + verify(mockRetryWaitSecCounter).inc(0); } @Test diff --git a/plan/src/test/java/org/apache/flink/agents/plan/actions/ChatModelActionRoutingTest.java b/plan/src/test/java/org/apache/flink/agents/plan/actions/ChatModelActionRoutingTest.java index 5964a2051..25bcb17a7 100644 --- a/plan/src/test/java/org/apache/flink/agents/plan/actions/ChatModelActionRoutingTest.java +++ b/plan/src/test/java/org/apache/flink/agents/plan/actions/ChatModelActionRoutingTest.java @@ -46,6 +46,8 @@ import org.apache.flink.agents.api.resource.ResourceType; import org.apache.flink.agents.api.tools.ToolResponse; import org.apache.flink.agents.plan.AgentConfiguration; +import org.apache.flink.metrics.Counter; +import org.apache.flink.metrics.Histogram; import org.junit.jupiter.api.Test; import java.util.ArrayDeque; @@ -60,6 +62,9 @@ import static org.assertj.core.api.Assertions.assertThat; import static org.assertj.core.api.Assertions.assertThatThrownBy; +import static org.mockito.Mockito.mock; +import static org.mockito.Mockito.verify; +import static org.mockito.Mockito.when; /** Integration tests for model routing inside {@link ChatModelAction}. */ public class ChatModelActionRoutingTest { @@ -117,6 +122,7 @@ static class FakeRunnerContext implements RunnerContext { private final ModelRouter router; private final MemoryObject sensoryMemory = new FakeMemoryObject(new HashMap<>()); private final AgentConfiguration config = new AgentConfiguration(Map.of()); + private FlinkAgentsMetricGroup actionMetricGroup; FakeRunnerContext(ModelRouter router) { this.router = router; @@ -144,6 +150,11 @@ FakeRunnerContext withRetryBudget(int maxRetries, int waitIntervalSec) { return this; } + FakeRunnerContext withActionMetricGroup(FlinkAgentsMetricGroup actionMetricGroup) { + this.actionMetricGroup = actionMetricGroup; + return this; + } + @Override public boolean hasResource(String name, ResourceType type) { return type == ResourceType.MODEL_ROUTER && "router".equals(name) && router != null; @@ -191,7 +202,7 @@ public FlinkAgentsMetricGroup getAgentMetricGroup() { @Override public FlinkAgentsMetricGroup getActionMetricGroup() { - return null; + return actionMetricGroup; } @Override @@ -394,6 +405,17 @@ void routedRequestUsesRoutedDurableCallIds() throws Exception { @Test void retryBudgetRunsBeforeFallback() throws Exception { + FlinkAgentsMetricGroup actionMetricGroup = mock(FlinkAgentsMetricGroup.class); + FlinkAgentsMetricGroup modelResourceMetricGroup = mock(FlinkAgentsMetricGroup.class); + Counter retryCount = mock(Counter.class); + Counter retryWaitSec = mock(Counter.class); + when(actionMetricGroup.getHistogram("routingDecisionLatencyMs")) + .thenReturn(mock(Histogram.class)); + when(actionMetricGroup.getSubGroup("model_resource", "big")) + .thenReturn(modelResourceMetricGroup); + when(modelResourceMetricGroup.getCounter("retryCount")).thenReturn(retryCount); + when(modelResourceMetricGroup.getCounter("retryWaitSec")).thenReturn(retryWaitSec); + ModelRouter router = new ModelRouter( ModelRouter.of("small", "big") @@ -406,6 +428,7 @@ void retryBudgetRunsBeforeFallback() throws Exception { new FakeRunnerContext(router) .withErrorHandling(Agent.ErrorHandlingStrategy.RETRY) .withRetryBudget(1, 0) + .withActionMetricGroup(actionMetricGroup) .register( "big", new FakeChatModel( @@ -422,6 +445,9 @@ void retryBudgetRunsBeforeFallback() throws Exception { assertThat(ctx.chatResponse().getResponse().getContent()).isEqualTo("recovered on retry"); assertThat(ctx.resolvedChatModels).containsExactly("big"); assertThat(ctx.routingEventCount()).isEqualTo(1L); + verify(actionMetricGroup).getSubGroup("model_resource", "big"); + verify(retryCount).inc(1); + verify(retryWaitSec).inc(0); } @Test diff --git a/python/flink_agents/plan/actions/chat_model_action.py b/python/flink_agents/plan/actions/chat_model_action.py index 0b6e7f4ae..fd9557ce4 100644 --- a/python/flink_agents/plan/actions/chat_model_action.py +++ b/python/flink_agents/plan/actions/chat_model_action.py @@ -182,16 +182,21 @@ def _get_retry_stats( def _record_retry_metrics( - ctx: RunnerContext, model: str, retry_count: int, total_retry_wait_sec: int + ctx: RunnerContext, + model_resource: str, + retry_count: int, + total_retry_wait_sec: int, ) -> None: - """Record retry metrics under the connection name if retries occurred.""" + """Record retry metrics under the ChatModel resource if retries occurred.""" if retry_count <= 0: return metric_group = ctx.action_metric_group if metric_group is not None: - model_group = metric_group.get_sub_group("model", model) - model_group.get_counter("retryCount").inc(retry_count) - model_group.get_counter("retryWaitSec").inc(total_retry_wait_sec) + model_resource_group = metric_group.get_sub_group( + "model_resource", model_resource + ) + model_resource_group.get_counter("retryCount").inc(retry_count) + model_resource_group.get_counter("retryWaitSec").inc(total_retry_wait_sec) def _inject_bash_tool_args( @@ -352,78 +357,81 @@ async def chat( total_wait_time_sec = 0 llm_metadata = {LLMExecutionMetadataKeys.MODEL: chat_model.model} - for attempt in range(num_retries + 1): - try: - ExecutionReporters.started( - ctx, ExecutionEntityTypes.LLM, model, llm_metadata - ) + try: + for attempt in range(num_retries + 1): try: - if chat_async: - response = await ctx.durable_execute_async( - chat_model.chat, messages, prompt_args=prompt_args - ) - else: - response = ctx.durable_execute( - chat_model.chat, messages, prompt_args=prompt_args + ExecutionReporters.started( + ctx, ExecutionEntityTypes.LLM, model, llm_metadata + ) + try: + if chat_async: + response = await ctx.durable_execute_async( + chat_model.chat, messages, prompt_args=prompt_args + ) + else: + response = ctx.durable_execute( + chat_model.chat, messages, prompt_args=prompt_args + ) + response = _require_model_response(response) + except Exception as model_error: + ExecutionReporters.failed( + ctx, + ExecutionEntityTypes.LLM, + model, + llm_metadata, + model_error, + ExecutionProblemCategories.MODEL_CALL_FAILED, ) - response = _require_model_response(response) - except Exception as model_error: - ExecutionReporters.failed( - ctx, - ExecutionEntityTypes.LLM, - model, - llm_metadata, - model_error, - ExecutionProblemCategories.MODEL_CALL_FAILED, + raise + ExecutionReporters.succeeded( + ctx, ExecutionEntityTypes.LLM, model, llm_metadata ) - raise - ExecutionReporters.succeeded( - ctx, ExecutionEntityTypes.LLM, model, llm_metadata - ) - if ( - request_metric_group is not None - and response.extra_args.get("model_name") - and response.extra_args.get("promptTokens") - and response.extra_args.get("completionTokens") - ): - chat_model._record_token_metrics( - response.extra_args["model_name"], - response.extra_args["promptTokens"], - response.extra_args["completionTokens"], - request_metric_group, - ) - if output_schema is not None and len(response.tool_calls) == 0: - response = _generate_structured_output_with_report( - ctx, response, output_schema - ) - break - except Exception as e: - if error_handling_strategy == ErrorHandlingStrategy.IGNORE: - _logger.warning( - f"Chat request {initial_request_id} failed with error: {e}, ignored." - ) - return - elif error_handling_strategy == ErrorHandlingStrategy.RETRY: - if attempt == num_retries: + if ( + request_metric_group is not None + and response.extra_args.get("model_name") + and response.extra_args.get("promptTokens") + and response.extra_args.get("completionTokens") + ): + chat_model._record_token_metrics( + response.extra_args["model_name"], + response.extra_args["promptTokens"], + response.extra_args["completionTokens"], + request_metric_group, + ) + if output_schema is not None and len(response.tool_calls) == 0: + response = _generate_structured_output_with_report( + ctx, response, output_schema + ) + break + except Exception as e: + if error_handling_strategy == ErrorHandlingStrategy.IGNORE: + _logger.warning( + f"Chat request {initial_request_id} failed with error: {e}, ignored." + ) + return + elif error_handling_strategy == ErrorHandlingStrategy.RETRY: + if attempt == num_retries: + raise + actual_retry_count = attempt + 1 + current_wait_sec = retry_wait_interval_sec * ( + 1 << (actual_retry_count - 1) + ) + _logger.warning( + f"Chat request {initial_request_id} failed with error: {e}, " + f"retrying {actual_retry_count} / {num_retries}, " + f"waiting {current_wait_sec} s." + ) + if current_wait_sec > 0: + time.sleep(current_wait_sec) + total_wait_time_sec += current_wait_sec + else: + _logger.debug( + f"Chat request {initial_request_id} failed, the input chat messages are {messages}." + ) raise - actual_retry_count = attempt + 1 - current_wait_sec = retry_wait_interval_sec * ( - 1 << (actual_retry_count - 1) - ) - _logger.warning( - f"Chat request {initial_request_id} failed with error: {e}, " - f"retrying {actual_retry_count} / {num_retries}, " - f"waiting {current_wait_sec} s." - ) - if current_wait_sec > 0: - time.sleep(current_wait_sec) - total_wait_time_sec += current_wait_sec - else: - _logger.debug( - f"Chat request {initial_request_id} failed, the input chat messages are {messages}." - ) - raise + finally: + _record_retry_metrics(ctx, model, actual_retry_count, total_wait_time_sec) if actual_retry_count > 0: _accumulate_retry_stats( @@ -451,10 +459,6 @@ async def chat( total_retry_count = retry_stats["total_retry_count"] total_retry_wait_sec = retry_stats["total_retry_wait_sec"] - _record_retry_metrics( - ctx, chat_model.connection, total_retry_count, total_retry_wait_sec - ) - ctx.send_event( ChatResponseEvent( request_id=initial_request_id, diff --git a/python/flink_agents/plan/tests/actions/test_chat_model_action_retry.py b/python/flink_agents/plan/tests/actions/test_chat_model_action_retry.py index f73648aa8..5ad7e1220 100644 --- a/python/flink_agents/plan/tests/actions/test_chat_model_action_retry.py +++ b/python/flink_agents/plan/tests/actions/test_chat_model_action_retry.py @@ -245,10 +245,12 @@ def mock_chat(messages: Sequence[ChatMessage], **kwargs: Any) -> ChatMessage: assert event.total_retry_wait_sec == 1 assert elapsed >= 1.0 - # Verify metrics recorded under connection name - model_group = metric_group.get_sub_group("model", chat_model.connection) - assert model_group.get_counter("retryCount").get_count() == 1 - assert model_group.get_counter("retryWaitSec").get_count() == 1 + # Retry health belongs to the ChatModel resource. + model_resource_group = metric_group.get_sub_group( + "model_resource", "test-model" + ) + assert model_resource_group.get_counter("retryCount").get_count() == 1 + assert model_resource_group.get_counter("retryWaitSec").get_count() == 1 assert ctx.report_execution_started.call_count == 2 ctx.report_execution_failed.assert_called_once() failed_args = ctx.report_execution_failed.call_args.args @@ -266,7 +268,7 @@ def test_chat_exhausts_retries_and_raises(self) -> None: chat_model = MagicMock() chat_model.chat = MagicMock(side_effect=RuntimeError("persistent error")) - ctx, sent_events, _, _ = _create_mock_runner_context( + ctx, sent_events, metric_group, _ = _create_mock_runner_context( chat_model, max_retries=2, retry_wait_interval_sec=0 ) request_id = uuid4() @@ -291,6 +293,11 @@ def test_chat_exhausts_retries_and_raises(self) -> None: assert failed_call.args[2] == _LLM_METADATA assert failed_call.args[-1] == ExecutionProblemCategories.MODEL_CALL_FAILED ctx.report_execution_succeeded.assert_not_called() + model_resource_group = metric_group.get_sub_group( + "model_resource", "test-model" + ) + assert model_resource_group.get_counter("retryCount").get_count() == 2 + assert model_resource_group.get_counter("retryWaitSec").get_count() == 0 def test_structured_output_parse_error_retries_without_failing_llm( self, diff --git a/runtime/src/main/java/org/apache/flink/agents/runtime/CompileUtils.java b/runtime/src/main/java/org/apache/flink/agents/runtime/CompileUtils.java index c1bf0805c..cd12249e1 100644 --- a/runtime/src/main/java/org/apache/flink/agents/runtime/CompileUtils.java +++ b/runtime/src/main/java/org/apache/flink/agents/runtime/CompileUtils.java @@ -29,6 +29,7 @@ import org.apache.flink.streaming.api.datastream.KeyedStream; import org.apache.flink.streaming.api.typeinfo.python.PickledByteArrayTypeInfo; import org.apache.flink.types.Row; +import org.apache.flink.util.StringUtils; import static org.apache.flink.util.Preconditions.checkArgument; @@ -37,6 +38,7 @@ public class CompileUtils { private static final int PYTHON_KEY_FIELD_INDEX = 0; private static final int PYTHON_VALUE_FIELD_INDEX = 1; + private static final String DEFAULT_OPERATOR_NAME = "action-execute-operator"; // ============================ invoke by python ==================================== public static DataStream connectToAgent( @@ -97,10 +99,13 @@ private static DataStream connectToAgent( TypeInformation outTypeInformation, boolean inputIsJava, boolean pythonKeyIsPickled) { + String agentName = agentPlan.getAgentName(); + String operatorName = + StringUtils.isNullOrWhitespaceOnly(agentName) ? DEFAULT_OPERATOR_NAME : agentName; return (DataStream) keyedInputStream .transform( - "action-execute-operator", + operatorName, outTypeInformation, new ActionExecutionOperatorFactory( agentPlan, inputIsJava, pythonKeyIsPickled)) diff --git a/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInActionMetrics.java b/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInActionMetrics.java index 2a518ef34..304557729 100644 --- a/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInActionMetrics.java +++ b/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInActionMetrics.java @@ -19,26 +19,123 @@ package org.apache.flink.agents.runtime.metrics; +import org.apache.flink.agents.api.Event; +import org.apache.flink.agents.api.trace.ExecutionLifecycleEvents; +import org.apache.flink.agents.api.trace.ExecutionTraceContext; import org.apache.flink.metrics.Counter; +import org.apache.flink.metrics.Histogram; import org.apache.flink.metrics.Meter; -/** - * ActionMetricGroup class extends FlinkAgentsMetricGroupImpl and is used to monitor and measure the - * performance metrics of executing actions. It provides metrics for the total number of actions - * executed and the number of actions executed per second. - */ +import java.util.HashMap; +import java.util.Map; +import java.util.OptionalLong; +import java.util.concurrent.TimeUnit; +import java.util.function.LongSupplier; + +/** Tracks execution rate, scheduling latency, and current task/execution counts for one Action. */ public class BuiltInActionMetrics { + static final String ACTION_SCHEDULING_LATENCY_MS = "actionSchedulingLatencyMs"; + static final String ACTION_EXECUTION_LATENCY_MS = "actionExecutionLatencyMs"; + static final String NUM_PENDING_ACTION_TASKS = "numOfPendingActionTasks"; + static final String NUM_ACTIVE_ACTION_EXECUTIONS = "numOfActiveActionExecutions"; + private final Meter numOfActionsExecutedPerSec; + private final Histogram schedulingLatencyHistogram; + private final Histogram executionLatencyHistogram; + private final CurrentCountGauge pendingActionTasks; + private final CurrentCountGauge activeActionExecutions; + private final LongSupplier nanoTime; + + private final Map initialTaskEnqueueNanos = new HashMap<>(); + private final Map activeExecutions = new HashMap<>(); public BuiltInActionMetrics(FlinkAgentsMetricGroupImpl parentMetricGroup) { + this(parentMetricGroup, System::nanoTime); + } + + BuiltInActionMetrics(FlinkAgentsMetricGroupImpl parentMetricGroup, LongSupplier nanoTime) { Counter numOfActionsExecuted = parentMetricGroup.getCounter("numOfActionsExecuted"); this.numOfActionsExecutedPerSec = parentMetricGroup.getMeter("numOfActionsExecutedPerSec", numOfActionsExecuted); + this.schedulingLatencyHistogram = + parentMetricGroup.getHistogram(ACTION_SCHEDULING_LATENCY_MS); + this.executionLatencyHistogram = + parentMetricGroup.getHistogram(ACTION_EXECUTION_LATENCY_MS); + this.pendingActionTasks = + new CurrentCountGauge(parentMetricGroup, NUM_PENDING_ACTION_TASKS); + this.activeActionExecutions = + new CurrentCountGauge(parentMetricGroup, NUM_ACTIVE_ACTION_EXECUTIONS); + this.nanoTime = nanoTime; } /** Marks that an action has finished executing. */ public void markActionExecuted() { numOfActionsExecutedPerSec.markEvent(); } + + void actionTaskEnqueued(String executionId, boolean executionStarted) { + pendingActionTasks.increment(); + if (!executionStarted && !isBlank(executionId)) { + initialTaskEnqueueNanos.putIfAbsent(executionId, nanoTime.getAsLong()); + } + } + + void actionTaskDequeued(String executionId, boolean executionStarted) { + pendingActionTasks.decrement(); + if (executionStarted || isBlank(executionId)) { + return; + } + + Long enqueueNanos = initialTaskEnqueueNanos.remove(executionId); + if (enqueueNanos != null) { + schedulingLatencyHistogram.update( + TimeUnit.NANOSECONDS.toMillis( + Math.max(0L, nanoTime.getAsLong() - enqueueNanos))); + } + } + + void restoreActionTask(String executionId, boolean executionStarted) { + pendingActionTasks.increment(); + if (executionStarted + && !isBlank(executionId) + && activeExecutions.putIfAbsent(executionId, OptionalLong.empty()) == null) { + activeActionExecutions.increment(); + } + } + + void executionEventObserved(Event event, ExecutionTraceContext traceContext) { + String executionId = traceContext.getExecutionId(); + if (isBlank(executionId)) { + return; + } + + if (ExecutionLifecycleEvents.EXECUTION_STARTED_EVENT_TYPE.equals(event.getType())) { + if (activeExecutions.putIfAbsent(executionId, OptionalLong.of(nanoTime.getAsLong())) + == null) { + activeActionExecutions.increment(); + } + return; + } + + if (!ExecutionLifecycleEvents.EXECUTION_FINISHED_EVENT_TYPE.equals(event.getType()) + && !ExecutionLifecycleEvents.EXECUTION_FAILED_EVENT_TYPE.equals(event.getType())) { + return; + } + + OptionalLong startNanos = activeExecutions.remove(executionId); + if (startNanos == null) { + return; + } + activeActionExecutions.decrement(); + if (startNanos.isPresent()) { + executionLatencyHistogram.update( + TimeUnit.NANOSECONDS.toMillis( + Math.max(0L, nanoTime.getAsLong() - startNanos.getAsLong()))); + } + } + + private static boolean isBlank(String value) { + return value == null || value.isBlank(); + } } diff --git a/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetrics.java b/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetrics.java new file mode 100644 index 000000000..6dc9c3a1b --- /dev/null +++ b/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetrics.java @@ -0,0 +1,95 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ +package org.apache.flink.agents.runtime.metrics; + +import org.apache.flink.agents.api.Event; +import org.apache.flink.agents.api.trace.ExecutionLifecycleEvents; +import org.apache.flink.agents.api.trace.ExecutionTraceContext; + +import java.util.HashMap; +import java.util.Map; +import java.util.concurrent.TimeUnit; +import java.util.function.LongSupplier; + +/** Derives built-in LLM and Tool metrics from execution lifecycle events. */ +final class BuiltInExecutionMetrics { + + private final FlinkAgentsMetricGroupImpl agentMetricGroup; + private final LongSupplier nanoTime; + private final Map metricRecordersByEntityType; + private final Map activeExecutionStartNanos = new HashMap<>(); + + BuiltInExecutionMetrics(FlinkAgentsMetricGroupImpl agentMetricGroup, LongSupplier nanoTime) { + this.agentMetricGroup = agentMetricGroup; + this.nanoTime = nanoTime; + ExecutionMetricRecorder llmMetricRecorder = new LlmExecutionMetricRecorder(); + ExecutionMetricRecorder toolMetricRecorder = new ToolExecutionMetricRecorder(); + this.metricRecordersByEntityType = + Map.of( + llmMetricRecorder.entityType(), + llmMetricRecorder, + toolMetricRecorder.entityType(), + toolMetricRecorder); + } + + void executionEventObserved( + String actionName, Event event, ExecutionTraceContext traceContext) { + ExecutionMetricRecorder recorder = + metricRecordersByEntityType.get(traceContext.getEntityType()); + if (isBlank(actionName) || recorder == null) { + return; + } + + String executionId = traceContext.getExecutionId(); + if (ExecutionLifecycleEvents.EXECUTION_STARTED_EVENT_TYPE.equals(event.getType())) { + if (!isBlank(executionId)) { + activeExecutionStartNanos.putIfAbsent(executionId, nanoTime.getAsLong()); + } + return; + } + + boolean succeeded = + ExecutionLifecycleEvents.EXECUTION_FINISHED_EVENT_TYPE.equals(event.getType()); + boolean failed = + ExecutionLifecycleEvents.EXECUTION_FAILED_EVENT_TYPE.equals(event.getType()); + if (!succeeded && !failed) { + return; + } + + Long startNanos = + isBlank(executionId) ? null : activeExecutionStartNanos.remove(executionId); + Long latencyMs = + startNanos == null + ? null + : TimeUnit.NANOSECONDS.toMillis( + Math.max(0L, nanoTime.getAsLong() - startNanos)); + + FlinkAgentsMetricGroupImpl actionMetricGroup = + agentMetricGroup.getSubGroup("action", actionName); + ExecutionMetricRecorder.Outcome outcome = + succeeded + ? ExecutionMetricRecorder.Outcome.SUCCEEDED + : ExecutionMetricRecorder.Outcome.FAILED; + recorder.record(actionMetricGroup, traceContext, outcome, latencyMs); + } + + private static boolean isBlank(String value) { + return value == null || value.isBlank(); + } +} diff --git a/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInInputRunMetrics.java b/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInInputRunMetrics.java new file mode 100644 index 000000000..0b50f7c34 --- /dev/null +++ b/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInInputRunMetrics.java @@ -0,0 +1,197 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ +package org.apache.flink.agents.runtime.metrics; + +import org.apache.flink.agents.api.Event; +import org.apache.flink.agents.api.trace.ExecutionTraceContext; +import org.apache.flink.metrics.Counter; +import org.apache.flink.metrics.Histogram; + +import javax.annotation.Nullable; + +import java.util.HashMap; +import java.util.HashSet; +import java.util.Map; +import java.util.Set; +import java.util.concurrent.TimeUnit; +import java.util.function.LongSupplier; + +/** + * Tracks input-run outcomes and latency on the operator mailbox thread. + * + *

A run is successful when it reaches the operator's run-completion boundary and failed when an + * unhandled exception terminates it. Handled or recovered execution failures do not change the + * final run outcome. End-to-end latency starts when the input enters the operator and is split into + * queueing and processing latency at the input-run start boundary. + * + *

Tracking state is intentionally process-local because Flink metrics reset when the task + * restarts. Latency and outcome samples for runs already in flight when a task is restored are + * excluded because their original timestamps are unavailable. Current-count gauges are rebuilt from + * operator state. + */ +final class BuiltInInputRunMetrics { + + static final String NUM_INPUT_RUNS_SUCCEEDED = "numOfInputRunsSucceeded"; + static final String NUM_INPUT_RUNS_FAILED = "numOfInputRunsFailed"; + static final String INPUT_RUN_LATENCY_MS = "inputRunLatencyMs"; + static final String INPUT_RUN_QUEUE_LATENCY_MS = "inputRunQueueLatencyMs"; + static final String INPUT_RUN_PROCESSING_LATENCY_MS = "inputRunProcessingLatencyMs"; + static final String NUM_PENDING_INPUT_EVENTS = "numOfPendingInputEvents"; + static final String NUM_ACTIVE_INPUT_RUNS = "numOfActiveInputRuns"; + + private final Counter succeededCounter; + private final Counter failedCounter; + private final Histogram latencyHistogram; + private final Histogram queueLatencyHistogram; + private final Histogram processingLatencyHistogram; + private final CurrentCountGauge pendingInputEvents; + private final CurrentCountGauge activeInputRuns; + private final LongSupplier nanoTime; + + private final Map receivedInputNanos = new HashMap<>(); + private final Map activeRunTimings = new HashMap<>(); + private final Set activeInputRunIds = new HashSet<>(); + private long unidentifiedRestoredActiveRuns; + + BuiltInInputRunMetrics(FlinkAgentsMetricGroupImpl metricGroup, LongSupplier nanoTime) { + this.succeededCounter = metricGroup.getCounter(NUM_INPUT_RUNS_SUCCEEDED); + this.failedCounter = metricGroup.getCounter(NUM_INPUT_RUNS_FAILED); + this.latencyHistogram = metricGroup.getHistogram(INPUT_RUN_LATENCY_MS); + this.queueLatencyHistogram = metricGroup.getHistogram(INPUT_RUN_QUEUE_LATENCY_MS); + this.processingLatencyHistogram = metricGroup.getHistogram(INPUT_RUN_PROCESSING_LATENCY_MS); + this.pendingInputEvents = new CurrentCountGauge(metricGroup, NUM_PENDING_INPUT_EVENTS); + this.activeInputRuns = new CurrentCountGauge(metricGroup, NUM_ACTIVE_INPUT_RUNS); + this.nanoTime = nanoTime; + } + + void inputEventReceived(Event inputEvent) { + receivedInputNanos.putIfAbsent(eventId(inputEvent), nanoTime.getAsLong()); + } + + void inputEventFailed(Event inputEvent) { + String inputEventId = eventId(inputEvent); + Long receivedNanos = receivedInputNanos.remove(inputEventId); + if (receivedNanos != null) { + recordTerminal(true, receivedNanos); + } + } + + void inputRunStarted(Event inputEvent, ExecutionTraceContext traceContext) { + String inputRunId = traceContext.getInputRunId(); + if (inputRunId == null || !activeInputRunIds.add(inputRunId)) { + return; + } + + activeInputRuns.increment(); + long startedNanos = nanoTime.getAsLong(); + String inputEventId = eventId(inputEvent); + Long receivedNanos = receivedInputNanos.remove(inputEventId); + if (receivedNanos != null) { + queueLatencyHistogram.update(elapsedMillis(receivedNanos, startedNanos)); + } + activeRunTimings.put(inputRunId, new RunTiming(receivedNanos, startedNanos)); + } + + void inputRunCompleted(String inputRunId) { + finish(inputRunId, false); + } + + void inputRunFailed(String inputRunId) { + finish(inputRunId, true); + } + + void pendingInputEventEnqueued() { + pendingInputEvents.increment(); + } + + void pendingInputEventDequeued() { + pendingInputEvents.decrement(); + } + + void restorePendingInputEvents(long count) { + pendingInputEvents.set(count); + } + + void restoreActiveInputRuns(long count) { + unidentifiedRestoredActiveRuns = Math.max(0L, count); + activeInputRuns.set(unidentifiedRestoredActiveRuns + activeInputRunIds.size()); + } + + void identifyRestoredActiveInputRun(String inputRunId) { + if (inputRunId != null + && activeInputRunIds.add(inputRunId) + && unidentifiedRestoredActiveRuns > 0L) { + unidentifiedRestoredActiveRuns--; + } + } + + private void finish(String inputRunId, boolean failed) { + boolean activeRunFinished = inputRunId != null && activeInputRunIds.remove(inputRunId); + if (!activeRunFinished && inputRunId == null && unidentifiedRestoredActiveRuns > 0L) { + unidentifiedRestoredActiveRuns--; + activeRunFinished = true; + } + if (activeRunFinished) { + activeInputRuns.decrement(); + } + + RunTiming timing = inputRunId == null ? null : activeRunTimings.remove(inputRunId); + if (timing == null) { + return; + } + + long terminalNanos = nanoTime.getAsLong(); + recordOutcome(failed); + if (timing.receivedNanos != null) { + latencyHistogram.update(elapsedMillis(timing.receivedNanos, terminalNanos)); + } + processingLatencyHistogram.update(elapsedMillis(timing.startedNanos, terminalNanos)); + } + + private void recordTerminal(boolean failed, long startNanos) { + recordOutcome(failed); + latencyHistogram.update(elapsedMillis(startNanos, nanoTime.getAsLong())); + } + + private void recordOutcome(boolean failed) { + if (failed) { + failedCounter.inc(); + } else { + succeededCounter.inc(); + } + } + + private static String eventId(Event event) { + return event.getId().toString(); + } + + private static long elapsedMillis(long startNanos, long endNanos) { + return TimeUnit.NANOSECONDS.toMillis(Math.max(0L, endNanos - startNanos)); + } + + private static final class RunTiming { + @Nullable private final Long receivedNanos; + private final long startedNanos; + + private RunTiming(@Nullable Long receivedNanos, long startedNanos) { + this.receivedNanos = receivedNanos; + this.startedNanos = startedNanos; + } + } +} diff --git a/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInMetrics.java b/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInMetrics.java index 8e3a17cb8..3d3cdb9a1 100644 --- a/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInMetrics.java +++ b/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInMetrics.java @@ -19,17 +19,20 @@ package org.apache.flink.agents.runtime.metrics; +import org.apache.flink.agents.api.Event; +import org.apache.flink.agents.api.trace.ExecutionReporter; +import org.apache.flink.agents.api.trace.ExecutionTraceContext; import org.apache.flink.agents.plan.AgentPlan; import org.apache.flink.metrics.Counter; import org.apache.flink.metrics.Meter; import java.util.HashMap; +import java.util.Map; /** * Represents a group of built-in metrics for monitoring the performance and behavior of a flink - * agent job. This class is responsible for collecting and managing various metrics such as the - * number of events processed, the number of actions being executed, and the number of actions - * executed per second. + * agent job. This class is responsible for collecting and managing input-run, event, and action + * metrics. */ public class BuiltInMetrics { @@ -41,7 +44,11 @@ public class BuiltInMetrics { private final Counter eventLogWriteFailures; - private final HashMap actionMetricGroups; + private final BuiltInInputRunMetrics inputRunMetrics; + + private final BuiltInExecutionMetrics executionMetrics; + + private final Map actionMetricGroups; public BuiltInMetrics(FlinkAgentsMetricGroupImpl parentMetricGroup, AgentPlan agentPlan) { Counter numOfEventsProcessed = parentMetricGroup.getCounter("numOfEventProcessed"); @@ -54,12 +61,15 @@ public BuiltInMetrics(FlinkAgentsMetricGroupImpl parentMetricGroup, AgentPlan ag this.eventLogTruncatedEvents = parentMetricGroup.getCounter("eventLogTruncatedEvents"); this.eventLogWriteFailures = parentMetricGroup.getCounter("eventLogWriteFailures"); + this.inputRunMetrics = new BuiltInInputRunMetrics(parentMetricGroup, System::nanoTime); + this.executionMetrics = new BuiltInExecutionMetrics(parentMetricGroup, System::nanoTime); this.actionMetricGroups = new HashMap<>(); for (String actionName : agentPlan.getActions().keySet()) { actionMetricGroups.put( actionName, - new BuiltInActionMetrics(parentMetricGroup.getSubGroup("action", actionName))); + new BuiltInActionMetrics( + parentMetricGroup.getSubGroup("action", actionName), System::nanoTime)); } } @@ -68,13 +78,73 @@ public void markEventProcessed() { numOfEventProcessedPerSec.markEvent(); } - /** - * Marks that an action has finished executing. Decrements the executing actions counter and - * marks an event on the executed meter. - */ + /** Marks that an action has finished executing. */ public void markActionExecuted(String actionName) { numOfActionsExecutedPerSec.markEvent(); - actionMetricGroups.get(actionName).markActionExecuted(); + actionMetrics(actionName).markActionExecuted(); + } + + public void markInputEventReceived(Event inputEvent) { + inputRunMetrics.inputEventReceived(inputEvent); + } + + public void markInputEventFailed(Event inputEvent) { + inputRunMetrics.inputEventFailed(inputEvent); + } + + public void markInputRunStarted(Event inputEvent, ExecutionTraceContext traceContext) { + inputRunMetrics.inputRunStarted(inputEvent, traceContext); + } + + public void markInputRunCompleted(String inputRunId) { + inputRunMetrics.inputRunCompleted(inputRunId); + } + + public void markInputRunFailed(String inputRunId) { + inputRunMetrics.inputRunFailed(inputRunId); + } + + public void markPendingInputEventEnqueued() { + inputRunMetrics.pendingInputEventEnqueued(); + } + + public void markPendingInputEventDequeued() { + inputRunMetrics.pendingInputEventDequeued(); + } + + public void restorePendingInputEvents(long count) { + inputRunMetrics.restorePendingInputEvents(count); + } + + public void restoreActiveInputRuns(long count) { + inputRunMetrics.restoreActiveInputRuns(count); + } + + public void markActionTaskEnqueued( + ExecutionTraceContext traceContext, boolean executionStarted) { + actionMetrics(traceContext.getEntityName()) + .actionTaskEnqueued(traceContext.getExecutionId(), executionStarted); + } + + public void markActionTaskDequeued( + ExecutionTraceContext traceContext, boolean executionStarted) { + actionMetrics(traceContext.getEntityName()) + .actionTaskDequeued(traceContext.getExecutionId(), executionStarted); + } + + public void restoreActionTask(ExecutionTraceContext traceContext, boolean executionStarted) { + inputRunMetrics.identifyRestoredActiveInputRun(traceContext.getInputRunId()); + actionMetrics(traceContext.getEntityName()) + .restoreActionTask(traceContext.getExecutionId(), executionStarted); + } + + public void markExecutionEvent( + String actionName, Event event, ExecutionTraceContext traceContext) { + if (ExecutionReporter.EntityTypes.ACTION.equals(traceContext.getEntityType())) { + actionMetrics(actionName).executionEventObserved(event, traceContext); + } else { + executionMetrics.executionEventObserved(actionName, event, traceContext); + } } /** Returns the counter tracking event log truncation occurrences. */ @@ -86,4 +156,12 @@ public Counter getEventLogTruncatedEventsCounter() { public Counter getEventLogWriteFailuresCounter() { return eventLogWriteFailures; } + + private BuiltInActionMetrics actionMetrics(String actionName) { + BuiltInActionMetrics actionMetrics = actionMetricGroups.get(actionName); + if (actionMetrics == null) { + throw new IllegalArgumentException("Unknown action: " + actionName); + } + return actionMetrics; + } } diff --git a/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/CurrentCountGauge.java b/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/CurrentCountGauge.java new file mode 100644 index 000000000..3deb66886 --- /dev/null +++ b/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/CurrentCountGauge.java @@ -0,0 +1,49 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ +package org.apache.flink.agents.runtime.metrics; + +/** Maintains a non-negative current-count gauge on the operator mailbox thread. */ +final class CurrentCountGauge { + + private final UpdatableGaugeImpl gauge; + private long value; + + @SuppressWarnings("unchecked") + CurrentCountGauge(FlinkAgentsMetricGroupImpl metricGroup, String name) { + this.gauge = (UpdatableGaugeImpl) metricGroup.getGauge(name); + update(0L); + } + + void increment() { + update(value + 1L); + } + + void decrement() { + update(Math.max(0L, value - 1L)); + } + + void set(long value) { + update(Math.max(0L, value)); + } + + private void update(long value) { + this.value = value; + gauge.update(value); + } +} diff --git a/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/ExecutionMetricRecorder.java b/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/ExecutionMetricRecorder.java new file mode 100644 index 000000000..dc68d704e --- /dev/null +++ b/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/ExecutionMetricRecorder.java @@ -0,0 +1,42 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ +package org.apache.flink.agents.runtime.metrics; + +import org.apache.flink.agents.api.trace.ExecutionTraceContext; + +import javax.annotation.Nullable; + +/** Records metrics for one execution entity type from a terminal lifecycle sample. */ +interface ExecutionMetricRecorder { + + enum Outcome { + SUCCEEDED, + FAILED + } + + /** Returns the execution entity type consumed by this recorder. */ + String entityType(); + + /** Records a terminal execution whose lifecycle has already been resolved by the caller. */ + void record( + FlinkAgentsMetricGroupImpl actionMetricGroup, + ExecutionTraceContext traceContext, + Outcome outcome, + @Nullable Long latencyMs); +} diff --git a/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/LlmExecutionMetricRecorder.java b/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/LlmExecutionMetricRecorder.java new file mode 100644 index 000000000..7347697b4 --- /dev/null +++ b/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/LlmExecutionMetricRecorder.java @@ -0,0 +1,60 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ +package org.apache.flink.agents.runtime.metrics; + +import org.apache.flink.agents.api.trace.ExecutionReporter; +import org.apache.flink.agents.api.trace.ExecutionTraceContext; +import org.apache.flink.metrics.Histogram; + +/** Records framework-observed LLM invocation outcomes and latency by ChatModel resource. */ +final class LlmExecutionMetricRecorder implements ExecutionMetricRecorder { + + static final String NUM_LLM_CALLS_SUCCEEDED = "numOfLlmCallsSucceeded"; + static final String NUM_LLM_CALLS_FAILED = "numOfLlmCallsFailed"; + static final String LLM_CALL_LATENCY_MS = "llmCallLatencyMs"; + + @Override + public String entityType() { + return ExecutionReporter.EntityTypes.LLM; + } + + @Override + public void record( + FlinkAgentsMetricGroupImpl actionMetricGroup, + ExecutionTraceContext traceContext, + Outcome outcome, + Long latencyMs) { + String entityName = traceContext.getEntityName(); + if (entityName == null || entityName.isBlank()) { + return; + } + FlinkAgentsMetricGroupImpl modelResourceMetricGroup = + actionMetricGroup.getSubGroup("model_resource", entityName); + modelResourceMetricGroup + .getCounter( + outcome == Outcome.SUCCEEDED + ? NUM_LLM_CALLS_SUCCEEDED + : NUM_LLM_CALLS_FAILED) + .inc(); + Histogram latencyHistogram = modelResourceMetricGroup.getHistogram(LLM_CALL_LATENCY_MS); + if (latencyMs != null) { + latencyHistogram.update(latencyMs); + } + } +} diff --git a/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/ToolExecutionMetricRecorder.java b/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/ToolExecutionMetricRecorder.java new file mode 100644 index 000000000..13ccff147 --- /dev/null +++ b/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/ToolExecutionMetricRecorder.java @@ -0,0 +1,109 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ +package org.apache.flink.agents.runtime.metrics; + +import org.apache.flink.agents.api.trace.ExecutionReporter; +import org.apache.flink.agents.api.trace.ExecutionTraceContext; +import org.apache.flink.agents.api.trace.ToolExecutionMetadataKeys; +import org.apache.flink.metrics.Histogram; + +/** Records Tool metrics and additional Skill and MCP projections. */ +final class ToolExecutionMetricRecorder implements ExecutionMetricRecorder { + + static final String NUM_TOOL_CALLS_SUCCEEDED = "numOfToolCallsSucceeded"; + static final String NUM_TOOL_CALLS_FAILED = "numOfToolCallsFailed"; + static final String TOOL_CALL_LATENCY_MS = "toolCallLatencyMs"; + + static final String NUM_SKILL_LOADS = "numOfSkillLoads"; + static final String SKILL_LOAD_LATENCY_MS = "skillLoadLatencyMs"; + + static final String NUM_MCP_TOOL_CALLS_SUCCEEDED = "numOfMcpToolCallsSucceeded"; + static final String NUM_MCP_TOOL_CALLS_FAILED = "numOfMcpToolCallsFailed"; + static final String MCP_TOOL_CALL_LATENCY_MS = "mcpToolCallLatencyMs"; + + @Override + public String entityType() { + return ExecutionReporter.EntityTypes.TOOL; + } + + @Override + public void record( + FlinkAgentsMetricGroupImpl actionMetricGroup, + ExecutionTraceContext traceContext, + Outcome outcome, + Long latencyMs) { + String toolName = traceContext.getEntityName(); + if (!isBlank(toolName)) { + recordOutcome( + actionMetricGroup.getSubGroup("tool", toolName), + outcome, + NUM_TOOL_CALLS_SUCCEEDED, + NUM_TOOL_CALLS_FAILED, + TOOL_CALL_LATENCY_MS, + latencyMs); + } + + String skillName = metadataValue(traceContext, ToolExecutionMetadataKeys.SKILL_NAME); + if (!isBlank(skillName)) { + FlinkAgentsMetricGroupImpl skillMetricGroup = + actionMetricGroup.getSubGroup("skill", skillName); + skillMetricGroup.getCounter(NUM_SKILL_LOADS).inc(); + updateLatency(skillMetricGroup.getHistogram(SKILL_LOAD_LATENCY_MS), latencyMs); + } + + String mcpServer = metadataValue(traceContext, ToolExecutionMetadataKeys.MCP_SERVER); + if (!isBlank(mcpServer)) { + recordOutcome( + actionMetricGroup.getSubGroup("mcp_server", mcpServer), + outcome, + NUM_MCP_TOOL_CALLS_SUCCEEDED, + NUM_MCP_TOOL_CALLS_FAILED, + MCP_TOOL_CALL_LATENCY_MS, + latencyMs); + } + } + + private static void recordOutcome( + FlinkAgentsMetricGroupImpl metricGroup, + Outcome outcome, + String succeededCounter, + String failedCounter, + String latencyHistogram, + Long latencyMs) { + metricGroup + .getCounter(outcome == Outcome.SUCCEEDED ? succeededCounter : failedCounter) + .inc(); + updateLatency(metricGroup.getHistogram(latencyHistogram), latencyMs); + } + + private static void updateLatency(Histogram histogram, Long latencyMs) { + if (latencyMs != null) { + histogram.update(latencyMs); + } + } + + private static String metadataValue(ExecutionTraceContext traceContext, String metadataKey) { + Object value = traceContext.getEntityMetadata().get(metadataKey); + return value == null ? null : String.valueOf(value); + } + + private static boolean isBlank(String value) { + return value == null || value.isBlank(); + } +} diff --git a/runtime/src/main/java/org/apache/flink/agents/runtime/operator/ActionExecutionOperator.java b/runtime/src/main/java/org/apache/flink/agents/runtime/operator/ActionExecutionOperator.java index f82d8047a..637a6548b 100644 --- a/runtime/src/main/java/org/apache/flink/agents/runtime/operator/ActionExecutionOperator.java +++ b/runtime/src/main/java/org/apache/flink/agents/runtime/operator/ActionExecutionOperator.java @@ -253,35 +253,41 @@ public void processElement(StreamRecord record) throws Exception { if (record.hasTimestamp()) { inputEvent.setSourceTimestamp(record.getTimestamp()); } + builtInMetrics.markInputEventReceived(inputEvent); - eventRouter.getKeySegmentQueue().addKeyToLastSegment(getCurrentKey()); + Object key = getCurrentKey(); + try { + eventRouter.getKeySegmentQueue().addKeyToLastSegment(key); - if (stateManager.hasMoreActionTasks()) { - // If there are already actions being processed for the current key, the newly incoming - // event should be queued and processed later. Therefore, we add it to - // pendingInputEventsState. - stateManager.addPendingInputEvent(inputEvent); - } else { - // Otherwise, the new event is processed immediately. - processInputEvent(getCurrentKey(), inputEvent); + if (stateManager.hasMoreActionTasks()) { + // If there are already actions being processed for the current key, the newly + // incoming event should be queued and processed later. Therefore, we add it to + // pendingInputEventsState. + enqueuePendingInputEvent(inputEvent); + return; + } + } catch (Exception e) { + builtInMetrics.markInputEventFailed(inputEvent); + throw e; } + + // Otherwise, the new event is processed immediately. Its failures are attributed to the + // input run created by processInputEvent. + processInputEvent(key, inputEvent); } /** Resolves one context key for an input and reuses it for the entire agent run. */ private void processInputEvent(Object key, Event inputEvent) throws Exception { - processEvent(key, resolveContextKey(key), inputEvent); - } - - /** - * Processes an incoming event for the given key and may submit a new mail - * `tryProcessActionTaskForKey` to continue processing. - */ - private void processEvent(Object key, String contextKey, Event event) throws Exception { - processEvent( - key, - contextKey, - event, - ExecutionTraceContext.forInputRun(contextKey, agentPlan.getAgentName())); + String contextKey = resolveContextKey(key); + ExecutionTraceContext traceContext = + ExecutionTraceContext.forInputRun(contextKey, agentPlan.getAgentName()); + builtInMetrics.markInputRunStarted(inputEvent, traceContext); + try { + processEvent(key, contextKey, inputEvent, traceContext); + } catch (Exception e) { + builtInMetrics.markInputRunFailed(traceContext.getInputRunId()); + throw e; + } } private void processEvent( @@ -316,8 +322,7 @@ private void processEvent( List triggerActions = eventRouter.getActionsTriggeredBy(event); if (triggerActions != null && !triggerActions.isEmpty()) { for (Action triggerAction : triggerActions) { - stateManager.addActionTask( - createActionTask(key, triggerAction, event, traceContext)); + enqueueActionTask(createActionTask(key, triggerAction, event, traceContext)); } } } @@ -325,7 +330,8 @@ private void processEvent( if (isInputEvent) { // If the event is an InputEvent, we submit a new mail to try processing the actions. mailboxExecutor.submit( - () -> tryProcessActionTaskForKey(key, contextKey), "process action task"); + () -> tryProcessActionTaskForKey(key, contextKey, traceContext.getInputRunId()), + "process action task"); } } @@ -375,9 +381,10 @@ private void tryEmitAgentRunBeginEvent( processEvent(key, contextKey, beginEvent, traceContext); } - private void tryProcessActionTaskForKey(Object key, String contextKey) { + private void tryProcessActionTaskForKey( + Object key, String contextKey, @Nullable String inputRunId) { try { - processActionTaskForKey(key, contextKey); + processActionTaskForKey(key, contextKey, inputRunId); } catch (Throwable t) { // MailboxExecutor.submit() stores task failures in its Future. Catch Throwable and // rethrow via execute() so Errors fail the task instead of leaving the key in-flight. @@ -390,26 +397,39 @@ private void tryProcessActionTaskForKey(Object key, String contextKey) { } } - private void processActionTaskForKey(Object key, String contextKey) throws Exception { - // 1. Get an action task for the key. - setCurrentKey(key); - - ActionTask actionTask = stateManager.pollNextActionTask(); - if (actionTask == null) { - int removedCount = stateManager.removeProcessingKey(key); - checkState( - removedCount == 1, - "Current processing key count for key " - + key - + " should be 1, but got " - + removedCount); - checkState( - eventRouter.getKeySegmentQueue().removeKey(key), - "Current key" + key + " is missing from the segmentedQueue."); - eventRouter.processEligibleWatermarks(super::processWatermark); - return; + private void processActionTaskForKey(Object key, String contextKey, @Nullable String inputRunId) + throws Exception { + String currentInputRunId = inputRunId; + try { + // 1. Get an action task for the key. + setCurrentKey(key); + + ActionTask actionTask = pollNextActionTask(); + if (actionTask == null) { + int removedCount = stateManager.removeProcessingKey(key); + checkState( + removedCount == 1, + "Current processing key count for key " + + key + + " should be 1, but got " + + removedCount); + checkState( + eventRouter.getKeySegmentQueue().removeKey(key), + "Current key" + key + " is missing from the segmentedQueue."); + eventRouter.processEligibleWatermarks(super::processWatermark); + builtInMetrics.markInputRunCompleted(currentInputRunId); + return; + } + currentInputRunId = actionTask.getTraceContext().getInputRunId(); + processActionTask(key, contextKey, actionTask); + } catch (Exception e) { + builtInMetrics.markInputRunFailed(currentInputRunId); + throw e; } + } + private void processActionTask(Object key, String contextKey, ActionTask actionTask) + throws Exception { // 2. Invoke the action task. contextManager.createAndSetRunnerContext( actionTask, @@ -423,7 +443,9 @@ private void processActionTaskForKey(Object key, String contextKey) throws Excep stateManager.getShortTermMemState(), pythonBridge.getPythonRunnerContext(), ltm, - executionEventLogger); + (event, traceContext) -> + notifyExecutionLifecycleEvent( + actionTask.action.getName(), traceContext, event)); long sequenceNumber = stateManager.getSequenceNumber(); boolean isFinished; @@ -543,7 +565,7 @@ private void processActionTaskForKey(Object key, String contextKey) throws Excep // next generated ActionTask to be invoked. contextManager.transferContexts(actionTask, generatedActionTask, durableExecManager); - stateManager.addActionTask(generatedActionTask); + enqueueActionTask(generatedActionTask); } // 3. Process the next InputEvent or next action task @@ -565,7 +587,8 @@ private void processActionTaskForKey(Object key, String contextKey) throws Excep eventRouter.getKeySegmentQueue().removeKey(key), "Current key" + key + " is missing from the segmentedQueue."); eventRouter.processEligibleWatermarks(super::processWatermark); - Event pendingInputEvent = stateManager.pollNextPendingInputEvent(); + builtInMetrics.markInputRunCompleted(actionTask.getTraceContext().getInputRunId()); + Event pendingInputEvent = pollNextPendingInputEvent(); if (pendingInputEvent != null) { processInputEvent(key, pendingInputEvent); } @@ -573,7 +596,10 @@ private void processActionTaskForKey(Object key, String contextKey) throws Excep // If the current key has additional action tasks remaining, we should submit a new mail // to continue processing them. mailboxExecutor.submit( - () -> tryProcessActionTaskForKey(key, contextKey), "process action task"); + () -> + tryProcessActionTaskForKey( + key, contextKey, actionTask.getTraceContext().getInputRunId()), + "process action task"); } } @@ -702,28 +728,37 @@ private void notifyActionStarted(ActionTask actionTask) { return; } notifyExecutionLifecycleEvent( - actionTask.getTraceContext(), ExecutionLifecycleEvents.executionStarted()); + actionTask.action.getName(), + actionTask.getTraceContext(), + ExecutionLifecycleEvents.executionStarted()); actionTask.markExecutionStartedEventEmitted(); } private void notifyActionFinished(ActionTask actionTask) { notifyExecutionLifecycleEvent( - actionTask.getTraceContext(), ExecutionLifecycleEvents.executionFinished()); + actionTask.action.getName(), + actionTask.getTraceContext(), + ExecutionLifecycleEvents.executionFinished()); } private void notifyActionReused(ActionTask actionTask) { notifyExecutionLifecycleEvent( - actionTask.getTraceContext(), ExecutionLifecycleEvents.executionReused()); + actionTask.action.getName(), + actionTask.getTraceContext(), + ExecutionLifecycleEvents.executionReused()); } private void notifyActionFailed(ActionTask actionTask, Throwable error) { notifyExecutionLifecycleEvent( + actionTask.action.getName(), actionTask.getTraceContext(), ExecutionLifecycleEvents.executionFailed( error, ExecutionReporter.ProblemCategories.ACTION_EXECUTION_FAILED)); } - private void notifyExecutionLifecycleEvent(ExecutionTraceContext traceContext, Event event) { + private void notifyExecutionLifecycleEvent( + String actionName, ExecutionTraceContext traceContext, Event event) { + builtInMetrics.markExecutionEvent(actionName, event, traceContext); executionEventLogger.emit(event, traceContext); } @@ -763,8 +798,39 @@ static String resolveContextKey( return pythonActionExecutor.resolveKeyText(key, pythonKeyIsPickled); } + private void enqueuePendingInputEvent(Event event) throws Exception { + stateManager.addPendingInputEvent(event); + builtInMetrics.markPendingInputEventEnqueued(); + } + + @Nullable + private Event pollNextPendingInputEvent() throws Exception { + Event event = stateManager.pollNextPendingInputEvent(); + if (event != null) { + builtInMetrics.markPendingInputEventDequeued(); + } + return event; + } + + private void enqueueActionTask(ActionTask actionTask) throws Exception { + stateManager.addActionTask(actionTask); + builtInMetrics.markActionTaskEnqueued( + actionTask.getTraceContext(), actionTask.hasExecutionStartedEventEmitted()); + } + + @Nullable + private ActionTask pollNextActionTask() throws Exception { + ActionTask actionTask = stateManager.pollNextActionTask(); + if (actionTask != null) { + builtInMetrics.markActionTaskDequeued( + actionTask.getTraceContext(), actionTask.hasExecutionStartedEventEmitted()); + } + return actionTask; + } + private void tryResumeProcessActionTasks() throws Exception { Iterable keys = stateManager.getProcessingKeys(); + long activeInputRuns = 0L; if (keys != null) { int maxParallelism = getRuntimeContext().getTaskInfo().getMaxNumberOfParallelSubtasks(); KeyGroupRange currentSubtaskKeyGroupRange = @@ -782,20 +848,34 @@ private void tryResumeProcessActionTasks() throws Exception { eventRouter.getKeySegmentQueue().addKeyToLastSegment(key); String contextKey = resolveContextKey(key); mailboxExecutor.submit( - () -> tryProcessActionTaskForKey(key, contextKey), "process action task"); + () -> tryProcessActionTaskForKey(key, contextKey, null), + "process action task"); } stateManager.replaceProcessingKeys(new ArrayList<>(ownedKeys)); + activeInputRuns = ownedKeys.size(); } + builtInMetrics.restoreActiveInputRuns(activeInputRuns); + + stateManager.forEachActionTaskKey( + getKeyedStateBackend(), + (key, state) -> { + for (ActionTask actionTask : state.get()) { + builtInMetrics.restoreActionTask( + actionTask.getTraceContext(), + actionTask.hasExecutionStartedEventEmitted()); + } + }); + long[] pendingInputEvents = {0L}; stateManager.forEachPendingInputEventKey( getKeyedStateBackend(), - (key, state) -> - state.get() - .forEach( - event -> - eventRouter - .getKeySegmentQueue() - .addKeyToLastSegment(key))); + (key, state) -> { + for (Event ignored : state.get()) { + eventRouter.getKeySegmentQueue().addKeyToLastSegment(key); + pendingInputEvents[0]++; + } + }); + builtInMetrics.restorePendingInputEvents(pendingInputEvents[0]); } @VisibleForTesting diff --git a/runtime/src/main/java/org/apache/flink/agents/runtime/operator/OperatorStateManager.java b/runtime/src/main/java/org/apache/flink/agents/runtime/operator/OperatorStateManager.java index 19f1f67cf..ea0c23f21 100644 --- a/runtime/src/main/java/org/apache/flink/agents/runtime/operator/OperatorStateManager.java +++ b/runtime/src/main/java/org/apache/flink/agents/runtime/operator/OperatorStateManager.java @@ -76,6 +76,7 @@ class OperatorStateManager { static final String MESSAGE_SEQUENCE_NUMBER_STATE_NAME = "messageSequenceNumber"; + static final String ACTION_TASK_STATE_NAME = "actionTasks"; static final String PENDING_INPUT_EVENT_STATE_NAME = "pendingInputEvents"; private ListState actionTasksKState; @@ -126,7 +127,7 @@ void initializeKeyedStates( actionTasksKState = runtimeContext.getListState( new ListStateDescriptor<>( - "actionTasks", TypeInformation.of(ActionTask.class))); + ACTION_TASK_STATE_NAME, TypeInformation.of(ActionTask.class))); pendingInputEventsKState = runtimeContext.getListState( new ListStateDescriptor<>( @@ -327,4 +328,19 @@ void forEachPendingInputEventKey( PENDING_INPUT_EVENT_STATE_NAME, TypeInformation.of(Event.class)), function); } + + /** Applies a function to the pending-action-task list state for every key in the backend. */ + @SuppressWarnings("unchecked") + void forEachActionTaskKey( + KeyedStateBackend keyedStateBackend, + KeyedStateFunction> function) + throws Exception { + ((KeyedStateBackend) keyedStateBackend) + .applyToAllKeys( + VoidNamespace.INSTANCE, + VoidNamespaceSerializer.INSTANCE, + new ListStateDescriptor<>( + ACTION_TASK_STATE_NAME, TypeInformation.of(ActionTask.class)), + function); + } } diff --git a/runtime/src/main/java/org/apache/flink/agents/runtime/trace/ExecutionEventSink.java b/runtime/src/main/java/org/apache/flink/agents/runtime/trace/ExecutionEventSink.java index 3eee1b24f..1195c6574 100644 --- a/runtime/src/main/java/org/apache/flink/agents/runtime/trace/ExecutionEventSink.java +++ b/runtime/src/main/java/org/apache/flink/agents/runtime/trace/ExecutionEventSink.java @@ -21,7 +21,7 @@ import org.apache.flink.agents.api.trace.ExecutionTraceContext; import org.apache.flink.annotation.Internal; -/** Runtime bridge for emitting execution lifecycle events to the event log pipeline. */ +/** Runtime bridge for emitting execution lifecycle events to runtime observability consumers. */ @Internal @FunctionalInterface public interface ExecutionEventSink { diff --git a/runtime/src/test/java/org/apache/flink/agents/runtime/CompileUtilsTest.java b/runtime/src/test/java/org/apache/flink/agents/runtime/CompileUtilsTest.java index 96a0ce8fc..5ea02d152 100644 --- a/runtime/src/test/java/org/apache/flink/agents/runtime/CompileUtilsTest.java +++ b/runtime/src/test/java/org/apache/flink/agents/runtime/CompileUtilsTest.java @@ -174,6 +174,23 @@ void rejectsMalformedPythonInputType() { .hasMessageContaining("contain 2 fields"); } + @Test + void testAgentNameUsedAsOperatorName() { + AgentPlan namedAgentPlan = + new AgentPlan( + TEST_AGENT_PLAN.getActions(), + TEST_AGENT_PLAN.getResourceProviders(), + TEST_AGENT_PLAN.getConfig(), + "test-agent"); + + assertThat(compileOperatorName(namedAgentPlan)).isEqualTo("test-agent"); + } + + @Test + void testMissingAgentNameUsesDefaultOperatorName() { + assertThat(compileOperatorName(TEST_AGENT_PLAN)).isEqualTo("action-execute-operator"); + } + private static KeyedStream createPythonInputStream(TypeInformation valueType) { StreamExecutionEnvironment env = StreamExecutionEnvironment.getExecutionEnvironment(); TypeInformation inputType = @@ -193,6 +210,14 @@ private static List getTestSequence() { return testSequence; } + private static String compileOperatorName(AgentPlan agentPlan) { + StreamExecutionEnvironment env = StreamExecutionEnvironment.getExecutionEnvironment(); + KeyedStream keyedInputStream = env.fromData(1L).keyBy(value -> value); + return CompileUtils.connectToAgent(keyedInputStream, agentPlan) + .getTransformation() + .getName(); + } + private static void checkResult(List resultList) { List expectedResultList = testSequence.stream().map(x -> (x + 1) * 2 + 1).collect(Collectors.toList()); diff --git a/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInActionMetricsTest.java b/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInActionMetricsTest.java new file mode 100644 index 000000000..6a1a185b3 --- /dev/null +++ b/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInActionMetricsTest.java @@ -0,0 +1,130 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ +package org.apache.flink.agents.runtime.metrics; + +import org.apache.flink.agents.api.trace.ExecutionLifecycleEvents; +import org.apache.flink.agents.api.trace.ExecutionTraceContext; +import org.apache.flink.runtime.metrics.groups.UnregisteredMetricGroups; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Test; + +import java.util.concurrent.atomic.AtomicLong; + +import static org.assertj.core.api.Assertions.assertThat; + +class BuiltInActionMetricsTest { + + private final AtomicLong nanoTime = new AtomicLong(); + private FlinkAgentsMetricGroupImpl metricGroup; + private BuiltInActionMetrics metrics; + + @BeforeEach + void setUp() { + metricGroup = + new FlinkAgentsMetricGroupImpl( + UnregisteredMetricGroups.createUnregisteredOperatorMetricGroup()); + metrics = new BuiltInActionMetrics(metricGroup, nanoTime::get); + } + + @Test + void initialTaskRecordsSchedulingLatencyAndPendingCount() { + metrics.actionTaskEnqueued("execution", false); + assertThat(gauge(BuiltInActionMetrics.NUM_PENDING_ACTION_TASKS)).isEqualTo(1L); + + nanoTime.set(25_000_000L); + metrics.actionTaskDequeued("execution", false); + + assertThat(gauge(BuiltInActionMetrics.NUM_PENDING_ACTION_TASKS)).isZero(); + assertThat( + metricGroup + .getHistogram(BuiltInActionMetrics.ACTION_SCHEDULING_LATENCY_MS) + .getStatistics() + .getMax()) + .isEqualTo(25L); + } + + @Test + void actionLifecycleRecordsExecutionLatency() { + ExecutionTraceContext action = actionExecution(); + + metrics.executionEventObserved(ExecutionLifecycleEvents.executionStarted(), action); + nanoTime.set(35_000_000L); + metrics.executionEventObserved(ExecutionLifecycleEvents.executionFinished(), action); + + assertThat( + metricGroup + .getHistogram(BuiltInActionMetrics.ACTION_EXECUTION_LATENCY_MS) + .getStatistics() + .getMax()) + .isEqualTo(35L); + assertThat(gauge(BuiltInActionMetrics.NUM_ACTIVE_ACTION_EXECUTIONS)).isZero(); + } + + @Test + void continuationCanBePendingWhileLogicalExecutionIsActive() { + ExecutionTraceContext action = actionExecution(); + String executionId = action.getExecutionId(); + + metrics.executionEventObserved(ExecutionLifecycleEvents.executionStarted(), action); + metrics.actionTaskEnqueued(executionId, true); + + assertThat(gauge(BuiltInActionMetrics.NUM_ACTIVE_ACTION_EXECUTIONS)).isEqualTo(1L); + assertThat(gauge(BuiltInActionMetrics.NUM_PENDING_ACTION_TASKS)).isEqualTo(1L); + + metrics.actionTaskDequeued(executionId, true); + metrics.executionEventObserved(ExecutionLifecycleEvents.executionFinished(), action); + + assertThat(gauge(BuiltInActionMetrics.NUM_ACTIVE_ACTION_EXECUTIONS)).isZero(); + assertThat(gauge(BuiltInActionMetrics.NUM_PENDING_ACTION_TASKS)).isZero(); + assertThat( + metricGroup + .getHistogram(BuiltInActionMetrics.ACTION_SCHEDULING_LATENCY_MS) + .getCount()) + .isZero(); + } + + @Test + void restoredContinuationRebuildsPendingAndActiveGauges() { + ExecutionTraceContext action = actionExecution(); + + metrics.restoreActionTask(action.getExecutionId(), true); + assertThat(gauge(BuiltInActionMetrics.NUM_PENDING_ACTION_TASKS)).isEqualTo(1L); + assertThat(gauge(BuiltInActionMetrics.NUM_ACTIVE_ACTION_EXECUTIONS)).isEqualTo(1L); + + metrics.actionTaskDequeued(action.getExecutionId(), true); + metrics.executionEventObserved(ExecutionLifecycleEvents.executionFinished(), action); + + assertThat(gauge(BuiltInActionMetrics.NUM_PENDING_ACTION_TASKS)).isZero(); + assertThat(gauge(BuiltInActionMetrics.NUM_ACTIVE_ACTION_EXECUTIONS)).isZero(); + assertThat( + metricGroup + .getHistogram(BuiltInActionMetrics.ACTION_EXECUTION_LATENCY_MS) + .getCount()) + .isZero(); + } + + private long gauge(String name) { + return (Long) metricGroup.getGauge(name).getValue(); + } + + private static ExecutionTraceContext actionExecution() { + return ExecutionTraceContext.forAction( + ExecutionTraceContext.forInputRun("key", "agent"), "action"); + } +} diff --git a/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetricsTest.java b/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetricsTest.java new file mode 100644 index 000000000..b666c9e5e --- /dev/null +++ b/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetricsTest.java @@ -0,0 +1,224 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ +package org.apache.flink.agents.runtime.metrics; + +import org.apache.flink.agents.api.trace.ExecutionLifecycleEvents; +import org.apache.flink.agents.api.trace.ExecutionReporter; +import org.apache.flink.agents.api.trace.ExecutionTraceContext; +import org.apache.flink.agents.api.trace.ToolExecutionMetadataKeys; +import org.apache.flink.metrics.MetricGroup; +import org.apache.flink.runtime.metrics.groups.UnregisteredMetricGroups; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Test; + +import java.util.Map; +import java.util.concurrent.atomic.AtomicLong; + +import static org.assertj.core.api.Assertions.assertThat; + +class BuiltInExecutionMetricsTest { + + private static final String ACTION_NAME = "chat_model_action"; + + private final AtomicLong nanoTime = new AtomicLong(); + private FlinkAgentsMetricGroupImpl metricGroup; + private BuiltInExecutionMetrics metrics; + + @BeforeEach + void setUp() { + MetricGroup parentMetricGroup = + UnregisteredMetricGroups.createUnregisteredOperatorMetricGroup(); + metricGroup = new FlinkAgentsMetricGroupImpl(parentMetricGroup); + metrics = new BuiltInExecutionMetrics(metricGroup, nanoTime::get); + } + + @Test + void recordsLlmOutcomeByModelResource() { + ExecutionTraceContext success = + execution(ExecutionReporter.EntityTypes.LLM, "primary_model", Map.of()); + metrics.executionEventObserved( + ACTION_NAME, ExecutionLifecycleEvents.executionStarted(), success); + nanoTime.addAndGet(25_000_000L); + metrics.executionEventObserved( + ACTION_NAME, ExecutionLifecycleEvents.executionFinished(), success); + + ExecutionTraceContext failure = + execution(ExecutionReporter.EntityTypes.LLM, "primary_model", Map.of()); + metrics.executionEventObserved( + ACTION_NAME, ExecutionLifecycleEvents.executionStarted(), failure); + nanoTime.addAndGet(40_000_000L); + metrics.executionEventObserved( + ACTION_NAME, + ExecutionLifecycleEvents.executionFailed(new RuntimeException("failed")), + failure); + + FlinkAgentsMetricGroupImpl modelResource = + actionMetricGroup().getSubGroup("model_resource", "primary_model"); + assertThat( + modelResource + .getCounter(LlmExecutionMetricRecorder.NUM_LLM_CALLS_SUCCEEDED) + .getCount()) + .isEqualTo(1); + assertThat( + modelResource + .getCounter(LlmExecutionMetricRecorder.NUM_LLM_CALLS_FAILED) + .getCount()) + .isEqualTo(1); + assertThat( + modelResource + .getHistogram(LlmExecutionMetricRecorder.LLM_CALL_LATENCY_MS) + .getCount()) + .isEqualTo(2); + } + + @Test + void recordsToolOutcomeByToolName() { + ExecutionTraceContext success = + execution(ExecutionReporter.EntityTypes.TOOL, "search", Map.of()); + metrics.executionEventObserved( + ACTION_NAME, ExecutionLifecycleEvents.executionStarted(), success); + nanoTime.addAndGet(15_000_000L); + metrics.executionEventObserved( + ACTION_NAME, ExecutionLifecycleEvents.executionFinished(), success); + + ExecutionTraceContext failure = + execution(ExecutionReporter.EntityTypes.TOOL, "search", Map.of()); + metrics.executionEventObserved( + ACTION_NAME, ExecutionLifecycleEvents.executionStarted(), failure); + nanoTime.addAndGet(20_000_000L); + metrics.executionEventObserved( + ACTION_NAME, + ExecutionLifecycleEvents.executionFailed(new RuntimeException("failed")), + failure); + + FlinkAgentsMetricGroupImpl tool = actionMetricGroup().getSubGroup("tool", "search"); + assertThat(tool.getCounter(ToolExecutionMetricRecorder.NUM_TOOL_CALLS_SUCCEEDED).getCount()) + .isEqualTo(1); + assertThat(tool.getCounter(ToolExecutionMetricRecorder.NUM_TOOL_CALLS_FAILED).getCount()) + .isEqualTo(1); + assertThat(tool.getHistogram(ToolExecutionMetricRecorder.TOOL_CALL_LATENCY_MS).getCount()) + .isEqualTo(2); + } + + @Test + void recordsExplicitSkillLoads() { + ExecutionTraceContext loadSkill = + execution( + ExecutionReporter.EntityTypes.TOOL, + "load_skill", + Map.of(ToolExecutionMetadataKeys.SKILL_NAME, "calculator")); + metrics.executionEventObserved( + ACTION_NAME, ExecutionLifecycleEvents.executionStarted(), loadSkill); + nanoTime.addAndGet(12_000_000L); + metrics.executionEventObserved( + ACTION_NAME, ExecutionLifecycleEvents.executionFinished(), loadSkill); + + FlinkAgentsMetricGroupImpl skill = actionMetricGroup().getSubGroup("skill", "calculator"); + assertThat(skill.getCounter(ToolExecutionMetricRecorder.NUM_SKILL_LOADS).getCount()) + .isEqualTo(1); + assertThat( + skill.getHistogram(ToolExecutionMetricRecorder.SKILL_LOAD_LATENCY_MS) + .getStatistics() + .getMax()) + .isEqualTo(12L); + + FlinkAgentsMetricGroupImpl tool = actionMetricGroup().getSubGroup("tool", "load_skill"); + assertThat(tool.getCounter(ToolExecutionMetricRecorder.NUM_TOOL_CALLS_SUCCEEDED).getCount()) + .isEqualTo(1); + } + + @Test + void aggregatesMcpToolOutcomesByServer() { + ExecutionTraceContext success = + execution( + ExecutionReporter.EntityTypes.TOOL, + "search", + Map.of(ToolExecutionMetadataKeys.MCP_SERVER, "search_server")); + metrics.executionEventObserved( + ACTION_NAME, ExecutionLifecycleEvents.executionStarted(), success); + nanoTime.addAndGet(30_000_000L); + metrics.executionEventObserved( + ACTION_NAME, ExecutionLifecycleEvents.executionFinished(), success); + + ExecutionTraceContext failure = + execution( + ExecutionReporter.EntityTypes.TOOL, + "fetch", + Map.of(ToolExecutionMetadataKeys.MCP_SERVER, "search_server")); + metrics.executionEventObserved( + ACTION_NAME, ExecutionLifecycleEvents.executionStarted(), failure); + nanoTime.addAndGet(50_000_000L); + metrics.executionEventObserved( + ACTION_NAME, + ExecutionLifecycleEvents.executionFailed(new RuntimeException("failed")), + failure); + + FlinkAgentsMetricGroupImpl mcpServer = + actionMetricGroup().getSubGroup("mcp_server", "search_server"); + assertThat( + mcpServer + .getCounter( + ToolExecutionMetricRecorder.NUM_MCP_TOOL_CALLS_SUCCEEDED) + .getCount()) + .isEqualTo(1); + assertThat( + mcpServer + .getCounter(ToolExecutionMetricRecorder.NUM_MCP_TOOL_CALLS_FAILED) + .getCount()) + .isEqualTo(1); + assertThat( + mcpServer + .getHistogram(ToolExecutionMetricRecorder.MCP_TOOL_CALL_LATENCY_MS) + .getCount()) + .isEqualTo(2); + } + + @Test + void terminalEventWithoutLocalStartDoesNotRecordLatency() { + ExecutionTraceContext llm = + execution(ExecutionReporter.EntityTypes.LLM, "restored_model", Map.of()); + metrics.executionEventObserved( + ACTION_NAME, ExecutionLifecycleEvents.executionFinished(), llm); + + FlinkAgentsMetricGroupImpl modelResource = + actionMetricGroup().getSubGroup("model_resource", "restored_model"); + assertThat( + modelResource + .getCounter(LlmExecutionMetricRecorder.NUM_LLM_CALLS_SUCCEEDED) + .getCount()) + .isEqualTo(1); + assertThat( + modelResource + .getHistogram(LlmExecutionMetricRecorder.LLM_CALL_LATENCY_MS) + .getCount()) + .isZero(); + } + + private FlinkAgentsMetricGroupImpl actionMetricGroup() { + return metricGroup.getSubGroup("action", ACTION_NAME); + } + + private static ExecutionTraceContext execution( + String entityType, String entityName, Map metadata) { + ExecutionTraceContext action = + ExecutionTraceContext.forAction( + ExecutionTraceContext.forInputRun("key", "agent"), ACTION_NAME); + return action.childExecution(entityType, entityName, metadata); + } +} diff --git a/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInInputRunMetricsTest.java b/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInInputRunMetricsTest.java new file mode 100644 index 000000000..168364d02 --- /dev/null +++ b/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInInputRunMetricsTest.java @@ -0,0 +1,222 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ +package org.apache.flink.agents.runtime.metrics; + +import org.apache.flink.agents.api.Event; +import org.apache.flink.agents.api.InputEvent; +import org.apache.flink.agents.api.trace.ExecutionTraceContext; +import org.apache.flink.metrics.Counter; +import org.apache.flink.metrics.Histogram; +import org.apache.flink.runtime.metrics.groups.UnregisteredMetricGroups; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Test; + +import java.util.concurrent.atomic.AtomicLong; + +import static java.util.concurrent.TimeUnit.MILLISECONDS; +import static org.assertj.core.api.Assertions.assertThat; + +class BuiltInInputRunMetricsTest { + + private final AtomicLong nanoTime = new AtomicLong(); + + private FlinkAgentsMetricGroupImpl metricGroup; + private BuiltInInputRunMetrics metrics; + + @BeforeEach + void setUp() { + metricGroup = + new FlinkAgentsMetricGroupImpl( + UnregisteredMetricGroups.createUnregisteredOperatorMetricGroup()); + metrics = new BuiltInInputRunMetrics(metricGroup, nanoTime::get); + } + + @Test + void completedRunIsSuccessfulAndLatencyIncludesQueueTime() { + setTimeMillis(100L); + Event inputEvent = new InputEvent("input"); + ExecutionTraceContext inputRun = ExecutionTraceContext.forInputRun("key", "agent"); + + metrics.inputEventReceived(inputEvent); + setTimeMillis(130L); + metrics.inputRunStarted(inputEvent, inputRun); + setTimeMillis(200L); + metrics.inputRunCompleted(inputRun.getInputRunId()); + + assertThat(counter(BuiltInInputRunMetrics.NUM_INPUT_RUNS_SUCCEEDED).getCount()) + .isEqualTo(1L); + assertThat(counter(BuiltInInputRunMetrics.NUM_INPUT_RUNS_FAILED).getCount()).isZero(); + assertHistogram(BuiltInInputRunMetrics.INPUT_RUN_LATENCY_MS, 1L, 100L); + assertHistogram(BuiltInInputRunMetrics.INPUT_RUN_QUEUE_LATENCY_MS, 1L, 30L); + assertHistogram(BuiltInInputRunMetrics.INPUT_RUN_PROCESSING_LATENCY_MS, 1L, 70L); + assertThat(gauge(BuiltInInputRunMetrics.NUM_ACTIVE_INPUT_RUNS)).isZero(); + } + + @Test + void inputProcessingFailureBeforeRunStartIsRecorded() { + setTimeMillis(100L); + Event inputEvent = new InputEvent("input"); + + metrics.inputEventReceived(inputEvent); + setTimeMillis(125L); + metrics.inputEventFailed(inputEvent); + + assertThat(counter(BuiltInInputRunMetrics.NUM_INPUT_RUNS_FAILED).getCount()).isEqualTo(1L); + assertHistogram(BuiltInInputRunMetrics.INPUT_RUN_LATENCY_MS, 1L, 25L); + assertThat(histogram(BuiltInInputRunMetrics.INPUT_RUN_QUEUE_LATENCY_MS).getCount()) + .isZero(); + assertThat(histogram(BuiltInInputRunMetrics.INPUT_RUN_PROCESSING_LATENCY_MS).getCount()) + .isZero(); + } + + @Test + void restoredRunRebuildsActiveGaugeWithoutRecordingHistoricalSamples() { + setTimeMillis(300L); + ExecutionTraceContext inputRun = ExecutionTraceContext.forInputRun("key", "agent"); + + metrics.restoreActiveInputRuns(1L); + metrics.identifyRestoredActiveInputRun(inputRun.getInputRunId()); + assertThat(gauge(BuiltInInputRunMetrics.NUM_ACTIVE_INPUT_RUNS)).isEqualTo(1L); + + setTimeMillis(375L); + metrics.inputRunCompleted(inputRun.getInputRunId()); + + assertThat(counter(BuiltInInputRunMetrics.NUM_INPUT_RUNS_SUCCEEDED).getCount()).isZero(); + assertThat(counter(BuiltInInputRunMetrics.NUM_INPUT_RUNS_FAILED).getCount()).isZero(); + assertThat(histogram(BuiltInInputRunMetrics.INPUT_RUN_LATENCY_MS).getCount()).isZero(); + assertThat(gauge(BuiltInInputRunMetrics.NUM_ACTIVE_INPUT_RUNS)).isZero(); + } + + @Test + void restoredPendingInputRecordsLocallyObservedOutcomeAndProcessingLatency() { + Event inputEvent = new InputEvent("restored-pending"); + ExecutionTraceContext inputRun = ExecutionTraceContext.forInputRun("key", "agent"); + + metrics.restorePendingInputEvents(1L); + metrics.pendingInputEventDequeued(); + setTimeMillis(300L); + metrics.inputRunStarted(inputEvent, inputRun); + setTimeMillis(375L); + metrics.inputRunCompleted(inputRun.getInputRunId()); + + assertThat(counter(BuiltInInputRunMetrics.NUM_INPUT_RUNS_SUCCEEDED).getCount()) + .isEqualTo(1L); + assertThat(histogram(BuiltInInputRunMetrics.INPUT_RUN_LATENCY_MS).getCount()).isZero(); + assertThat(histogram(BuiltInInputRunMetrics.INPUT_RUN_QUEUE_LATENCY_MS).getCount()) + .isZero(); + assertHistogram(BuiltInInputRunMetrics.INPUT_RUN_PROCESSING_LATENCY_MS, 1L, 75L); + assertThat(gauge(BuiltInInputRunMetrics.NUM_PENDING_INPUT_EVENTS)).isZero(); + assertThat(gauge(BuiltInInputRunMetrics.NUM_ACTIVE_INPUT_RUNS)).isZero(); + } + + @Test + void duplicateTerminalForIdentifiedRestoredRunDoesNotConsumeAnonymousRun() { + ExecutionTraceContext identifiedRun = ExecutionTraceContext.forInputRun("key-1", "agent"); + + metrics.restoreActiveInputRuns(2L); + metrics.identifyRestoredActiveInputRun(identifiedRun.getInputRunId()); + metrics.inputRunCompleted(identifiedRun.getInputRunId()); + metrics.inputRunCompleted(identifiedRun.getInputRunId()); + + assertThat(gauge(BuiltInInputRunMetrics.NUM_ACTIVE_INPUT_RUNS)).isEqualTo(1L); + + metrics.inputRunCompleted(null); + assertThat(gauge(BuiltInInputRunMetrics.NUM_ACTIVE_INPUT_RUNS)).isZero(); + } + + @Test + void terminalFailureIsAttributedToMatchingRunForSameKey() { + setTimeMillis(100L); + Event firstInput = new InputEvent("first"); + ExecutionTraceContext firstRun = ExecutionTraceContext.forInputRun("key", "agent"); + metrics.inputEventReceived(firstInput); + metrics.inputRunStarted(firstInput, firstRun); + assertThat(gauge(BuiltInInputRunMetrics.NUM_ACTIVE_INPUT_RUNS)).isEqualTo(1L); + + setTimeMillis(110L); + Event secondInput = new InputEvent("second"); + ExecutionTraceContext secondRun = ExecutionTraceContext.forInputRun("key", "agent"); + metrics.inputEventReceived(secondInput); + metrics.inputRunStarted(secondInput, secondRun); + assertThat(gauge(BuiltInInputRunMetrics.NUM_ACTIVE_INPUT_RUNS)).isEqualTo(2L); + + setTimeMillis(150L); + metrics.inputRunCompleted(firstRun.getInputRunId()); + setTimeMillis(180L); + metrics.inputRunFailed(secondRun.getInputRunId()); + + assertThat(counter(BuiltInInputRunMetrics.NUM_INPUT_RUNS_SUCCEEDED).getCount()) + .isEqualTo(1L); + assertThat(counter(BuiltInInputRunMetrics.NUM_INPUT_RUNS_FAILED).getCount()).isEqualTo(1L); + assertThat(histogram(BuiltInInputRunMetrics.INPUT_RUN_LATENCY_MS).getCount()).isEqualTo(2L); + assertThat(gauge(BuiltInInputRunMetrics.NUM_ACTIVE_INPUT_RUNS)).isZero(); + } + + @Test + void pendingInputGaugeTracksQueueAndRestore() { + assertThat(gauge(BuiltInInputRunMetrics.NUM_PENDING_INPUT_EVENTS)).isZero(); + + metrics.pendingInputEventEnqueued(); + metrics.pendingInputEventEnqueued(); + assertThat(gauge(BuiltInInputRunMetrics.NUM_PENDING_INPUT_EVENTS)).isEqualTo(2L); + + metrics.pendingInputEventDequeued(); + assertThat(gauge(BuiltInInputRunMetrics.NUM_PENDING_INPUT_EVENTS)).isEqualTo(1L); + + metrics.restorePendingInputEvents(3L); + assertThat(gauge(BuiltInInputRunMetrics.NUM_PENDING_INPUT_EVENTS)).isEqualTo(3L); + } + + @Test + void duplicateTerminalNotificationDoesNotUnderflowActiveGauge() { + Event inputEvent = new InputEvent("input"); + ExecutionTraceContext inputRun = ExecutionTraceContext.forInputRun("key", "agent"); + metrics.inputEventReceived(inputEvent); + metrics.inputRunStarted(inputEvent, inputRun); + + metrics.inputRunCompleted(inputRun.getInputRunId()); + metrics.inputRunCompleted(inputRun.getInputRunId()); + + assertThat(gauge(BuiltInInputRunMetrics.NUM_ACTIVE_INPUT_RUNS)).isZero(); + assertThat(counter(BuiltInInputRunMetrics.NUM_INPUT_RUNS_SUCCEEDED).getCount()) + .isEqualTo(1L); + } + + private Counter counter(String name) { + return metricGroup.getCounter(name); + } + + private Histogram histogram(String name) { + return metricGroup.getHistogram(name); + } + + private long gauge(String name) { + return (Long) metricGroup.getGauge(name).getValue(); + } + + private void setTimeMillis(long millis) { + nanoTime.set(MILLISECONDS.toNanos(millis)); + } + + private void assertHistogram(String name, long count, long max) { + Histogram histogram = histogram(name); + assertThat(histogram.getCount()).isEqualTo(count); + assertThat(histogram.getStatistics().getMax()).isEqualTo(max); + } +} From 1a49b5b5257db139847bb3f64347c7e928178f4e Mon Sep 17 00:00:00 2001 From: Joey Tong Date: Mon, 3 Aug 2026 20:14:30 +0800 Subject: [PATCH 02/10] [docs] Clarify Tool outcome metric semantics Document the current Java and Python Tool result mappings, align the retry configuration reference with the model resource scope, and link the follow-up alignment work. Co-Authored-By: Claude Code AI-Model: gpt-5 AI-Contributed/Feature: 4/4 AI-Contributed/UT: 0/0 --- docs/content/docs/operations/configuration.md | 2 +- docs/content/docs/operations/monitoring.md | 2 ++ 2 files changed, 3 insertions(+), 1 deletion(-) diff --git a/docs/content/docs/operations/configuration.md b/docs/content/docs/operations/configuration.md index 4feaf250b..f23e03ac8 100644 --- a/docs/content/docs/operations/configuration.md +++ b/docs/content/docs/operations/configuration.md @@ -130,7 +130,7 @@ Here is the list of all built-in core configuration options. | `action.trigger-condition.evaluate-failure-strategy` | `WARN_AND_SKIP` | ConditionEvaluationFailureStrategy | Handles event-time failures while preparing variables for or evaluating a compiled condition, including a dynamic non-Boolean result.
  • `WARN_AND_SKIP` (default): log a warning, treat that condition as false, and continue with later OR conditions.
  • `FAIL`: throw `IllegalStateException` and fail the Flink task; recovery follows the job's restart configuration.
Plan-validation failures and runtime compilation or static type-check failures occur during initialization and are not handled by this option. | | `error-handling-strategy` | ErrorHandlingStrategy.FAIL | ErrorHandlingStrategy | Strategy for handling errors during model requests, include timeout and unexpected output schema.
The option value could be:
  • `ErrorHandlingStrategy.FAIL`
  • `ErrorHandlingStrategy.RETRY`
  • `ErrorHandlingStrategy.IGNORE`
    • | | `max-retries` | 3 | int | Number of retries when using `ErrorHandlingStrategy.RETRY`. | -| `retry-wait-interval` | 1 | int | Base wait interval in seconds between retries when using `ErrorHandlingStrategy.RETRY`. Uses exponential backoff: the actual wait time for the Nth retry is `retry-wait-interval * 2^(N-1)` seconds. For example, with default 1s, waits are 1s, 2s, 4s, etc. Retry count and total wait time are reported in `ChatResponseEvent` and recorded as metrics (`retryCount`, `retryWaitSec`) under the connection name. | +| `retry-wait-interval` | 1 | int | Base wait interval in seconds between retries when using `ErrorHandlingStrategy.RETRY`. Uses exponential backoff: the actual wait time for the Nth retry is `retry-wait-interval * 2^(N-1)` seconds. For example, with default 1s, waits are 1s, 2s, 4s, etc. Retry count and total wait time are reported in `ChatResponseEvent` and recorded as metrics (`retryCount`, `retryWaitSec`) under the configured ChatModel resource name. | | `chat.async` | true | boolean | Whether chat asynchronously for built-in chat action. | | `tool-call.async` | true | boolean | Whether the built-in tool-call action runs each tool via durable async execution. | | `tool-call.parallelism` | os cpu count | int | In-flight concurrency for tool calls from one `ToolRequestEvent` batch when `tool-call.async` is enabled. `1` runs tools serially; values greater than `1` run a parallel durable batch with a sliding window of at most that many concurrent tool calls. On **Java**, concurrent in-batch execution requires **JDK 21+** (Continuation API); below JDK 21 the batch still runs but tool calls execute serially. **Python** uses the shared async `ThreadPoolExecutor` and runs batches concurrently regardless of JDK version. Increases in-flight external calls; after failover, unfinished tools may be submitted again — side-effecting tools should be idempotent or provide a reconciler. {{< hint warning >}}**Default is parallel** (`os cpu count`). Chat, RAG, and tool batches share one `num-async-threads` pool **per operator subtask** (all keys on that subtask). Built-in actions for a single key run one at a time, so chat and a tool batch on the **same key** do not overlap in the usual chat → tool path; delay shows up mainly **across keys** on the same subtask. With defaults (`num-async-threads = 2× cores`, `tool-call.parallelism = cores`), one batch can use up to half the pool; several busy keys can still saturate it. Lower this value or increase `num-async-threads` on hot subtasks. {{< /hint >}} | diff --git a/docs/content/docs/operations/monitoring.md b/docs/content/docs/operations/monitoring.md index 394b3478b..9c7fe0ca3 100644 --- a/docs/content/docs/operations/monitoring.md +++ b/docs/content/docs/operations/monitoring.md @@ -82,6 +82,8 @@ An LLM metric represents one framework invocation of `ChatModel`. A framework re Tool outcomes follow the existing language-specific Tool contracts. In both Java and Python, resource preparation or invocation exceptions are failures and a normal return is successful. Java additionally treats an unsuccessful `ToolResponse` as a failed Tool execution. Python Tools return arbitrary values and currently have no equivalent explicit error-result type, so the runtime does not infer failure from a normally returned Python value. +Consequently, Tool and MCP outcome metrics use the same names and scopes in both runtimes, but explicit error-result semantics are not yet identical. This alignment is tracked in [Issue #956](https://github.com/apache/flink-agents/issues/956) and is planned after the parallel Tool-call work in [PR #926](https://github.com/apache/flink-agents/pull/926). + Execution latency tracking is process-local. A latency sample is recorded only when the execution start and terminal events are observed in the same task attempt; LLM and Tool terminal counters are still updated when a restored execution has no local start timestamp. #### Token Usage Metrics From c2ff839ff3f066495fbf3f1c79dbabc40e9834b5 Mon Sep 17 00:00:00 2001 From: Joey Tong Date: Tue, 4 Aug 2026 11:01:11 +0800 Subject: [PATCH 03/10] [test] Align metrics E2E operator identifier Use the test Agent name when validating the operator metric scope. Co-Authored-By: Claude Code AI-Model: gpt-5 AI-Contributed/Feature: 0/0 AI-Contributed/UT: 8/8 --- .../agents/integration/test/TokenMetricsE2ETest.java | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/e2e-test/flink-agents-end-to-end-tests-integration/src/test/java/org/apache/flink/agents/integration/test/TokenMetricsE2ETest.java b/e2e-test/flink-agents-end-to-end-tests-integration/src/test/java/org/apache/flink/agents/integration/test/TokenMetricsE2ETest.java index 5b0982b29..7e4006e41 100644 --- a/e2e-test/flink-agents-end-to-end-tests-integration/src/test/java/org/apache/flink/agents/integration/test/TokenMetricsE2ETest.java +++ b/e2e-test/flink-agents-end-to-end-tests-integration/src/test/java/org/apache/flink/agents/integration/test/TokenMetricsE2ETest.java @@ -69,12 +69,16 @@ class TokenMetricsE2ETest { + "\"finish_reason\":\"stop\"}]," + "\"usage\":{\"prompt_tokens\":10,\"completion_tokens\":5,\"total_tokens\":15}}"; + private static final String OPERATOR_NAME = TokenMetricsE2EAgent.class.getSimpleName(); + private static final Pattern PREFIX_PATTERN = Pattern.compile( - "^\\.taskmanager\\.([a-f0-9-]+)\\.Flink Streaming Job\\.action-execute-operator\\.0\\."); + "^\\.taskmanager\\.([a-f0-9-]+)\\.Flink Streaming Job\\." + + Pattern.quote(OPERATOR_NAME) + + "\\.0\\."); private static final String PREFIX_TEMPLATE = - ".taskmanager.%s.Flink Streaming Job.action-execute-operator.0."; + ".taskmanager.%s.Flink Streaming Job." + OPERATOR_NAME + ".0."; /** * Expected agent Counter metrics. Each key is the deterministic suffix after the prefix in the From 2a1058e5c0126af07ad3a5217dd60c13075b8974 Mon Sep 17 00:00:00 2001 From: Joey Tong Date: Sat, 29 Aug 2026 18:04:01 +0800 Subject: [PATCH 04/10] [runtime][docs] Address operational metrics review comments Bound invalid Tool metric scopes, close restored Action gauges on reused executions, and account for Input Event setup failures. Co-Authored-By: Codex AI-Model: gpt-5.6-sol AI-Contributed/Feature: 84/84 AI-Contributed/UT: 78/78 --- docs/content/docs/operations/monitoring.md | 2 ++ .../runtime/metrics/BuiltInActionMetrics.java | 3 +- .../metrics/BuiltInExecutionMetrics.java | 9 +++-- .../runtime/metrics/BuiltInMetrics.java | 18 +++++++++- .../metrics/ToolExecutionMetricRecorder.java | 33 +++++++++++++------ .../operator/ActionExecutionOperator.java | 19 ++++++++--- .../metrics/BuiltInActionMetricsTest.java | 17 ++++++++++ .../metrics/BuiltInExecutionMetricsTest.java | 28 +++++++++++++++- .../operator/ActionExecutionOperatorTest.java | 33 +++++++++++++++++++ 9 files changed, 143 insertions(+), 19 deletions(-) diff --git a/docs/content/docs/operations/monitoring.md b/docs/content/docs/operations/monitoring.md index 9c7fe0ca3..6ceb9ba77 100644 --- a/docs/content/docs/operations/monitoring.md +++ b/docs/content/docs/operations/monitoring.md @@ -80,6 +80,8 @@ Execution metrics are derived from LLM and Tool execution lifecycle events. The An LLM metric represents one framework invocation of `ChatModel`. A framework retry that calls the model again produces another LLM outcome and latency sample; retries hidden inside a provider or connection are not observed. Every named Tool execution emits Tool metrics. Skill metrics are emitted only for explicit `load_skill` calls; subsequent Tool calls are not inferred to belong to a Skill. MCP metrics aggregate only Tool executions carrying an explicit MCP Server resource name. A `load_skill` or MCP Tool execution therefore contributes to both its Tool scope and the corresponding Skill or MCP Server scope. +Tool names that are not registered runtime resources are aggregated under the fixed `tool=unknown` scope to keep metric cardinality bounded. Their original requested names remain available in Agent Trace records. + Tool outcomes follow the existing language-specific Tool contracts. In both Java and Python, resource preparation or invocation exceptions are failures and a normal return is successful. Java additionally treats an unsuccessful `ToolResponse` as a failed Tool execution. Python Tools return arbitrary values and currently have no equivalent explicit error-result type, so the runtime does not infer failure from a normally returned Python value. Consequently, Tool and MCP outcome metrics use the same names and scopes in both runtimes, but explicit error-result semantics are not yet identical. This alignment is tracked in [Issue #956](https://github.com/apache/flink-agents/issues/956) and is planned after the parallel Tool-call work in [PR #926](https://github.com/apache/flink-agents/pull/926). diff --git a/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInActionMetrics.java b/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInActionMetrics.java index 304557729..84d908bf4 100644 --- a/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInActionMetrics.java +++ b/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInActionMetrics.java @@ -119,7 +119,8 @@ void executionEventObserved(Event event, ExecutionTraceContext traceContext) { } if (!ExecutionLifecycleEvents.EXECUTION_FINISHED_EVENT_TYPE.equals(event.getType()) - && !ExecutionLifecycleEvents.EXECUTION_FAILED_EVENT_TYPE.equals(event.getType())) { + && !ExecutionLifecycleEvents.EXECUTION_FAILED_EVENT_TYPE.equals(event.getType()) + && !ExecutionLifecycleEvents.EXECUTION_REUSED_EVENT_TYPE.equals(event.getType())) { return; } diff --git a/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetrics.java b/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetrics.java index 6dc9c3a1b..6574eee73 100644 --- a/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetrics.java +++ b/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetrics.java @@ -26,6 +26,7 @@ import java.util.Map; import java.util.concurrent.TimeUnit; import java.util.function.LongSupplier; +import java.util.function.Predicate; /** Derives built-in LLM and Tool metrics from execution lifecycle events. */ final class BuiltInExecutionMetrics { @@ -35,11 +36,15 @@ final class BuiltInExecutionMetrics { private final Map metricRecordersByEntityType; private final Map activeExecutionStartNanos = new HashMap<>(); - BuiltInExecutionMetrics(FlinkAgentsMetricGroupImpl agentMetricGroup, LongSupplier nanoTime) { + BuiltInExecutionMetrics( + FlinkAgentsMetricGroupImpl agentMetricGroup, + LongSupplier nanoTime, + Predicate isRegisteredTool) { this.agentMetricGroup = agentMetricGroup; this.nanoTime = nanoTime; ExecutionMetricRecorder llmMetricRecorder = new LlmExecutionMetricRecorder(); - ExecutionMetricRecorder toolMetricRecorder = new ToolExecutionMetricRecorder(); + ExecutionMetricRecorder toolMetricRecorder = + new ToolExecutionMetricRecorder(isRegisteredTool); this.metricRecordersByEntityType = Map.of( llmMetricRecorder.entityType(), diff --git a/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInMetrics.java b/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInMetrics.java index 3d3cdb9a1..e21ebb425 100644 --- a/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInMetrics.java +++ b/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInMetrics.java @@ -20,6 +20,7 @@ package org.apache.flink.agents.runtime.metrics; import org.apache.flink.agents.api.Event; +import org.apache.flink.agents.api.resource.ResourceType; import org.apache.flink.agents.api.trace.ExecutionReporter; import org.apache.flink.agents.api.trace.ExecutionTraceContext; import org.apache.flink.agents.plan.AgentPlan; @@ -28,6 +29,7 @@ import java.util.HashMap; import java.util.Map; +import java.util.function.Predicate; /** * Represents a group of built-in metrics for monitoring the performance and behavior of a flink @@ -51,6 +53,19 @@ public class BuiltInMetrics { private final Map actionMetricGroups; public BuiltInMetrics(FlinkAgentsMetricGroupImpl parentMetricGroup, AgentPlan agentPlan) { + this( + parentMetricGroup, + agentPlan, + toolName -> { + Map tools = agentPlan.getResourceProviders().get(ResourceType.TOOL); + return tools != null && tools.containsKey(toolName); + }); + } + + public BuiltInMetrics( + FlinkAgentsMetricGroupImpl parentMetricGroup, + AgentPlan agentPlan, + Predicate isRegisteredTool) { Counter numOfEventsProcessed = parentMetricGroup.getCounter("numOfEventProcessed"); this.numOfEventProcessedPerSec = parentMetricGroup.getMeter("numOfEventProcessedPerSec", numOfEventsProcessed); @@ -62,7 +77,8 @@ public BuiltInMetrics(FlinkAgentsMetricGroupImpl parentMetricGroup, AgentPlan ag this.eventLogTruncatedEvents = parentMetricGroup.getCounter("eventLogTruncatedEvents"); this.eventLogWriteFailures = parentMetricGroup.getCounter("eventLogWriteFailures"); this.inputRunMetrics = new BuiltInInputRunMetrics(parentMetricGroup, System::nanoTime); - this.executionMetrics = new BuiltInExecutionMetrics(parentMetricGroup, System::nanoTime); + this.executionMetrics = + new BuiltInExecutionMetrics(parentMetricGroup, System::nanoTime, isRegisteredTool); this.actionMetricGroups = new HashMap<>(); for (String actionName : agentPlan.getActions().keySet()) { diff --git a/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/ToolExecutionMetricRecorder.java b/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/ToolExecutionMetricRecorder.java index 13ccff147..995ae1865 100644 --- a/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/ToolExecutionMetricRecorder.java +++ b/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/ToolExecutionMetricRecorder.java @@ -23,9 +23,14 @@ import org.apache.flink.agents.api.trace.ToolExecutionMetadataKeys; import org.apache.flink.metrics.Histogram; +import java.util.Objects; +import java.util.function.Predicate; + /** Records Tool metrics and additional Skill and MCP projections. */ final class ToolExecutionMetricRecorder implements ExecutionMetricRecorder { + static final String UNKNOWN_TOOL_NAME = "unknown"; + static final String NUM_TOOL_CALLS_SUCCEEDED = "numOfToolCallsSucceeded"; static final String NUM_TOOL_CALLS_FAILED = "numOfToolCallsFailed"; static final String TOOL_CALL_LATENCY_MS = "toolCallLatencyMs"; @@ -37,6 +42,12 @@ final class ToolExecutionMetricRecorder implements ExecutionMetricRecorder { static final String NUM_MCP_TOOL_CALLS_FAILED = "numOfMcpToolCallsFailed"; static final String MCP_TOOL_CALL_LATENCY_MS = "mcpToolCallLatencyMs"; + private final Predicate isRegisteredTool; + + ToolExecutionMetricRecorder(Predicate isRegisteredTool) { + this.isRegisteredTool = Objects.requireNonNull(isRegisteredTool); + } + @Override public String entityType() { return ExecutionReporter.EntityTypes.TOOL; @@ -48,16 +59,18 @@ public void record( ExecutionTraceContext traceContext, Outcome outcome, Long latencyMs) { - String toolName = traceContext.getEntityName(); - if (!isBlank(toolName)) { - recordOutcome( - actionMetricGroup.getSubGroup("tool", toolName), - outcome, - NUM_TOOL_CALLS_SUCCEEDED, - NUM_TOOL_CALLS_FAILED, - TOOL_CALL_LATENCY_MS, - latencyMs); - } + String requestedToolName = traceContext.getEntityName(); + String metricToolName = + !isBlank(requestedToolName) && isRegisteredTool.test(requestedToolName) + ? requestedToolName + : UNKNOWN_TOOL_NAME; + recordOutcome( + actionMetricGroup.getSubGroup("tool", metricToolName), + outcome, + NUM_TOOL_CALLS_SUCCEEDED, + NUM_TOOL_CALLS_FAILED, + TOOL_CALL_LATENCY_MS, + latencyMs); String skillName = metadataValue(traceContext, ToolExecutionMetadataKeys.SKILL_NAME); if (!isBlank(skillName)) { diff --git a/runtime/src/main/java/org/apache/flink/agents/runtime/operator/ActionExecutionOperator.java b/runtime/src/main/java/org/apache/flink/agents/runtime/operator/ActionExecutionOperator.java index 637a6548b..a71c0b056 100644 --- a/runtime/src/main/java/org/apache/flink/agents/runtime/operator/ActionExecutionOperator.java +++ b/runtime/src/main/java/org/apache/flink/agents/runtime/operator/ActionExecutionOperator.java @@ -21,6 +21,7 @@ import org.apache.flink.agents.api.OutputEvent; import org.apache.flink.agents.api.agents.AgentExecutionOptions; import org.apache.flink.agents.api.event.AgentRunBeginEvent; +import org.apache.flink.agents.api.resource.ResourceType; import org.apache.flink.agents.api.trace.ExecutionLifecycleEvents; import org.apache.flink.agents.api.trace.ExecutionReporter; import org.apache.flink.agents.api.trace.ExecutionTraceContext; @@ -190,7 +191,11 @@ public void open() throws Exception { getRuntimeContext().getUserCodeClassLoader()); metricGroup = new FlinkAgentsMetricGroupImpl(getMetricGroup()); - builtInMetrics = new BuiltInMetrics(metricGroup, agentPlan); + builtInMetrics = + new BuiltInMetrics( + metricGroup, + agentPlan, + toolName -> resourceCache.hasResource(toolName, ResourceType.TOOL)); eventRouter.open(builtInMetrics); @@ -278,9 +283,15 @@ public void processElement(StreamRecord record) throws Exception { /** Resolves one context key for an input and reuses it for the entire agent run. */ private void processInputEvent(Object key, Event inputEvent) throws Exception { - String contextKey = resolveContextKey(key); - ExecutionTraceContext traceContext = - ExecutionTraceContext.forInputRun(contextKey, agentPlan.getAgentName()); + final String contextKey; + final ExecutionTraceContext traceContext; + try { + contextKey = resolveContextKey(key); + traceContext = ExecutionTraceContext.forInputRun(contextKey, agentPlan.getAgentName()); + } catch (Exception e) { + builtInMetrics.markInputEventFailed(inputEvent); + throw e; + } builtInMetrics.markInputRunStarted(inputEvent, traceContext); try { processEvent(key, contextKey, inputEvent, traceContext); diff --git a/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInActionMetricsTest.java b/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInActionMetricsTest.java index 6a1a185b3..9e0e23c57 100644 --- a/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInActionMetricsTest.java +++ b/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInActionMetricsTest.java @@ -119,6 +119,23 @@ void restoredContinuationRebuildsPendingAndActiveGauges() { .isZero(); } + @Test + void reusedRestoredExecutionEndsActiveGaugeWithoutLatency() { + ExecutionTraceContext action = actionExecution(); + + metrics.restoreActionTask(action.getExecutionId(), true); + metrics.actionTaskDequeued(action.getExecutionId(), true); + metrics.executionEventObserved(ExecutionLifecycleEvents.executionReused(), action); + + assertThat(gauge(BuiltInActionMetrics.NUM_PENDING_ACTION_TASKS)).isZero(); + assertThat(gauge(BuiltInActionMetrics.NUM_ACTIVE_ACTION_EXECUTIONS)).isZero(); + assertThat( + metricGroup + .getHistogram(BuiltInActionMetrics.ACTION_EXECUTION_LATENCY_MS) + .getCount()) + .isZero(); + } + private long gauge(String name) { return (Long) metricGroup.getGauge(name).getValue(); } diff --git a/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetricsTest.java b/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetricsTest.java index b666c9e5e..95ad74c97 100644 --- a/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetricsTest.java +++ b/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetricsTest.java @@ -28,6 +28,7 @@ import org.junit.jupiter.api.Test; import java.util.Map; +import java.util.Set; import java.util.concurrent.atomic.AtomicLong; import static org.assertj.core.api.Assertions.assertThat; @@ -45,7 +46,9 @@ void setUp() { MetricGroup parentMetricGroup = UnregisteredMetricGroups.createUnregisteredOperatorMetricGroup(); metricGroup = new FlinkAgentsMetricGroupImpl(parentMetricGroup); - metrics = new BuiltInExecutionMetrics(metricGroup, nanoTime::get); + Set registeredTools = Set.of("search", "fetch", "load_skill"); + metrics = + new BuiltInExecutionMetrics(metricGroup, nanoTime::get, registeredTools::contains); } @Test @@ -116,6 +119,29 @@ void recordsToolOutcomeByToolName() { .isEqualTo(2); } + @Test + void aggregatesUnregisteredToolNamesIntoUnknownScope() { + ExecutionTraceContext first = + execution(ExecutionReporter.EntityTypes.TOOL, "hallucinated_one", Map.of()); + ExecutionTraceContext second = + execution(ExecutionReporter.EntityTypes.TOOL, "hallucinated_two", Map.of()); + + metrics.executionEventObserved( + ACTION_NAME, + ExecutionLifecycleEvents.executionFailed(new RuntimeException("missing")), + first); + metrics.executionEventObserved( + ACTION_NAME, + ExecutionLifecycleEvents.executionFailed(new RuntimeException("missing")), + second); + + FlinkAgentsMetricGroupImpl unknown = + actionMetricGroup() + .getSubGroup("tool", ToolExecutionMetricRecorder.UNKNOWN_TOOL_NAME); + assertThat(unknown.getCounter(ToolExecutionMetricRecorder.NUM_TOOL_CALLS_FAILED).getCount()) + .isEqualTo(2); + } + @Test void recordsExplicitSkillLoads() { ExecutionTraceContext loadSkill = diff --git a/runtime/src/test/java/org/apache/flink/agents/runtime/operator/ActionExecutionOperatorTest.java b/runtime/src/test/java/org/apache/flink/agents/runtime/operator/ActionExecutionOperatorTest.java index b92f887e3..1885cd8b9 100644 --- a/runtime/src/test/java/org/apache/flink/agents/runtime/operator/ActionExecutionOperatorTest.java +++ b/runtime/src/test/java/org/apache/flink/agents/runtime/operator/ActionExecutionOperatorTest.java @@ -58,6 +58,7 @@ import org.apache.flink.agents.runtime.eventlog.FileEventLogger; import org.apache.flink.agents.runtime.eventlog.Slf4jEventLogger; import org.apache.flink.agents.runtime.memory.Mem0LongTermMemory; +import org.apache.flink.agents.runtime.metrics.FlinkAgentsMetricGroupImpl; import org.apache.flink.api.common.typeinfo.TypeInformation; import org.apache.flink.api.java.functions.KeySelector; import org.apache.flink.runtime.checkpoint.OperatorSubtaskState; @@ -144,6 +145,29 @@ void testExecuteAgent() throws Exception { } } + @Test + void contextKeyResolutionFailureMarksInputEventFailed() throws Exception { + try (KeyedOneInputStreamOperatorTestHarness testHarness = + new KeyedOneInputStreamOperatorTestHarness<>( + new ActionExecutionOperatorFactory(TestAgent.getAgentPlan(false), true), + (KeySelector) value -> FailingContextKey.INSTANCE, + TypeInformation.of(FailingContextKey.class))) { + testHarness.open(); + ActionExecutionOperator operator = + (ActionExecutionOperator) testHarness.getOperator(); + + assertThatThrownBy(() -> testHarness.processElement(new StreamRecord<>(1L))) + .isInstanceOf(IllegalStateException.class) + .hasMessage("context key conversion failed"); + + Field metricGroupField = ActionExecutionOperator.class.getDeclaredField("metricGroup"); + metricGroupField.setAccessible(true); + FlinkAgentsMetricGroupImpl metricGroup = + (FlinkAgentsMetricGroupImpl) metricGroupField.get(operator); + assertThat(metricGroup.getCounter("numOfInputRunsFailed").getCount()).isEqualTo(1L); + } + } + @Test void testSameKeyDataAreProcessedInOrder() throws Exception { try (KeyedOneInputStreamOperatorTestHarness testHarness = @@ -3849,6 +3873,15 @@ private Map getCompletedStateBytes() { } } + private enum FailingContextKey { + INSTANCE; + + @Override + public String toString() { + throw new IllegalStateException("context key conversion failed"); + } + } + private static void assertMailboxSizeAndRun(TaskMailbox mailbox, int expectedSize) throws Exception { assertThat(mailbox.size()).isEqualTo(expectedSize); From 69babf3694ce0692d4f2bceb569e0aa296bbb95c Mon Sep 17 00:00:00 2001 From: Joey Tong Date: Mon, 31 Aug 2026 11:36:16 +0800 Subject: [PATCH 05/10] [runtime][docs] Address follow-up metrics review comments Bound Skill metric cardinality, tolerate restored Actions missing from the current Plan, and document migration and durable-replay semantics. Co-Authored-By: Claude Code AI-Model: gpt-5.6-sol AI-Contributed/Feature: 75/75 AI-Contributed/UT: 185/185 --- .../api/trace/ToolExecutionMetadataKeys.java | 1 + docs/content/docs/operations/monitoring.md | 16 +++-- .../api/trace/tool_execution_metadata_keys.py | 1 + .../flink_agents/runtime/skill/skill_tools.py | 13 +++- .../runtime/skill/tests/test_load_skill.py | 12 +++- .../runtime/metrics/BuiltInMetrics.java | 19 ++++-- .../metrics/ToolExecutionMetricRecorder.java | 10 ++- .../agents/runtime/skill/LoadSkillTool.java | 15 ++++- .../metrics/BuiltInExecutionMetricsTest.java | 39 ++++++++++- .../runtime/metrics/BuiltInMetricsTest.java | 64 +++++++++++++++++++ .../metrics/CurrentCountGaugeTest.java | 60 +++++++++++++++++ .../runtime/skill/LoadSkillToolTest.java | 10 +++ 12 files changed, 242 insertions(+), 18 deletions(-) create mode 100644 runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInMetricsTest.java create mode 100644 runtime/src/test/java/org/apache/flink/agents/runtime/metrics/CurrentCountGaugeTest.java diff --git a/api/src/main/java/org/apache/flink/agents/api/trace/ToolExecutionMetadataKeys.java b/api/src/main/java/org/apache/flink/agents/api/trace/ToolExecutionMetadataKeys.java index 85f910c9f..acc6d96c7 100644 --- a/api/src/main/java/org/apache/flink/agents/api/trace/ToolExecutionMetadataKeys.java +++ b/api/src/main/java/org/apache/flink/agents/api/trace/ToolExecutionMetadataKeys.java @@ -26,6 +26,7 @@ public final class ToolExecutionMetadataKeys { public static final String TOOL_TYPE = "toolType"; public static final String MCP_SERVER = "mcpServer"; public static final String SKILL_NAME = "skillName"; + public static final String SKILL_REGISTERED = "skillRegistered"; public static final String SKILL_RESOURCE_PATH = "skillResourcePath"; private ToolExecutionMetadataKeys() {} diff --git a/docs/content/docs/operations/monitoring.md b/docs/content/docs/operations/monitoring.md index 6ceb9ba77..a890f16c7 100644 --- a/docs/content/docs/operations/monitoring.md +++ b/docs/content/docs/operations/monitoring.md @@ -67,12 +67,12 @@ Execution metrics are derived from LLM and Tool execution lifecycle events. The | **Model Resource** | action.\.model_resource.\.numOfLlmCallsSucceeded | The number of framework-observed model invocations that returned successfully. | Count | | **Model Resource** | action.\.model_resource.\.numOfLlmCallsFailed | The number of framework-observed model invocations that failed. | Count | | **Model Resource** | action.\.model_resource.\.llmCallLatencyMs | Latency of each framework-observed model invocation, excluding structured-output parsing and retry wait time. | Histogram | -| **Model Resource** | action.\.model_resource.\.retryCount | The number of additional model invocations initiated by framework retry logic. Only recorded when at least one retry occurs. See [retry-wait-interval]({{< ref "docs/operations/configuration#core-options" >}}). | Count | -| **Model Resource** | action.\.model_resource.\.retryWaitSec | The total backoff time, in seconds, accumulated by framework-level retries. | Count | +| **Model Resource** | action.\.model_resource.\.retryCount | The number of additional model invocations initiated when `ErrorHandlingStrategy.RETRY` is configured. Only recorded when at least one retry occurs. See [retry-wait-interval]({{< ref "docs/operations/configuration#core-options" >}}). | Count | +| **Model Resource** | action.\.model_resource.\.retryWaitSec | The total backoff time, in seconds, accumulated when `ErrorHandlingStrategy.RETRY` is configured. Only recorded when at least one retry occurs. | Count | | **Tool** | action.\.tool.\.numOfToolCallsSucceeded | The number of successful calls to the Tool. | Count | | **Tool** | action.\.tool.\.numOfToolCallsFailed | The number of failed calls to the Tool. | Count | | **Tool** | action.\.tool.\.toolCallLatencyMs | Tool call latency. | Histogram | -| **Skill** | action.\.skill.\.numOfSkillLoads | The number of completed explicit `load_skill` calls for the Skill. | Count | +| **Skill** | action.\.skill.\.numOfSkillLoads | The number of terminal explicit `load_skill` calls attributed to the Skill, regardless of outcome. | Count | | **Skill** | action.\.skill.\.skillLoadLatencyMs | Latency of explicit `load_skill` calls. | Histogram | | **MCP Server** | action.\.mcp_server.\.numOfMcpToolCallsSucceeded | The number of successful Tool calls served by the MCP Server. | Count | | **MCP Server** | action.\.mcp_server.\.numOfMcpToolCallsFailed | The number of failed Tool calls served by the MCP Server. | Count | @@ -80,14 +80,18 @@ Execution metrics are derived from LLM and Tool execution lifecycle events. The An LLM metric represents one framework invocation of `ChatModel`. A framework retry that calls the model again produces another LLM outcome and latency sample; retries hidden inside a provider or connection are not observed. Every named Tool execution emits Tool metrics. Skill metrics are emitted only for explicit `load_skill` calls; subsequent Tool calls are not inferred to belong to a Skill. MCP metrics aggregate only Tool executions carrying an explicit MCP Server resource name. A `load_skill` or MCP Tool execution therefore contributes to both its Tool scope and the corresponding Skill or MCP Server scope. -Tool names that are not registered runtime resources are aggregated under the fixed `tool=unknown` scope to keep metric cardinality bounded. Their original requested names remain available in Agent Trace records. +Execution metrics currently inherit Agent Trace's durable-replay behavior. During fine-grained recovery, a cached durable LLM or Tool result is reported as a new successful execution because child cache reuse is not exposed to execution reporting. The corresponding success counter therefore increments and the latency histogram may receive a near-zero sample even though the underlying model or Tool was not invoked. Distinguishing reused child executions is follow-up work. + +Tool names that are not registered runtime resources are aggregated under the fixed `tool=unknown` scope. Requested Skill names that do not resolve in the runtime registry are similarly aggregated under `skill=unknown`. The original requested names remain available in Agent Trace records, while Metric scope cardinality remains bounded. Tool outcomes follow the existing language-specific Tool contracts. In both Java and Python, resource preparation or invocation exceptions are failures and a normal return is successful. Java additionally treats an unsuccessful `ToolResponse` as a failed Tool execution. Python Tools return arbitrary values and currently have no equivalent explicit error-result type, so the runtime does not infer failure from a normally returned Python value. -Consequently, Tool and MCP outcome metrics use the same names and scopes in both runtimes, but explicit error-result semantics are not yet identical. This alignment is tracked in [Issue #956](https://github.com/apache/flink-agents/issues/956) and is planned after the parallel Tool-call work in [PR #926](https://github.com/apache/flink-agents/pull/926). +`numOfSkillLoads` counts terminal calls rather than successful loads. Under the current Tool contracts, a `load_skill` not-found response returns normally and is therefore observed as a successful Tool outcome. Consequently, Tool and MCP outcome metrics use the same names and scopes in both runtimes, but explicit error-result semantics are not yet identical. This alignment, including explicit failure results for framework Tools such as `load_skill`, is tracked in [Issue #956](https://github.com/apache/flink-agents/issues/956). Execution latency tracking is process-local. A latency sample is recorded only when the execution start and terminal events are observed in the same task attempt; LLM and Tool terminal counters are still updated when a restored execution has no local start timestamp. +In previous releases, `retryCount` and `retryWaitSec` used the `model.` scope. They now use `model_resource.` so retries are attributed to the configured ChatModel resource. Existing queries and dashboards for these two metrics must use the new scope. + #### Token Usage Metrics Token usage metrics are automatically recorded when chat models are invoked through `ChatModelConnection`. These metrics help track LLM API usage and costs. @@ -161,7 +165,7 @@ public class MyAgent extends Agent { ### How to check the metrics with Flink executor -Flink agents enable the reporting of metrics to external systems by creating a metric identifier prefix in the format `.taskmanager....`. For an agent operator, `` is the agent name. Agent-specific metrics use key-value metric groups (e.g., `action.`, `model.`) which are exposed as dimensions/labels in reporters that support them (such as Prometheus). Please refer to [Flink Metric Reporters](https://nightlies.apache.org/flink/flink-docs-release-1.20/docs/deployment/metric_reporters/) for more details. +Flink agents enable the reporting of metrics to external systems by creating a metric identifier prefix in the format `.taskmanager....`. For an agent operator, `` is the agent name. If the Agent name is unavailable, the operator retains the previous `action-execute-operator` value as a fallback. This changes only the value of the existing `` scope; the Agent-specific metric hierarchy is unchanged. Queries and dashboards that filter on `operator_name=action-execute-operator` must use the Agent name after upgrading. Agent-specific metrics use key-value metric groups (e.g., `action.`, `model.`) which are exposed as dimensions/labels in reporters that support them (such as Prometheus). Please refer to [Flink Metric Reporters](https://nightlies.apache.org/flink/flink-docs-release-1.20/docs/deployment/metric_reporters/) for more details. Additionally, we can check the metric results in the Flink Job WebUI using the metric identifier prefix `.`. diff --git a/python/flink_agents/api/trace/tool_execution_metadata_keys.py b/python/flink_agents/api/trace/tool_execution_metadata_keys.py index 1308cb7be..7549a096c 100644 --- a/python/flink_agents/api/trace/tool_execution_metadata_keys.py +++ b/python/flink_agents/api/trace/tool_execution_metadata_keys.py @@ -27,4 +27,5 @@ class ToolExecutionMetadataKeys: TOOL_TYPE = "toolType" MCP_SERVER = "mcpServer" SKILL_NAME = "skillName" + SKILL_REGISTERED = "skillRegistered" SKILL_RESOURCE_PATH = "skillResourcePath" diff --git a/python/flink_agents/runtime/skill/skill_tools.py b/python/flink_agents/runtime/skill/skill_tools.py index 5178ab308..b50e7f163 100644 --- a/python/flink_agents/runtime/skill/skill_tools.py +++ b/python/flink_agents/runtime/skill/skill_tools.py @@ -92,7 +92,11 @@ def get_tool_execution_metadata( """Describe the requested skill resource for execution tracing.""" metadata = {} if "name" in parameters: - metadata[ToolExecutionMetadataKeys.SKILL_NAME] = str(parameters["name"]) + skill_name = str(parameters["name"]) + metadata[ToolExecutionMetadataKeys.SKILL_NAME] = skill_name + metadata[ToolExecutionMetadataKeys.SKILL_REGISTERED] = ( + self._is_registered_skill(skill_name) + ) metadata[ToolExecutionMetadataKeys.SKILL_RESOURCE_PATH] = ( _normalize_skill_resource_path( parameters.get("path"), missing="path" not in parameters @@ -151,6 +155,13 @@ def call(self, *args: Any, **kwargs: Any) -> str: return f"Resource '{resource_path}' not found in skill '{skill_name}', Available resources: {available}" return content + def _is_registered_skill(self, skill_name: str) -> bool: + try: + manager = self._get_skill_manager() + return manager is not None and skill_name in manager.get_all_skill_names() + except Exception: + return False + def _get_skill_manager(self) -> SkillManager | None: from flink_agents.runtime.resource_context import ResourceContextImpl diff --git a/python/flink_agents/runtime/skill/tests/test_load_skill.py b/python/flink_agents/runtime/skill/tests/test_load_skill.py index be0246ce8..d47f50681 100644 --- a/python/flink_agents/runtime/skill/tests/test_load_skill.py +++ b/python/flink_agents/runtime/skill/tests/test_load_skill.py @@ -95,9 +95,12 @@ def test_execution_metadata_describes_requested_resource( {"name": "github", "path": "README.md"} ) assert metadata[ToolExecutionMetadataKeys.SKILL_NAME] == "github" + assert metadata[ToolExecutionMetadataKeys.SKILL_REGISTERED] is True assert metadata[ToolExecutionMetadataKeys.SKILL_RESOURCE_PATH] == "README.md" - def test_execution_metadata_normalizes_omitted_path(self, tool: LoadSkillTool) -> None: + def test_execution_metadata_normalizes_omitted_path( + self, tool: LoadSkillTool + ) -> None: metadata = tool.get_tool_execution_metadata({"name": "github"}) assert metadata[ToolExecutionMetadataKeys.SKILL_NAME] == "github" assert metadata[ToolExecutionMetadataKeys.SKILL_RESOURCE_PATH] == "SKILL.md" @@ -118,6 +121,13 @@ def test_skill_not_found(self, tool: LoadSkillTool) -> None: assert "github" in result assert "nano-banana-pro" in result + def test_execution_metadata_marks_unknown_skill_as_unregistered( + self, tool: LoadSkillTool + ) -> None: + metadata = tool.get_tool_execution_metadata({"name": "nonexistent-skill"}) + assert metadata[ToolExecutionMetadataKeys.SKILL_NAME] == "nonexistent-skill" + assert metadata[ToolExecutionMetadataKeys.SKILL_REGISTERED] is False + # -- no skill manager ---------------------------------------------------- def test_no_skill_manager(self) -> None: diff --git a/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInMetrics.java b/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInMetrics.java index e21ebb425..b1aafdc3b 100644 --- a/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInMetrics.java +++ b/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInMetrics.java @@ -38,6 +38,8 @@ */ public class BuiltInMetrics { + private final FlinkAgentsMetricGroupImpl parentMetricGroup; + private final Meter numOfEventProcessedPerSec; private final Meter numOfActionsExecutedPerSec; @@ -66,6 +68,7 @@ public BuiltInMetrics( FlinkAgentsMetricGroupImpl parentMetricGroup, AgentPlan agentPlan, Predicate isRegisteredTool) { + this.parentMetricGroup = parentMetricGroup; Counter numOfEventsProcessed = parentMetricGroup.getCounter("numOfEventProcessed"); this.numOfEventProcessedPerSec = parentMetricGroup.getMeter("numOfEventProcessedPerSec", numOfEventsProcessed); @@ -82,10 +85,7 @@ public BuiltInMetrics( this.actionMetricGroups = new HashMap<>(); for (String actionName : agentPlan.getActions().keySet()) { - actionMetricGroups.put( - actionName, - new BuiltInActionMetrics( - parentMetricGroup.getSubGroup("action", actionName), System::nanoTime)); + actionMetricGroups.put(actionName, createActionMetrics(actionName)); } } @@ -150,7 +150,7 @@ public void markActionTaskDequeued( public void restoreActionTask(ExecutionTraceContext traceContext, boolean executionStarted) { inputRunMetrics.identifyRestoredActiveInputRun(traceContext.getInputRunId()); - actionMetrics(traceContext.getEntityName()) + restoredActionMetrics(traceContext.getEntityName()) .restoreActionTask(traceContext.getExecutionId(), executionStarted); } @@ -180,4 +180,13 @@ private BuiltInActionMetrics actionMetrics(String actionName) { } return actionMetrics; } + + private BuiltInActionMetrics restoredActionMetrics(String actionName) { + return actionMetricGroups.computeIfAbsent(actionName, this::createActionMetrics); + } + + private BuiltInActionMetrics createActionMetrics(String actionName) { + return new BuiltInActionMetrics( + parentMetricGroup.getSubGroup("action", actionName), System::nanoTime); + } } diff --git a/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/ToolExecutionMetricRecorder.java b/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/ToolExecutionMetricRecorder.java index 995ae1865..f2b0bc7eb 100644 --- a/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/ToolExecutionMetricRecorder.java +++ b/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/ToolExecutionMetricRecorder.java @@ -30,6 +30,7 @@ final class ToolExecutionMetricRecorder implements ExecutionMetricRecorder { static final String UNKNOWN_TOOL_NAME = "unknown"; + static final String UNKNOWN_SKILL_NAME = "unknown"; static final String NUM_TOOL_CALLS_SUCCEEDED = "numOfToolCallsSucceeded"; static final String NUM_TOOL_CALLS_FAILED = "numOfToolCallsFailed"; @@ -74,8 +75,10 @@ public void record( String skillName = metadataValue(traceContext, ToolExecutionMetadataKeys.SKILL_NAME); if (!isBlank(skillName)) { + String metricSkillName = + isRegisteredSkill(traceContext) ? skillName : UNKNOWN_SKILL_NAME; FlinkAgentsMetricGroupImpl skillMetricGroup = - actionMetricGroup.getSubGroup("skill", skillName); + actionMetricGroup.getSubGroup("skill", metricSkillName); skillMetricGroup.getCounter(NUM_SKILL_LOADS).inc(); updateLatency(skillMetricGroup.getHistogram(SKILL_LOAD_LATENCY_MS), latencyMs); } @@ -116,6 +119,11 @@ private static String metadataValue(ExecutionTraceContext traceContext, String m return value == null ? null : String.valueOf(value); } + private static boolean isRegisteredSkill(ExecutionTraceContext traceContext) { + return Boolean.TRUE.equals( + traceContext.getEntityMetadata().get(ToolExecutionMetadataKeys.SKILL_REGISTERED)); + } + private static boolean isBlank(String value) { return value == null || value.isBlank(); } diff --git a/runtime/src/main/java/org/apache/flink/agents/runtime/skill/LoadSkillTool.java b/runtime/src/main/java/org/apache/flink/agents/runtime/skill/LoadSkillTool.java index abfeb306f..b9c5f0d43 100644 --- a/runtime/src/main/java/org/apache/flink/agents/runtime/skill/LoadSkillTool.java +++ b/runtime/src/main/java/org/apache/flink/agents/runtime/skill/LoadSkillTool.java @@ -69,9 +69,9 @@ public ToolType getToolType() { public Map getToolExecutionMetadata(ToolParameters parameters) { Map metadata = new LinkedHashMap<>(); if (parameters.hasParameter("name")) { - metadata.put( - ToolExecutionMetadataKeys.SKILL_NAME, - String.valueOf(parameters.getParameter("name"))); + String skillName = String.valueOf(parameters.getParameter("name")); + metadata.put(ToolExecutionMetadataKeys.SKILL_NAME, skillName); + metadata.put(ToolExecutionMetadataKeys.SKILL_REGISTERED, isRegisteredSkill(skillName)); } metadata.put( ToolExecutionMetadataKeys.SKILL_RESOURCE_PATH, normalizeResourcePath(parameters)); @@ -158,6 +158,15 @@ private SkillManager resolveSkillManager() throws Exception { return null; } + private boolean isRegisteredSkill(String skillName) { + try { + SkillManager manager = resolveSkillManager(); + return manager != null && manager.getAllSkillNames().contains(skillName); + } catch (Exception ignored) { + return false; + } + } + private static String normalizeResourcePath(ToolParameters parameters) { if (parameters == null || !parameters.hasParameter("path")) { return "SKILL.md"; diff --git a/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetricsTest.java b/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetricsTest.java index 95ad74c97..7716287b6 100644 --- a/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetricsTest.java +++ b/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetricsTest.java @@ -148,7 +148,11 @@ void recordsExplicitSkillLoads() { execution( ExecutionReporter.EntityTypes.TOOL, "load_skill", - Map.of(ToolExecutionMetadataKeys.SKILL_NAME, "calculator")); + Map.of( + ToolExecutionMetadataKeys.SKILL_NAME, + "calculator", + ToolExecutionMetadataKeys.SKILL_REGISTERED, + true)); metrics.executionEventObserved( ACTION_NAME, ExecutionLifecycleEvents.executionStarted(), loadSkill); nanoTime.addAndGet(12_000_000L); @@ -169,6 +173,39 @@ void recordsExplicitSkillLoads() { .isEqualTo(1); } + @Test + void aggregatesUnregisteredSkillNamesIntoUnknownScope() { + ExecutionTraceContext first = + execution( + ExecutionReporter.EntityTypes.TOOL, + "load_skill", + Map.of( + ToolExecutionMetadataKeys.SKILL_NAME, + "hallucinated_one", + ToolExecutionMetadataKeys.SKILL_REGISTERED, + false)); + ExecutionTraceContext second = + execution( + ExecutionReporter.EntityTypes.TOOL, + "load_skill", + Map.of( + ToolExecutionMetadataKeys.SKILL_NAME, + "hallucinated_two", + ToolExecutionMetadataKeys.SKILL_REGISTERED, + false)); + + metrics.executionEventObserved( + ACTION_NAME, ExecutionLifecycleEvents.executionFinished(), first); + metrics.executionEventObserved( + ACTION_NAME, ExecutionLifecycleEvents.executionFinished(), second); + + FlinkAgentsMetricGroupImpl unknown = + actionMetricGroup() + .getSubGroup("skill", ToolExecutionMetricRecorder.UNKNOWN_SKILL_NAME); + assertThat(unknown.getCounter(ToolExecutionMetricRecorder.NUM_SKILL_LOADS).getCount()) + .isEqualTo(2); + } + @Test void aggregatesMcpToolOutcomesByServer() { ExecutionTraceContext success = diff --git a/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInMetricsTest.java b/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInMetricsTest.java new file mode 100644 index 000000000..acae32521 --- /dev/null +++ b/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInMetricsTest.java @@ -0,0 +1,64 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ +package org.apache.flink.agents.runtime.metrics; + +import org.apache.flink.agents.api.trace.ExecutionLifecycleEvents; +import org.apache.flink.agents.api.trace.ExecutionTraceContext; +import org.apache.flink.agents.plan.AgentPlan; +import org.apache.flink.metrics.MetricGroup; +import org.apache.flink.runtime.metrics.groups.UnregisteredMetricGroups; +import org.junit.jupiter.api.Test; + +import java.util.Map; + +import static org.assertj.core.api.Assertions.assertThat; + +class BuiltInMetricsTest { + + @Test + void restoredActionMissingFromCurrentPlanKeepsItsMetricLifecycle() { + MetricGroup parentMetricGroup = + UnregisteredMetricGroups.createUnregisteredOperatorMetricGroup(); + FlinkAgentsMetricGroupImpl metricGroup = new FlinkAgentsMetricGroupImpl(parentMetricGroup); + BuiltInMetrics metrics = new BuiltInMetrics(metricGroup, new AgentPlan(Map.of())); + ExecutionTraceContext restoredAction = + ExecutionTraceContext.forAction( + ExecutionTraceContext.forInputRun("key", "agent"), "restored_action"); + + metrics.restoreActionTask(restoredAction, true); + metrics.markActionTaskDequeued(restoredAction, true); + metrics.markExecutionEvent( + "restored_action", ExecutionLifecycleEvents.executionReused(), restoredAction); + metrics.markActionExecuted("restored_action"); + + FlinkAgentsMetricGroupImpl actionMetricGroup = + metricGroup.getSubGroup("action", "restored_action"); + assertThat( + actionMetricGroup + .getGauge(BuiltInActionMetrics.NUM_PENDING_ACTION_TASKS) + .getValue()) + .isEqualTo(0L); + assertThat( + actionMetricGroup + .getGauge(BuiltInActionMetrics.NUM_ACTIVE_ACTION_EXECUTIONS) + .getValue()) + .isEqualTo(0L); + assertThat(actionMetricGroup.getCounter("numOfActionsExecuted").getCount()).isEqualTo(1L); + } +} diff --git a/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/CurrentCountGaugeTest.java b/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/CurrentCountGaugeTest.java new file mode 100644 index 000000000..ff9b6c32a --- /dev/null +++ b/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/CurrentCountGaugeTest.java @@ -0,0 +1,60 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ +package org.apache.flink.agents.runtime.metrics; + +import org.apache.flink.metrics.MetricGroup; +import org.apache.flink.runtime.metrics.groups.UnregisteredMetricGroups; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Test; + +import static org.assertj.core.api.Assertions.assertThat; + +class CurrentCountGaugeTest { + + private static final String GAUGE_NAME = "current"; + + private FlinkAgentsMetricGroupImpl metricGroup; + private CurrentCountGauge gauge; + + @BeforeEach + void setUp() { + MetricGroup parentMetricGroup = + UnregisteredMetricGroups.createUnregisteredOperatorMetricGroup(); + metricGroup = new FlinkAgentsMetricGroupImpl(parentMetricGroup); + gauge = new CurrentCountGauge(metricGroup, GAUGE_NAME); + } + + @Test + void decrementAtZeroRemainsZero() { + gauge.decrement(); + + assertThat(value()).isZero(); + } + + @Test + void negativeSetValueIsClampedToZero() { + gauge.set(-1L); + + assertThat(value()).isZero(); + } + + private long value() { + return (Long) metricGroup.getGauge(GAUGE_NAME).getValue(); + } +} diff --git a/runtime/src/test/java/org/apache/flink/agents/runtime/skill/LoadSkillToolTest.java b/runtime/src/test/java/org/apache/flink/agents/runtime/skill/LoadSkillToolTest.java index f131cd07e..5bb0df784 100644 --- a/runtime/src/test/java/org/apache/flink/agents/runtime/skill/LoadSkillToolTest.java +++ b/runtime/src/test/java/org/apache/flink/agents/runtime/skill/LoadSkillToolTest.java @@ -103,9 +103,19 @@ void executionMetadataDescribesRequestedSkillResource() { tool(contextWithSkills()).getToolExecutionMetadata(args("github", "README.md")); assertEquals("github", metadata.get(ToolExecutionMetadataKeys.SKILL_NAME)); + assertEquals(true, metadata.get(ToolExecutionMetadataKeys.SKILL_REGISTERED)); assertEquals("README.md", metadata.get(ToolExecutionMetadataKeys.SKILL_RESOURCE_PATH)); } + @Test + void executionMetadataMarksUnknownSkillAsUnregistered() { + Map metadata = + tool(contextWithSkills()).getToolExecutionMetadata(args("does-not-exist", null)); + + assertEquals("does-not-exist", metadata.get(ToolExecutionMetadataKeys.SKILL_NAME)); + assertEquals(false, metadata.get(ToolExecutionMetadataKeys.SKILL_REGISTERED)); + } + @Test void executionMetadataNormalizesOmittedPathToSkillMd() { Map metadata = From 367be6c0695ee536f5f1d1244c3628a5c5971953 Mon Sep 17 00:00:00 2001 From: Joey Tong Date: Mon, 31 Aug 2026 13:33:35 +0800 Subject: [PATCH 06/10] [runtime][docs] Address final metrics review comments Scope child execution latency state to its Action, reserve built-in metric names, and remove the inconsistent Tool registration fallback. Co-Authored-By: Claude Code AI-Model: gpt-5.6-sol AI-Contributed/Feature: 64/64 AI-Contributed/UT: 46/46 --- .../agents/api/context/RunnerContext.java | 4 ++ docs/content/docs/operations/monitoring.md | 2 + .../metrics/BuiltInExecutionMetrics.java | 37 +++++++++++++--- .../runtime/metrics/BuiltInMetrics.java | 21 +++++---- .../runtime/metrics/BuiltInMetricsTest.java | 44 ++++++++++++++++++- .../runtime/operator/EventRouterTest.java | 2 +- 6 files changed, 92 insertions(+), 18 deletions(-) diff --git a/api/src/main/java/org/apache/flink/agents/api/context/RunnerContext.java b/api/src/main/java/org/apache/flink/agents/api/context/RunnerContext.java index a61dc0d18..76f8b11a1 100644 --- a/api/src/main/java/org/apache/flink/agents/api/context/RunnerContext.java +++ b/api/src/main/java/org/apache/flink/agents/api/context/RunnerContext.java @@ -72,6 +72,8 @@ public interface RunnerContext { * from inside a {@link #durableExecute} or {@link #durableExecuteAsync} callable, which runs on * a separate thread pool. * + *

    Names used by built-in Agent metrics are reserved in this group. + * * @return the metric group shared across all actions. */ FlinkAgentsMetricGroup getAgentMetricGroup(); @@ -83,6 +85,8 @@ public interface RunnerContext { * from inside a {@link #durableExecute} or {@link #durableExecuteAsync} callable, which runs on * a separate thread pool. * + *

    Names used by built-in Action metrics are reserved in this group. + * * @return the individual metric group specific to the current action. */ FlinkAgentsMetricGroup getActionMetricGroup(); diff --git a/docs/content/docs/operations/monitoring.md b/docs/content/docs/operations/monitoring.md index a890f16c7..99d67466a 100644 --- a/docs/content/docs/operations/monitoring.md +++ b/docs/content/docs/operations/monitoring.md @@ -105,6 +105,8 @@ Token usage metrics are automatically recorded when chat models are invoked thro In Flink Agents, users implement their logic by defining custom Actions that respond to various Events throughout the Agent lifecycle. To support user-defined metrics, we introduce two new properties: `agent_metric_group` and `action_metric_group` in the RunnerContext. These properties allow users to create or update global metrics and independent metrics for actions. For an introduction to metric types, please refer to the [Metric types documentation](https://nightlies.apache.org/flink/flink-docs-release-1.20/docs/ops/metrics/#metric-types). +Metric names listed in the built-in tables above are reserved in their corresponding scopes. Custom metrics must use different names within the same scope. + Here is the user case example: {{< tabs "Custom Metrics" >}} diff --git a/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetrics.java b/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetrics.java index 6574eee73..d98005eb0 100644 --- a/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetrics.java +++ b/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetrics.java @@ -34,7 +34,8 @@ final class BuiltInExecutionMetrics { private final FlinkAgentsMetricGroupImpl agentMetricGroup; private final LongSupplier nanoTime; private final Map metricRecordersByEntityType; - private final Map activeExecutionStartNanos = new HashMap<>(); + private final Map> startNanosByActionExecutionId = + new HashMap<>(); BuiltInExecutionMetrics( FlinkAgentsMetricGroupImpl agentMetricGroup, @@ -62,9 +63,12 @@ void executionEventObserved( } String executionId = traceContext.getExecutionId(); + String actionExecutionId = traceContext.getParentExecutionId(); if (ExecutionLifecycleEvents.EXECUTION_STARTED_EVENT_TYPE.equals(event.getType())) { - if (!isBlank(executionId)) { - activeExecutionStartNanos.putIfAbsent(executionId, nanoTime.getAsLong()); + if (!isBlank(actionExecutionId) && !isBlank(executionId)) { + startNanosByActionExecutionId + .computeIfAbsent(actionExecutionId, ignored -> new HashMap<>()) + .putIfAbsent(executionId, nanoTime.getAsLong()); } return; } @@ -77,8 +81,7 @@ void executionEventObserved( return; } - Long startNanos = - isBlank(executionId) ? null : activeExecutionStartNanos.remove(executionId); + Long startNanos = removeExecutionStart(actionExecutionId, executionId); Long latencyMs = startNanos == null ? null @@ -94,6 +97,30 @@ void executionEventObserved( recorder.record(actionMetricGroup, traceContext, outcome, latencyMs); } + void actionExecutionTerminated(String actionExecutionId) { + if (!isBlank(actionExecutionId)) { + startNanosByActionExecutionId.remove(actionExecutionId); + } + } + + private Long removeExecutionStart(String actionExecutionId, String executionId) { + if (isBlank(actionExecutionId) || isBlank(executionId)) { + return null; + } + + Map actionExecutionStarts = + startNanosByActionExecutionId.get(actionExecutionId); + if (actionExecutionStarts == null) { + return null; + } + + Long startNanos = actionExecutionStarts.remove(executionId); + if (actionExecutionStarts.isEmpty()) { + startNanosByActionExecutionId.remove(actionExecutionId); + } + return startNanos; + } + private static boolean isBlank(String value) { return value == null || value.isBlank(); } diff --git a/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInMetrics.java b/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInMetrics.java index b1aafdc3b..9fd2b23f1 100644 --- a/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInMetrics.java +++ b/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInMetrics.java @@ -20,7 +20,7 @@ package org.apache.flink.agents.runtime.metrics; import org.apache.flink.agents.api.Event; -import org.apache.flink.agents.api.resource.ResourceType; +import org.apache.flink.agents.api.trace.ExecutionLifecycleEvents; import org.apache.flink.agents.api.trace.ExecutionReporter; import org.apache.flink.agents.api.trace.ExecutionTraceContext; import org.apache.flink.agents.plan.AgentPlan; @@ -54,16 +54,6 @@ public class BuiltInMetrics { private final Map actionMetricGroups; - public BuiltInMetrics(FlinkAgentsMetricGroupImpl parentMetricGroup, AgentPlan agentPlan) { - this( - parentMetricGroup, - agentPlan, - toolName -> { - Map tools = agentPlan.getResourceProviders().get(ResourceType.TOOL); - return tools != null && tools.containsKey(toolName); - }); - } - public BuiltInMetrics( FlinkAgentsMetricGroupImpl parentMetricGroup, AgentPlan agentPlan, @@ -158,6 +148,9 @@ public void markExecutionEvent( String actionName, Event event, ExecutionTraceContext traceContext) { if (ExecutionReporter.EntityTypes.ACTION.equals(traceContext.getEntityType())) { actionMetrics(actionName).executionEventObserved(event, traceContext); + if (isTerminalExecutionEvent(event)) { + executionMetrics.actionExecutionTerminated(traceContext.getExecutionId()); + } } else { executionMetrics.executionEventObserved(actionName, event, traceContext); } @@ -189,4 +182,10 @@ private BuiltInActionMetrics createActionMetrics(String actionName) { return new BuiltInActionMetrics( parentMetricGroup.getSubGroup("action", actionName), System::nanoTime); } + + private static boolean isTerminalExecutionEvent(Event event) { + return ExecutionLifecycleEvents.EXECUTION_FINISHED_EVENT_TYPE.equals(event.getType()) + || ExecutionLifecycleEvents.EXECUTION_FAILED_EVENT_TYPE.equals(event.getType()) + || ExecutionLifecycleEvents.EXECUTION_REUSED_EVENT_TYPE.equals(event.getType()); + } } diff --git a/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInMetricsTest.java b/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInMetricsTest.java index acae32521..c026c7f6c 100644 --- a/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInMetricsTest.java +++ b/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInMetricsTest.java @@ -19,6 +19,7 @@ package org.apache.flink.agents.runtime.metrics; import org.apache.flink.agents.api.trace.ExecutionLifecycleEvents; +import org.apache.flink.agents.api.trace.ExecutionReporter; import org.apache.flink.agents.api.trace.ExecutionTraceContext; import org.apache.flink.agents.plan.AgentPlan; import org.apache.flink.metrics.MetricGroup; @@ -36,7 +37,8 @@ void restoredActionMissingFromCurrentPlanKeepsItsMetricLifecycle() { MetricGroup parentMetricGroup = UnregisteredMetricGroups.createUnregisteredOperatorMetricGroup(); FlinkAgentsMetricGroupImpl metricGroup = new FlinkAgentsMetricGroupImpl(parentMetricGroup); - BuiltInMetrics metrics = new BuiltInMetrics(metricGroup, new AgentPlan(Map.of())); + BuiltInMetrics metrics = + new BuiltInMetrics(metricGroup, new AgentPlan(Map.of()), ignored -> false); ExecutionTraceContext restoredAction = ExecutionTraceContext.forAction( ExecutionTraceContext.forInputRun("key", "agent"), "restored_action"); @@ -61,4 +63,44 @@ void restoredActionMissingFromCurrentPlanKeepsItsMetricLifecycle() { .isEqualTo(0L); assertThat(actionMetricGroup.getCounter("numOfActionsExecuted").getCount()).isEqualTo(1L); } + + @Test + void actionTerminalDropsOnlyItsUnpairedChildLatencyState() { + MetricGroup parentMetricGroup = + UnregisteredMetricGroups.createUnregisteredOperatorMetricGroup(); + FlinkAgentsMetricGroupImpl metricGroup = new FlinkAgentsMetricGroupImpl(parentMetricGroup); + BuiltInMetrics metrics = + new BuiltInMetrics(metricGroup, new AgentPlan(Map.of()), ignored -> false); + ExecutionTraceContext inputRun = ExecutionTraceContext.forInputRun("key", "agent"); + ExecutionTraceContext completedAction = + ExecutionTraceContext.forAction(inputRun, "restored_action"); + ExecutionTraceContext activeAction = + ExecutionTraceContext.forAction(inputRun, "restored_action"); + ExecutionTraceContext completedActionLlm = + completedAction.childExecution(ExecutionReporter.EntityTypes.LLM, "primary_model"); + ExecutionTraceContext activeActionLlm = + activeAction.childExecution(ExecutionReporter.EntityTypes.LLM, "primary_model"); + metrics.restoreActionTask(completedAction, false); + + metrics.markExecutionEvent( + "restored_action", ExecutionLifecycleEvents.executionStarted(), completedActionLlm); + metrics.markExecutionEvent( + "restored_action", ExecutionLifecycleEvents.executionStarted(), activeActionLlm); + metrics.markExecutionEvent( + "restored_action", ExecutionLifecycleEvents.executionFinished(), completedAction); + metrics.markExecutionEvent( + "restored_action", + ExecutionLifecycleEvents.executionFinished(), + completedActionLlm); + metrics.markExecutionEvent( + "restored_action", ExecutionLifecycleEvents.executionFinished(), activeActionLlm); + + assertThat( + metricGroup + .getSubGroup("action", "restored_action") + .getSubGroup("model_resource", "primary_model") + .getHistogram(LlmExecutionMetricRecorder.LLM_CALL_LATENCY_MS) + .getCount()) + .isEqualTo(1L); + } } diff --git a/runtime/src/test/java/org/apache/flink/agents/runtime/operator/EventRouterTest.java b/runtime/src/test/java/org/apache/flink/agents/runtime/operator/EventRouterTest.java index 1cba93622..e781879a4 100644 --- a/runtime/src/test/java/org/apache/flink/agents/runtime/operator/EventRouterTest.java +++ b/runtime/src/test/java/org/apache/flink/agents/runtime/operator/EventRouterTest.java @@ -288,6 +288,6 @@ private static BuiltInMetrics makeMetrics() { FlinkAgentsMetricGroupImpl metricGroup = mock(FlinkAgentsMetricGroupImpl.class, RETURNS_DEEP_STUBS); AgentPlan plan = new AgentPlan(new HashMap<>(), new HashMap<>()); - return new BuiltInMetrics(metricGroup, plan); + return new BuiltInMetrics(metricGroup, plan, ignored -> false); } } From 61648680b840d85475791907f465347296bc513e Mon Sep 17 00:00:00 2001 From: Joey Tong Date: Mon, 31 Aug 2026 13:36:23 +0800 Subject: [PATCH 07/10] [runtime] Fix execution metric formatting Apply Spotless after shortening the Action-scoped latency state name. Co-Authored-By: Claude Code AI-Model: gpt-5.6-sol AI-Contributed/Feature: 3/3 AI-Contributed/UT: 0/0 --- .../flink/agents/runtime/metrics/BuiltInExecutionMetrics.java | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetrics.java b/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetrics.java index d98005eb0..b80899f88 100644 --- a/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetrics.java +++ b/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetrics.java @@ -34,8 +34,7 @@ final class BuiltInExecutionMetrics { private final FlinkAgentsMetricGroupImpl agentMetricGroup; private final LongSupplier nanoTime; private final Map metricRecordersByEntityType; - private final Map> startNanosByActionExecutionId = - new HashMap<>(); + private final Map> startNanosByActionExecutionId = new HashMap<>(); BuiltInExecutionMetrics( FlinkAgentsMetricGroupImpl agentMetricGroup, From 6a404e3775f189b93d1312d67ab7f4dc940ef01f Mon Sep 17 00:00:00 2001 From: Joey Tong Date: Tue, 1 Sep 2026 13:58:31 +0800 Subject: [PATCH 08/10] [runtime] Strengthen action latency cleanup test Use distinct model resource scopes to verify that terminal Action cleanup removes only the completed Action's child latency state. Co-Authored-By: Claude Code AI-Model: gpt-5.6-sol AI-Contributed/Feature: 0/0 AI-Contributed/UT: 9/9 --- .../flink/agents/runtime/metrics/BuiltInMetricsTest.java | 9 ++++++++- 1 file changed, 8 insertions(+), 1 deletion(-) diff --git a/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInMetricsTest.java b/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInMetricsTest.java index c026c7f6c..ff59e4cbd 100644 --- a/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInMetricsTest.java +++ b/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInMetricsTest.java @@ -79,7 +79,7 @@ void actionTerminalDropsOnlyItsUnpairedChildLatencyState() { ExecutionTraceContext completedActionLlm = completedAction.childExecution(ExecutionReporter.EntityTypes.LLM, "primary_model"); ExecutionTraceContext activeActionLlm = - activeAction.childExecution(ExecutionReporter.EntityTypes.LLM, "primary_model"); + activeAction.childExecution(ExecutionReporter.EntityTypes.LLM, "secondary_model"); metrics.restoreActionTask(completedAction, false); metrics.markExecutionEvent( @@ -101,6 +101,13 @@ void actionTerminalDropsOnlyItsUnpairedChildLatencyState() { .getSubGroup("model_resource", "primary_model") .getHistogram(LlmExecutionMetricRecorder.LLM_CALL_LATENCY_MS) .getCount()) + .isZero(); + assertThat( + metricGroup + .getSubGroup("action", "restored_action") + .getSubGroup("model_resource", "secondary_model") + .getHistogram(LlmExecutionMetricRecorder.LLM_CALL_LATENCY_MS) + .getCount()) .isEqualTo(1L); } } From 7c3abde69c07ad437208c62a425180831d5dfed1 Mon Sep 17 00:00:00 2001 From: Joey Tong Date: Thu, 3 Sep 2026 18:18:52 +0800 Subject: [PATCH 09/10] [plan][runtime][python] Measure latency from per-tool occurrences Capture each Tool invocation's timestamps in ToolCallAction and carry them through EventContext to metrics and Event Log, preserving deferred mailbox delivery without substituting the batch duration. Use each durable Outcome for terminal status and omit latency samples when the callable was not invoked. Capture timeout result observation before response processing and reporting without changing the execution framework. Validated with 168 Java and 63 Python tests, Spotless, and Ruff. Generated-by: Codex CLI 0.153.0-alpha.5 (gpt-5.6-sol) Co-Authored-By: Codex AI-Model: gpt-5.6-sol AI-Contributed/Feature: 766/766 AI-Contributed/UT: 1162/1162 --- .../agents/api/trace/ExecutionReporter.java | 48 ++ .../agents/api/trace/ExecutionReporters.java | 49 ++ docs/content/docs/operations/monitoring.md | 16 +- .../agents/plan/actions/ToolCallAction.java | 167 +++--- .../actions/ToolCallActionReportTest.java | 487 +++++++++++++++++- .../api/tests/test_execution_reporter.py | 51 ++ .../api/trace/execution_reporter.py | 99 ++++ .../plan/actions/tool_call_action.py | 127 +++-- .../tests/actions/test_tool_call_action.py | 429 ++++++++++++++- .../runtime/flink_runner_context.py | 52 ++ .../tests/test_flink_runner_context_trace.py | 32 ++ .../runtime/context/RunnerContextImpl.java | 63 ++- .../runtime/eventlog/EventLogWriter.java | 8 +- .../metrics/BuiltInExecutionMetrics.java | 64 ++- .../runtime/metrics/BuiltInMetrics.java | 14 +- .../operator/ActionExecutionOperator.java | 17 +- .../context/PythonRunnerContextImpl.java | 34 ++ .../runtime/trace/ExecutionEventLogger.java | 5 +- .../runtime/trace/ExecutionEventSink.java | 3 +- ...unnerContextImplExecutionReporterTest.java | 36 +- .../runtime/eventlog/EventLogWriterTest.java | 6 +- .../metrics/BuiltInExecutionMetricsTest.java | 101 ++-- .../operator/ActionExecutionOperatorTest.java | 14 +- .../ActionTaskContextManagerTest.java | 6 +- 24 files changed, 1689 insertions(+), 239 deletions(-) diff --git a/api/src/main/java/org/apache/flink/agents/api/trace/ExecutionReporter.java b/api/src/main/java/org/apache/flink/agents/api/trace/ExecutionReporter.java index a3fb6f11b..95e75ad6d 100644 --- a/api/src/main/java/org/apache/flink/agents/api/trace/ExecutionReporter.java +++ b/api/src/main/java/org/apache/flink/agents/api/trace/ExecutionReporter.java @@ -62,6 +62,21 @@ void reportExecutionStarted( String entityType, String entityName, Map entityMetadata) throws Exception; + /** + * Reports that a logical execution started at the given occurrence timestamp. + * + *

    The default implementation delegates to {@link #reportExecutionStarted(String, String, + * Map)}, so reporters that do not retain occurrence timestamps may use their observation time. + */ + default void reportExecutionStartedAt( + String entityType, + String entityName, + Map entityMetadata, + String timestamp) + throws Exception { + reportExecutionStarted(entityType, entityName, entityMetadata); + } + /** * Reports that a previously started logical execution completed successfully. * @@ -72,6 +87,21 @@ void reportExecutionSucceeded( String entityType, String entityName, Map entityMetadata) throws Exception; + /** + * Reports that a logical execution completed successfully at the given occurrence timestamp. + * + *

    The default implementation delegates to {@link #reportExecutionSucceeded(String, String, + * Map)}, so reporters that do not retain occurrence timestamps may use their observation time. + */ + default void reportExecutionSucceededAt( + String entityType, + String entityName, + Map entityMetadata, + String timestamp) + throws Exception { + reportExecutionSucceeded(entityType, entityName, entityMetadata); + } + /** * Reports that a logical execution failed. * @@ -85,4 +115,22 @@ void reportExecutionFailed( Throwable error, @Nullable String problemCategory) throws Exception; + + /** + * Reports that a logical execution failed at the given occurrence timestamp. + * + *

    The default implementation delegates to {@link #reportExecutionFailed(String, String, Map, + * Throwable, String)}, so reporters that do not retain occurrence timestamps may use their + * observation time. + */ + default void reportExecutionFailedAt( + String entityType, + String entityName, + Map entityMetadata, + Throwable error, + @Nullable String problemCategory, + String timestamp) + throws Exception { + reportExecutionFailed(entityType, entityName, entityMetadata, error, problemCategory); + } } diff --git a/api/src/main/java/org/apache/flink/agents/api/trace/ExecutionReporters.java b/api/src/main/java/org/apache/flink/agents/api/trace/ExecutionReporters.java index 87ca12445..4b5a12984 100644 --- a/api/src/main/java/org/apache/flink/agents/api/trace/ExecutionReporters.java +++ b/api/src/main/java/org/apache/flink/agents/api/trace/ExecutionReporters.java @@ -56,6 +56,20 @@ public static void started( null); } + public static void startedAt( + RunnerContext ctx, + String entityType, + String entityName, + Map entityMetadata, + String timestamp) { + report( + ctx, + reporter -> + reporter.reportExecutionStartedAt( + entityType, entityName, entityMetadata, timestamp), + null); + } + public static void succeeded(RunnerContext ctx, String entityType, String entityName) { succeeded(ctx, entityType, entityName, EMPTY_METADATA); } @@ -72,6 +86,20 @@ public static void succeeded( null); } + public static void succeededAt( + RunnerContext ctx, + String entityType, + String entityName, + Map entityMetadata, + String timestamp) { + report( + ctx, + reporter -> + reporter.reportExecutionSucceededAt( + entityType, entityName, entityMetadata, timestamp), + null); + } + public static void failed( RunnerContext ctx, String entityType, @@ -96,6 +124,27 @@ public static void failed( error); } + public static void failedAt( + RunnerContext ctx, + String entityType, + String entityName, + Map entityMetadata, + Throwable error, + @Nullable String problemCategory, + String timestamp) { + report( + ctx, + reporter -> + reporter.reportExecutionFailedAt( + entityType, + entityName, + entityMetadata, + error, + problemCategory, + timestamp), + error); + } + private static void report( RunnerContext ctx, ReporterCall reporterCall, @Nullable Throwable businessError) { if (ctx instanceof ExecutionReporter) { diff --git a/docs/content/docs/operations/monitoring.md b/docs/content/docs/operations/monitoring.md index 99d67466a..4fb422024 100644 --- a/docs/content/docs/operations/monitoring.md +++ b/docs/content/docs/operations/monitoring.md @@ -60,7 +60,7 @@ Input-run outcomes and all latency samples are process-local. Runs or Action exe #### Execution Metrics -Execution metrics are derived from LLM and Tool execution lifecycle events. The `model_resource`, `tool`, `skill`, and `mcp_server` scopes are independent key-value scopes directly under an Action; none is nested under another. The existing `model` scope remains dedicated to model usage metrics. +LLM and Tool outcome and latency metrics are derived from execution lifecycle Events. Each Tool callable records its own start and completion timestamps; its durable execution Outcome determines the reported result, including failures during result persistence. Events may be delivered after the parallel batch completes, but use each call's timestamps rather than the batch duration. Event publication is independent of response aggregation, so a later response-processing failure does not repeat or discard reports for calls with available Outcomes. The `model_resource`, `tool`, `skill`, and `mcp_server` scopes are independent key-value scopes directly under an Action; none is nested under another. The existing `model` scope remains dedicated to model usage metrics. | Scope | Metrics | Description | Type | |-------|---------|-------------|------| @@ -71,24 +71,26 @@ Execution metrics are derived from LLM and Tool execution lifecycle events. The | **Model Resource** | action.\.model_resource.\.retryWaitSec | The total backoff time, in seconds, accumulated when `ErrorHandlingStrategy.RETRY` is configured. Only recorded when at least one retry occurs. | Count | | **Tool** | action.\.tool.\.numOfToolCallsSucceeded | The number of successful calls to the Tool. | Count | | **Tool** | action.\.tool.\.numOfToolCallsFailed | The number of failed calls to the Tool. | Count | -| **Tool** | action.\.tool.\.toolCallLatencyMs | Tool call latency. | Histogram | +| **Tool** | action.\.tool.\.toolCallLatencyMs | Time spent invoking the individual Tool, excluding time waiting for other calls in the same parallel batch. | Histogram | | **Skill** | action.\.skill.\.numOfSkillLoads | The number of terminal explicit `load_skill` calls attributed to the Skill, regardless of outcome. | Count | -| **Skill** | action.\.skill.\.skillLoadLatencyMs | Latency of explicit `load_skill` calls. | Histogram | +| **Skill** | action.\.skill.\.skillLoadLatencyMs | Time spent invoking an explicit `load_skill` call. | Histogram | | **MCP Server** | action.\.mcp_server.\.numOfMcpToolCallsSucceeded | The number of successful Tool calls served by the MCP Server. | Count | | **MCP Server** | action.\.mcp_server.\.numOfMcpToolCallsFailed | The number of failed Tool calls served by the MCP Server. | Count | -| **MCP Server** | action.\.mcp_server.\.mcpToolCallLatencyMs | Tool call latency aggregated across the MCP Server. | Histogram | +| **MCP Server** | action.\.mcp_server.\.mcpToolCallLatencyMs | Individual Tool invocation latency aggregated across the MCP Server. | Histogram | An LLM metric represents one framework invocation of `ChatModel`. A framework retry that calls the model again produces another LLM outcome and latency sample; retries hidden inside a provider or connection are not observed. Every named Tool execution emits Tool metrics. Skill metrics are emitted only for explicit `load_skill` calls; subsequent Tool calls are not inferred to belong to a Skill. MCP metrics aggregate only Tool executions carrying an explicit MCP Server resource name. A `load_skill` or MCP Tool execution therefore contributes to both its Tool scope and the corresponding Skill or MCP Server scope. -Execution metrics currently inherit Agent Trace's durable-replay behavior. During fine-grained recovery, a cached durable LLM or Tool result is reported as a new successful execution because child cache reuse is not exposed to execution reporting. The corresponding success counter therefore increments and the latency histogram may receive a near-zero sample even though the underlying model or Tool was not invoked. Distinguishing reused child executions is follow-up work. +Execution metrics currently inherit Agent Trace's durable-replay behavior. During fine-grained recovery, a cached durable LLM or Tool result is reported as a new successful execution because child cache reuse is not exposed to execution reporting. The corresponding success counter therefore increments. A cached LLM result may produce a near-zero latency sample; a cached Tool result produces no latency sample because the Tool callable was not invoked and no execution duration was measured. Distinguishing reused child executions is follow-up work. Tool names that are not registered runtime resources are aggregated under the fixed `tool=unknown` scope. Requested Skill names that do not resolve in the runtime registry are similarly aggregated under `skill=unknown`. The original requested names remain available in Agent Trace records, while Metric scope cardinality remains bounded. -Tool outcomes follow the existing language-specific Tool contracts. In both Java and Python, resource preparation or invocation exceptions are failures and a normal return is successful. Java additionally treats an unsuccessful `ToolResponse` as a failed Tool execution. Python Tools return arbitrary values and currently have no equivalent explicit error-result type, so the runtime does not infer failure from a normally returned Python value. +Tool outcomes follow the existing language-specific Tool contracts. In both Java and Python, resource preparation, invocation, or durable result-persistence exceptions are failures. Java additionally treats an unsuccessful `ToolResponse` as a failed Tool execution. Python Tools return arbitrary values and currently have no equivalent explicit error-result type, so the runtime does not infer failure from a normally returned Python value when durable execution also succeeds. `numOfSkillLoads` counts terminal calls rather than successful loads. Under the current Tool contracts, a `load_skill` not-found response returns normally and is therefore observed as a successful Tool outcome. Consequently, Tool and MCP outcome metrics use the same names and scopes in both runtimes, but explicit error-result semantics are not yet identical. This alignment, including explicit failure results for framework Tools such as `load_skill`, is tracked in [Issue #956](https://github.com/apache/flink-agents/issues/956). -Execution latency tracking is process-local. A latency sample is recorded only when the execution start and terminal events are observed in the same task attempt; LLM and Tool terminal counters are still updated when a restored execution has no local start timestamp. +Execution latency tracking is process-local and uses the occurrence timestamps in matching start and terminal Events. Both Events must be observed in the same task attempt. A Tool latency sample additionally requires the Tool callable to run; queueing and parallel-batch fan-in are excluded. LLM and Tool terminal counters are still updated when no matching start Event is available. + +A request timeout does not necessarily stop a running Tool. ToolCallAction records when the durable call returns or raises, before processing responses or publishing Events. If a Tool has not finished by that time, its terminal Event uses this fixed observation time; a later Tool completion cannot extend it or produce another terminal Event. This excludes response-processing and Event-publication delays, but is not the execution framework's exact timeout-decision time: any delay before the durable result reaches the Action remains included. Cached results and failures before invocation retain terminal-only reporting, without an invocation latency sample. If a batch aborts without returning per-call Outcomes, known starts may be reported without terminal Events; individual results are not inferred from timestamps or the batch exception. These observation rules do not change the execution framework's timeout, failure, or durable-persistence behavior. In previous releases, `retryCount` and `retryWaitSec` used the `model.` scope. They now use `model_resource.` so retries are attributed to the configured ChatModel resource. Existing queries and dashboards for these two metrics must use the new scope. diff --git a/plan/src/main/java/org/apache/flink/agents/plan/actions/ToolCallAction.java b/plan/src/main/java/org/apache/flink/agents/plan/actions/ToolCallAction.java index a67571a8f..1861c7d18 100644 --- a/plan/src/main/java/org/apache/flink/agents/plan/actions/ToolCallAction.java +++ b/plan/src/main/java/org/apache/flink/agents/plan/actions/ToolCallAction.java @@ -42,6 +42,7 @@ import org.slf4j.Logger; import org.slf4j.LoggerFactory; +import java.time.Instant; import java.util.ArrayList; import java.util.HashMap; import java.util.LinkedHashMap; @@ -133,9 +134,6 @@ private static List buildToolCallExecutions( name, tool, metadataParameters); - ExecutionReporters.started( - ctx, ExecutionReporter.EntityTypes.TOOL, name, entityMetadata); - if (tool == null || preparationError != null) { Exception failure = preparationError != null @@ -169,6 +167,7 @@ private static List buildToolCallExecutions( final Tool toolRef = tool; final Map callArguments = mergedArguments; + ToolCallOccurrence occurrence = new ToolCallOccurrence(); DurableCallable callable = new DurableCallable<>() { @Override @@ -183,10 +182,15 @@ public Class getResultClass() { @Override public ToolResponse call() throws Exception { - return toolRef.call(new ToolParameters(callArguments)); + occurrence.markStarted(); + try { + return toolRef.call(new ToolParameters(callArguments)); + } finally { + occurrence.markFinished(); + } } }; - executions.add(new ToolCallExecution(id, name, callable, entityMetadata)); + executions.add(new ToolCallExecution(id, name, callable, entityMetadata, occurrence)); } return executions; } @@ -201,26 +205,29 @@ private static void executeParallel( for (ToolCallExecution execution : executions) { callables.add(execution.callable); } + List> outcomes = List.of(); + Instant resultObservedAt = null; try { - List> outcomes = ctx.durableExecuteAllAsync(callables); + outcomes = ctx.durableExecuteAllAsync(callables); + resultObservedAt = Instant.now(); for (int i = 0; i < outcomes.size(); i++) { - recordOutcome(executions.get(i), outcomes.get(i), ctx, success, error, responses); + recordOutcome(executions.get(i), outcomes.get(i), success, error, responses); } } catch (Exception e) { + if (resultObservedAt == null) { + resultObservedAt = Instant.now(); + } for (ToolCallExecution execution : executions) { recordExecutionException(execution, e, success, error, responses); } - } catch (Error e) { - for (ToolCallExecution execution : executions) { - ExecutionReporters.failed( + } finally { + for (int i = 0; i < executions.size(); i++) { + reportExecution( + executions.get(i), ctx, - ExecutionReporter.EntityTypes.TOOL, - execution.name, - execution.entityMetadata, - e, - ExecutionReporter.ProblemCategories.TOOL_CALL_FAILED); + i < outcomes.size() ? outcomes.get(i) : null, + resultObservedAt); } - throw e; } } @@ -232,45 +239,24 @@ private static void executeSequentially( Map error, Map responses) { for (ToolCallExecution execution : executions) { + Outcome outcome = null; + Instant resultObservedAt = null; try { ToolResponse response = toolCallAsync ? ctx.durableExecuteAsync(execution.callable) : ctx.durableExecute(execution.callable); + resultObservedAt = Instant.now(); + outcome = Outcome.success(response); recordToolResponse(execution.id, response, success, error, responses); - if (response.isError()) { - ExecutionReporters.failed( - ctx, - ExecutionReporter.EntityTypes.TOOL, - execution.name, - execution.entityMetadata, - new RuntimeException(response.getError()), - ExecutionReporter.ProblemCategories.TOOL_CALL_FAILED); - } else { - ExecutionReporters.succeeded( - ctx, - ExecutionReporter.EntityTypes.TOOL, - execution.name, - execution.entityMetadata); - } } catch (Exception e) { + if (resultObservedAt == null) { + resultObservedAt = Instant.now(); + } + outcome = Outcome.failure(e); recordExecutionException(execution, e, success, error, responses); - ExecutionReporters.failed( - ctx, - ExecutionReporter.EntityTypes.TOOL, - execution.name, - execution.entityMetadata, - e, - ExecutionReporter.ProblemCategories.TOOL_CALL_FAILED); - } catch (Error e) { - ExecutionReporters.failed( - ctx, - ExecutionReporter.EntityTypes.TOOL, - execution.name, - execution.entityMetadata, - e, - ExecutionReporter.ProblemCategories.TOOL_CALL_FAILED); - throw e; + } finally { + reportExecution(execution, ctx, outcome, resultObservedAt); } } } @@ -278,38 +264,65 @@ private static void executeSequentially( private static void recordOutcome( ToolCallExecution execution, Outcome outcome, - RunnerContext ctx, Map success, Map error, Map responses) { if (outcome.isFailure()) { recordExecutionException(execution, outcome.getError(), success, error, responses); - ExecutionReporters.failed( + } else { + recordToolResponse(execution.id, outcome.getValue(), success, error, responses); + } + } + + private static void reportExecution( + ToolCallExecution execution, + RunnerContext ctx, + Outcome outcome, + Instant resultObservedAt) { + Instant finishedAt = execution.occurrence.finishedAt; + Instant startedAt = execution.occurrence.startedAt; + if (startedAt != null) { + ExecutionReporters.startedAt( + ctx, + ExecutionReporter.EntityTypes.TOOL, + execution.name, + execution.entityMetadata, + startedAt.toString()); + } + if (outcome == null) { + return; + } + // A timed-out callable may finish after the Action already received its failure. + if (finishedAt == null || finishedAt.isAfter(resultObservedAt)) { + finishedAt = resultObservedAt; + } + Throwable failure = + outcome.isFailure() ? outcome.getError() : toolResponseFailure(outcome.getValue()); + + if (failure == null) { + ExecutionReporters.succeededAt( ctx, ExecutionReporter.EntityTypes.TOOL, execution.name, execution.entityMetadata, - outcome.getError(), - ExecutionReporter.ProblemCategories.TOOL_CALL_FAILED); + finishedAt.toString()); } else { - ToolResponse response = outcome.getValue(); - recordToolResponse(execution.id, response, success, error, responses); - if (response.isError()) { - ExecutionReporters.failed( - ctx, - ExecutionReporter.EntityTypes.TOOL, - execution.name, - execution.entityMetadata, - new RuntimeException(response.getError()), - ExecutionReporter.ProblemCategories.TOOL_CALL_FAILED); - } else { - ExecutionReporters.succeeded( - ctx, - ExecutionReporter.EntityTypes.TOOL, - execution.name, - execution.entityMetadata); - } + ExecutionReporters.failedAt( + ctx, + ExecutionReporter.EntityTypes.TOOL, + execution.name, + execution.entityMetadata, + failure, + ExecutionReporter.ProblemCategories.TOOL_CALL_FAILED, + finishedAt.toString()); + } + } + + private static Throwable toolResponseFailure(ToolResponse response) { + if (response == null) { + return new IllegalStateException("Tool returned a null response."); } + return response.isError() ? new RuntimeException(response.getError()) : null; } private static void recordInlineResponse( @@ -356,16 +369,32 @@ private static final class ToolCallExecution { private final String name; private final DurableCallable callable; private final Map entityMetadata; + private final ToolCallOccurrence occurrence; private ToolCallExecution( String id, String name, DurableCallable callable, - Map entityMetadata) { + Map entityMetadata, + ToolCallOccurrence occurrence) { this.id = id; this.name = name; this.callable = callable; this.entityMetadata = entityMetadata; + this.occurrence = occurrence; + } + } + + private static final class ToolCallOccurrence { + private volatile Instant startedAt; + private volatile Instant finishedAt; + + private void markStarted() { + startedAt = Instant.now(); + } + + private void markFinished() { + finishedAt = Instant.now(); } } diff --git a/plan/src/test/java/org/apache/flink/agents/plan/actions/ToolCallActionReportTest.java b/plan/src/test/java/org/apache/flink/agents/plan/actions/ToolCallActionReportTest.java index 08348327b..52ceb8bae 100644 --- a/plan/src/test/java/org/apache/flink/agents/plan/actions/ToolCallActionReportTest.java +++ b/plan/src/test/java/org/apache/flink/agents/plan/actions/ToolCallActionReportTest.java @@ -20,6 +20,7 @@ import org.apache.flink.agents.api.Event; import org.apache.flink.agents.api.agents.AgentExecutionOptions; import org.apache.flink.agents.api.context.DurableCallable; +import org.apache.flink.agents.api.context.Outcome; import org.apache.flink.agents.api.context.RunnerContext; import org.apache.flink.agents.api.event.ToolRequestEvent; import org.apache.flink.agents.api.event.ToolResponseEvent; @@ -33,18 +34,32 @@ import org.apache.flink.agents.api.trace.ExecutionReporter; import org.apache.flink.agents.api.trace.ToolExecutionMetadataKeys; import org.junit.jupiter.api.Test; +import org.junit.jupiter.params.ParameterizedTest; +import org.junit.jupiter.params.provider.ValueSource; +import org.mockito.ArgumentCaptor; +import java.time.Instant; import java.util.ArrayList; import java.util.LinkedHashMap; import java.util.List; import java.util.Map; +import java.util.concurrent.CountDownLatch; +import java.util.concurrent.ExecutorService; +import java.util.concurrent.Executors; +import java.util.concurrent.Future; +import java.util.concurrent.TimeUnit; +import java.util.concurrent.TimeoutException; +import java.util.concurrent.atomic.AtomicReference; import static org.assertj.core.api.Assertions.assertThat; import static org.mockito.ArgumentMatchers.any; +import static org.mockito.ArgumentMatchers.anyMap; +import static org.mockito.ArgumentMatchers.anyString; import static org.mockito.ArgumentMatchers.eq; import static org.mockito.Mockito.doAnswer; import static org.mockito.Mockito.mock; import static org.mockito.Mockito.never; +import static org.mockito.Mockito.times; import static org.mockito.Mockito.verify; import static org.mockito.Mockito.when; import static org.mockito.Mockito.withSettings; @@ -86,10 +101,22 @@ void processToolRequestReportsEachToolCall() throws Exception { metadata.put(ToolExecutionMetadataKeys.TOOL_TYPE, ToolType.MCP.getValue()); metadata.put(ToolExecutionMetadataKeys.MCP_SERVER, "search-server"); ExecutionReporter reporter = (ExecutionReporter) ctx; + ArgumentCaptor startedAt = ArgumentCaptor.forClass(String.class); + ArgumentCaptor finishedAt = ArgumentCaptor.forClass(String.class); verify(reporter) - .reportExecutionStarted(ExecutionReporter.EntityTypes.TOOL, "search", metadata); + .reportExecutionStartedAt( + eq(ExecutionReporter.EntityTypes.TOOL), + eq("search"), + eq(metadata), + startedAt.capture()); verify(reporter) - .reportExecutionSucceeded(ExecutionReporter.EntityTypes.TOOL, "search", metadata); + .reportExecutionSucceededAt( + eq(ExecutionReporter.EntityTypes.TOOL), + eq("search"), + eq(metadata), + finishedAt.capture()); + assertThat(Instant.parse(finishedAt.getValue())) + .isAfterOrEqualTo(Instant.parse(startedAt.getValue())); assertThat(sentEvents).hasSize(1); assertThat(sentEvents.get(0)).isInstanceOf(ToolResponseEvent.class); @@ -123,20 +150,409 @@ void processToolRequestMarksErrorResponseAsFailed() throws Exception { metadata.put(ToolExecutionMetadataKeys.TOOL_CALL_ID, "call-1"); ExecutionReporter reporter = (ExecutionReporter) ctx; verify(reporter) - .reportExecutionFailed( + .reportExecutionFailedAt( eq(ExecutionReporter.EntityTypes.TOOL), eq("search"), eq(metadata), any(Throwable.class), - eq(ExecutionReporter.ProblemCategories.TOOL_CALL_FAILED)); + eq(ExecutionReporter.ProblemCategories.TOOL_CALL_FAILED), + anyString()); verify(reporter, never()) - .reportExecutionSucceeded(ExecutionReporter.EntityTypes.TOOL, "search", metadata); + .reportExecutionSucceededAt(anyString(), anyString(), anyMap(), anyString()); ToolResponseEvent responseEvent = (ToolResponseEvent) sentEvents.get(0); assertThat(responseEvent.getSuccess()).containsEntry("call-1", false); assertThat(responseEvent.getError()).containsEntry("call-1", "tool rejected request"); } + @Test + void parallelToolCallsReportIndependentOutcomes() throws Exception { + RunnerContext ctx = + mock(RunnerContext.class, withSettings().extraInterfaces(ExecutionReporter.class)); + List sentEvents = new ArrayList<>(); + Tool tool = mock(Tool.class); + when(tool.call(any())) + .thenAnswer( + invocation -> { + String query = + invocation + .getArgument(0) + .getParameter("query", String.class); + if ("call-2".equals(query)) { + throw new IllegalStateException("call-2 failed"); + } + if ("call-3".equals(query)) { + return ToolResponse.error("call-3 rejected"); + } + return ToolResponse.success("ok"); + }); + when(ctx.getResource("search", ResourceType.TOOL)).thenReturn(tool); + when(ctx.getConfig()).thenReturn(toolCallConfig(true, 3)); + when(ctx.durableExecuteAllAsync(any())) + .thenAnswer( + invocation -> { + List> callables = + invocation.getArgument(0); + List> outcomes = new ArrayList<>(); + for (DurableCallable callable : callables) { + try { + outcomes.add(Outcome.success(callable.call())); + } catch (Exception e) { + outcomes.add(Outcome.failure(e)); + } + } + return outcomes; + }); + doAnswer(inv -> sentEvents.add(inv.getArgument(0))).when(ctx).sendEvent(any()); + + ToolCallAction.processToolRequest( + new ToolRequestEvent( + "test-model", + List.of(toolCall("call-1"), toolCall("call-2"), toolCall("call-3"))), + ctx); + + ExecutionReporter reporter = (ExecutionReporter) ctx; + verify(reporter, times(3)) + .reportExecutionStartedAt( + eq(ExecutionReporter.EntityTypes.TOOL), + eq("search"), + anyMap(), + anyString()); + verify(reporter) + .reportExecutionSucceededAt( + eq(ExecutionReporter.EntityTypes.TOOL), + eq("search"), + anyMap(), + anyString()); + verify(reporter, times(2)) + .reportExecutionFailedAt( + eq(ExecutionReporter.EntityTypes.TOOL), + eq("search"), + anyMap(), + any(Throwable.class), + eq(ExecutionReporter.ProblemCategories.TOOL_CALL_FAILED), + anyString()); + + ToolResponseEvent response = (ToolResponseEvent) sentEvents.get(0); + assertThat(response.getSuccess()) + .containsEntry("call-1", true) + .containsEntry("call-2", false) + .containsEntry("call-3", false); + assertThat(response.getError()) + .containsEntry("call-2", "call-2 failed") + .containsEntry("call-3", "call-3 rejected"); + } + + @Test + void responseProcessingFailureDoesNotRepeatCompletedOccurrences() throws Exception { + Tool tool = mock(Tool.class); + when(tool.call(any())) + .thenAnswer( + invocation -> + "call-2" + .equals( + invocation + .getArgument(0) + .getParameter( + "query", String.class)) + ? null + : ToolResponse.success("ok")); + RunnerContext ctx = parallelContext(tool); + + ToolCallAction.processToolRequest(parallelRequest(), ctx); + + assertReports( + ctx, + List.of("call-1", "call-2", "call-3"), + List.of("call-1", "call-3"), + List.of("call-2")); + assertBusinessResponsesFailed(ctx); + } + + @ParameterizedTest + @ValueSource(booleans = {false, true}) + void durableFailureIsReportedAsToolFailure(boolean async) throws Exception { + IllegalStateException failure = new IllegalStateException("persist failed"); + Tool tool = mock(Tool.class); + when(tool.call(any())).thenReturn(ToolResponse.success("ok")); + RunnerContext ctx = parallelContext(tool); + when(ctx.getConfig()).thenReturn(toolCallConfig(async, 1)); + when(ctx.durableExecute(any())) + .thenAnswer( + invocation -> { + invocation.>getArgument(0).call(); + throw failure; + }); + when(ctx.durableExecuteAsync(any())) + .thenAnswer( + invocation -> { + invocation.>getArgument(0).call(); + throw failure; + }); + + ToolCallAction.processToolRequest(parallelRequest(), ctx); + + assertReports( + ctx, + List.of("call-1", "call-2", "call-3"), + List.of(), + List.of("call-1", "call-2", "call-3")); + verify((ExecutionReporter) ctx, times(3)) + .reportExecutionFailedAt( + anyString(), anyString(), anyMap(), eq(failure), anyString(), anyString()); + assertBusinessResponsesFailed(ctx); + } + + @Test + void parallelDurableFailureIsReportedForItsToolCall() throws Exception { + IllegalStateException failure = new IllegalStateException("persist failed"); + Tool tool = mock(Tool.class); + when(tool.call(any())).thenReturn(ToolResponse.success("ok")); + RunnerContext ctx = parallelContext(tool); + doAnswer( + invocation -> { + List> callables = + invocation.getArgument(0); + List> outcomes = new ArrayList<>(); + for (DurableCallable callable : callables) { + outcomes.add(Outcome.success(callable.call())); + } + outcomes.set(1, Outcome.failure(failure)); + return outcomes; + }) + .when(ctx) + .durableExecuteAllAsync(any()); + + ToolCallAction.processToolRequest(parallelRequest(), ctx); + + assertReports( + ctx, + List.of("call-1", "call-2", "call-3"), + List.of("call-1", "call-3"), + List.of("call-2")); + verify((ExecutionReporter) ctx) + .reportExecutionFailedAt( + anyString(), anyString(), anyMap(), eq(failure), anyString(), anyString()); + ArgumentCaptor event = ArgumentCaptor.forClass(Event.class); + verify(ctx).sendEvent(event.capture()); + assertThat(((ToolResponseEvent) event.getValue()).getSuccess()) + .containsEntry("call-1", true) + .containsEntry("call-2", false) + .containsEntry("call-3", true); + } + + @Test + void timeoutIsReportedAsFailureWithoutRepeatingOnLateCompletion() throws Exception { + TimeoutException failure = new TimeoutException("request timed out"); + CountDownLatch started = new CountDownLatch(1); + CountDownLatch release = new CountDownLatch(1); + ExecutorService worker = Executors.newSingleThreadExecutor(); + AtomicReference> pending = new AtomicReference<>(); + AtomicReference reportingStartedAt = new AtomicReference<>(); + Tool tool = mock(Tool.class); + when(tool.call(any())) + .thenAnswer( + invocation -> { + started.countDown(); + assertThat(release.await(5, TimeUnit.SECONDS)).isTrue(); + return ToolResponse.success("ok"); + }); + RunnerContext ctx = parallelContext(tool); + when(ctx.getConfig()).thenReturn(toolCallConfig(true, 1)); + when(ctx.durableExecuteAsync(any())) + .thenAnswer( + invocation -> { + DurableCallable callable = invocation.getArgument(0); + pending.set(worker.submit(callable::call)); + assertThat(started.await(5, TimeUnit.SECONDS)).isTrue(); + throw failure; + }); + doAnswer( + invocation -> { + reportingStartedAt.set(Instant.now()); + return null; + }) + .when((ExecutionReporter) ctx) + .reportExecutionStartedAt(anyString(), anyString(), anyMap(), anyString()); + + try { + ToolCallAction.processToolRequest( + new ToolRequestEvent("test-model", List.of(toolCall("call-1"))), ctx); + assertReports(ctx, List.of("call-1"), List.of(), List.of("call-1")); + ArgumentCaptor finishedAt = ArgumentCaptor.forClass(String.class); + verify((ExecutionReporter) ctx) + .reportExecutionFailedAt( + anyString(), + anyString(), + anyMap(), + eq(failure), + anyString(), + finishedAt.capture()); + assertThat(Instant.parse(finishedAt.getValue())) + .isBeforeOrEqualTo(reportingStartedAt.get()); + assertBusinessResponsesFailed(ctx); + } finally { + release.countDown(); + worker.shutdown(); + assertThat(worker.awaitTermination(5, TimeUnit.SECONDS)).isTrue(); + } + assertThat(pending.get().get().isSuccess()).isTrue(); + assertReports(ctx, List.of("call-1"), List.of(), List.of("call-1")); + } + + @ParameterizedTest + @ValueSource(booleans = {false, true}) + void parallelTimeoutTimestampPrecedesResponseProcessingAndReporting( + boolean completeDuringReporting) throws Exception { + TimeoutException failure = new TimeoutException("batch timed out"); + CountDownLatch started = new CountDownLatch(2); + CountDownLatch release = new CountDownLatch(1); + ExecutorService workers = Executors.newFixedThreadPool(2); + List> pending = new ArrayList<>(); + AtomicReference responseProcessingStartedAt = new AtomicReference<>(); + ToolResponse firstResponse = mock(ToolResponse.class); + when(firstResponse.isSuccess()) + .thenAnswer( + invocation -> { + responseProcessingStartedAt.compareAndSet(null, Instant.now()); + return true; + }); + Tool tool = mock(Tool.class); + when(tool.call(any())) + .thenAnswer( + invocation -> { + ToolParameters parameters = invocation.getArgument(0); + if ("call-1".equals(parameters.getParameter("query"))) { + return firstResponse; + } + started.countDown(); + assertThat(release.await(5, TimeUnit.SECONDS)).isTrue(); + return ToolResponse.success("late result"); + }); + RunnerContext ctx = parallelContext(tool); + doAnswer( + invocation -> { + List> callables = + invocation.getArgument(0); + ToolResponse response = callables.get(0).call(); + pending.add(workers.submit(callables.get(1)::call)); + pending.add(workers.submit(callables.get(2)::call)); + assertThat(started.await(5, TimeUnit.SECONDS)).isTrue(); + return List.of( + Outcome.success(response), + Outcome.failure(failure), + Outcome.failure(failure)); + }) + .when(ctx) + .durableExecuteAllAsync(any()); + doAnswer( + invocation -> { + if (completeDuringReporting) { + release.countDown(); + for (Future future : pending) { + future.get(5, TimeUnit.SECONDS); + } + } + return null; + }) + .when((ExecutionReporter) ctx) + .reportExecutionStartedAt(anyString(), anyString(), anyMap(), anyString()); + + try { + ToolCallAction.processToolRequest(parallelRequest(), ctx); + ArgumentCaptor finishedAt = ArgumentCaptor.forClass(String.class); + verify((ExecutionReporter) ctx, times(2)) + .reportExecutionFailedAt( + anyString(), + anyString(), + anyMap(), + eq(failure), + anyString(), + finishedAt.capture()); + assertThat(finishedAt.getAllValues().get(0)) + .isEqualTo(finishedAt.getAllValues().get(1)); + assertThat(Instant.parse(finishedAt.getValue())) + .isBeforeOrEqualTo(responseProcessingStartedAt.get()); + } finally { + release.countDown(); + workers.shutdown(); + assertThat(workers.awaitTermination(5, TimeUnit.SECONDS)).isTrue(); + } + assertReports( + ctx, + List.of("call-1", "call-2", "call-3"), + List.of("call-1"), + List.of("call-2", "call-3")); + } + + private static RunnerContext parallelContext(Tool tool) throws Exception { + RunnerContext ctx = + mock(RunnerContext.class, withSettings().extraInterfaces(ExecutionReporter.class)); + when(ctx.getResource("search", ResourceType.TOOL)).thenReturn(tool); + when(ctx.getConfig()).thenReturn(toolCallConfig(true, 3)); + when(ctx.durableExecuteAllAsync(any())) + .thenAnswer( + invocation -> { + List> callables = + invocation.getArgument(0); + List> outcomes = new ArrayList<>(); + for (DurableCallable callable : callables) { + try { + outcomes.add(Outcome.success(callable.call())); + } catch (Exception e) { + outcomes.add(Outcome.failure(e)); + } + } + return outcomes; + }); + return ctx; + } + + private static ToolRequestEvent parallelRequest() { + return new ToolRequestEvent( + "test-model", List.of(toolCall("call-1"), toolCall("call-2"), toolCall("call-3"))); + } + + @SuppressWarnings({"rawtypes", "unchecked"}) + private static void assertReports( + RunnerContext ctx, List started, List succeeded, List failed) + throws Exception { + ExecutionReporter reporter = (ExecutionReporter) ctx; + ArgumentCaptor starts = ArgumentCaptor.forClass(Map.class); + ArgumentCaptor successes = ArgumentCaptor.forClass(Map.class); + ArgumentCaptor failures = ArgumentCaptor.forClass(Map.class); + verify(reporter, times(started.size())) + .reportExecutionStartedAt(anyString(), anyString(), starts.capture(), anyString()); + verify(reporter, times(succeeded.size())) + .reportExecutionSucceededAt( + anyString(), anyString(), successes.capture(), anyString()); + verify(reporter, times(failed.size())) + .reportExecutionFailedAt( + anyString(), + anyString(), + failures.capture(), + any(Throwable.class), + anyString(), + anyString()); + assertThat(starts.getAllValues()) + .extracting(m -> m.get(ToolExecutionMetadataKeys.TOOL_CALL_ID)) + .containsExactlyInAnyOrderElementsOf(started); + assertThat(successes.getAllValues()) + .extracting(m -> m.get(ToolExecutionMetadataKeys.TOOL_CALL_ID)) + .containsExactlyInAnyOrderElementsOf(succeeded); + assertThat(failures.getAllValues()) + .extracting(m -> m.get(ToolExecutionMetadataKeys.TOOL_CALL_ID)) + .containsExactlyInAnyOrderElementsOf(failed); + } + + private static void assertBusinessResponsesFailed(RunnerContext ctx) { + ArgumentCaptor event = ArgumentCaptor.forClass(Event.class); + verify(ctx).sendEvent(event.capture()); + assertThat(((ToolResponseEvent) event.getValue()).getSuccess().values()) + .isNotEmpty() + .containsOnly(false); + } + @Test void processLoadSkillToolRequestAddsSkillMetadata() throws Exception { RunnerContext ctx = @@ -148,7 +564,9 @@ void processLoadSkillToolRequestAddsSkillMetadata() throws Exception { ToolExecutionMetadataKeys.SKILL_NAME, "math-calculator", ToolExecutionMetadataKeys.SKILL_RESOURCE_PATH, - "README.md"), + "README.md", + ToolExecutionMetadataKeys.SKILL_REGISTERED, + true), ToolResponse.success("skill content")); when(ctx.getResource("load_skill", ResourceType.TOOL)).thenReturn(tool); when(ctx.getConfig()).thenReturn(toolCallConfig()); @@ -171,8 +589,43 @@ void processLoadSkillToolRequestAddsSkillMetadata() throws Exception { metadata.put(ToolExecutionMetadataKeys.TOOL_TYPE, ToolType.FUNCTION.getValue()); metadata.put(ToolExecutionMetadataKeys.SKILL_NAME, "math-calculator"); metadata.put(ToolExecutionMetadataKeys.SKILL_RESOURCE_PATH, "README.md"); + metadata.put(ToolExecutionMetadataKeys.SKILL_REGISTERED, true); verify((ExecutionReporter) ctx) - .reportExecutionStarted(ExecutionReporter.EntityTypes.TOOL, "load_skill", metadata); + .reportExecutionStartedAt( + eq(ExecutionReporter.EntityTypes.TOOL), + eq("load_skill"), + eq(metadata), + anyString()); + } + + @Test + void durableCacheHitDoesNotRecordToolCallLatency() throws Exception { + RunnerContext ctx = + mock(RunnerContext.class, withSettings().extraInterfaces(ExecutionReporter.class)); + Tool tool = mock(Tool.class); + when(ctx.getResource("search", ResourceType.TOOL)).thenReturn(tool); + when(ctx.getConfig()).thenReturn(toolCallConfig()); + when(ctx.durableExecute(any())).thenReturn(ToolResponse.success("cached")); + Map function = new LinkedHashMap<>(); + function.put("name", "search"); + function.put("arguments", Map.of("query", "flink")); + Map toolCall = new LinkedHashMap<>(); + toolCall.put("id", "call-1"); + toolCall.put("function", function); + + ToolCallAction.processToolRequest( + new ToolRequestEvent("test-model", List.of(toolCall)), ctx); + + verify(tool, never()).call(any()); + ExecutionReporter reporter = (ExecutionReporter) ctx; + verify(reporter, never()) + .reportExecutionStartedAt(anyString(), anyString(), anyMap(), anyString()); + verify(reporter) + .reportExecutionSucceededAt( + eq(ExecutionReporter.EntityTypes.TOOL), + eq("search"), + anyMap(), + anyString()); } @Test @@ -202,12 +655,20 @@ void executionMetadataCannotMutateToolCallParameters() throws Exception { private static org.apache.flink.agents.api.configuration.ReadableConfiguration toolCallConfig() { + return toolCallConfig(false, 1); + } + + private static org.apache.flink.agents.api.configuration.ReadableConfiguration toolCallConfig( + boolean async, int parallelism) { return new org.apache.flink.agents.api.configuration.ReadableConfiguration() { @Override @SuppressWarnings("unchecked") public T get(org.apache.flink.agents.api.configuration.ConfigOption option) { if (option == AgentExecutionOptions.TOOL_CALL_ASYNC) { - return (T) Boolean.FALSE; + return (T) Boolean.valueOf(async); + } + if (option == AgentExecutionOptions.TOOL_CALL_PARALLELISM) { + return (T) Integer.valueOf(parallelism); } return option.getDefaultValue(); } @@ -244,6 +705,16 @@ public String getStr(String key, String defaultValue) { }; } + private static Map toolCall(String id) { + Map function = new LinkedHashMap<>(); + function.put("name", "search"); + function.put("arguments", Map.of("query", id)); + Map toolCall = new LinkedHashMap<>(); + toolCall.put("id", id); + toolCall.put("function", function); + return toolCall; + } + private static final class ReportingTool extends Tool implements ToolExecutionMetadataProvider { private final ToolType toolType; private final Map entityMetadata; diff --git a/python/flink_agents/api/tests/test_execution_reporter.py b/python/flink_agents/api/tests/test_execution_reporter.py index a31810484..c67644b87 100644 --- a/python/flink_agents/api/tests/test_execution_reporter.py +++ b/python/flink_agents/api/tests/test_execution_reporter.py @@ -48,6 +48,57 @@ def test_failed_reporter_uses_metadata_before_error() -> None: ) +def test_timestamped_reporters_forward_occurrence_timestamps() -> None: + ctx = MagicMock(spec=ExecutionReporter) + metadata = {"toolCallId": "call-1"} + error = RuntimeError("boom") + + ExecutionReporters.started_at( + ctx, + ExecutionEntityTypes.TOOL, + "search", + metadata, + "2026-01-01T00:00:00.001Z", + ) + ExecutionReporters.succeeded_at( + ctx, + ExecutionEntityTypes.TOOL, + "search", + metadata, + "2026-01-01T00:00:00.025Z", + ) + ExecutionReporters.failed_at( + ctx, + ExecutionEntityTypes.TOOL, + "search", + metadata, + error, + ExecutionProblemCategories.TOOL_CALL_FAILED, + "2026-01-01T00:00:00.030Z", + ) + + ctx.report_execution_started_at.assert_called_once_with( + ExecutionEntityTypes.TOOL, + "search", + metadata, + "2026-01-01T00:00:00.001Z", + ) + ctx.report_execution_succeeded_at.assert_called_once_with( + ExecutionEntityTypes.TOOL, + "search", + metadata, + "2026-01-01T00:00:00.025Z", + ) + ctx.report_execution_failed_at.assert_called_once_with( + ExecutionEntityTypes.TOOL, + "search", + metadata, + error, + ExecutionProblemCategories.TOOL_CALL_FAILED, + "2026-01-01T00:00:00.030Z", + ) + + def test_reporters_ignore_context_without_execution_reporter() -> None: ctx = MagicMock() diff --git a/python/flink_agents/api/trace/execution_reporter.py b/python/flink_agents/api/trace/execution_reporter.py index 926f1ae39..e14109781 100644 --- a/python/flink_agents/api/trace/execution_reporter.py +++ b/python/flink_agents/api/trace/execution_reporter.py @@ -58,6 +58,16 @@ def report_execution_started( ) -> None: """Report that a logical execution started.""" + def report_execution_started_at( + self, + entity_type: str, + entity_name: str, + entity_metadata: Mapping[str, Any] | None, + timestamp: str, + ) -> None: + """Report that a logical execution started at an occurrence timestamp.""" + self.report_execution_started(entity_type, entity_name, entity_metadata) + @abstractmethod def report_execution_succeeded( self, @@ -67,6 +77,16 @@ def report_execution_succeeded( ) -> None: """Report that a logical execution completed successfully.""" + def report_execution_succeeded_at( + self, + entity_type: str, + entity_name: str, + entity_metadata: Mapping[str, Any] | None, + timestamp: str, + ) -> None: + """Report successful completion at an occurrence timestamp.""" + self.report_execution_succeeded(entity_type, entity_name, entity_metadata) + @abstractmethod def report_execution_failed( self, @@ -78,6 +98,24 @@ def report_execution_failed( ) -> None: """Report that a logical execution failed.""" + def report_execution_failed_at( + self, + entity_type: str, + entity_name: str, + entity_metadata: Mapping[str, Any] | None, + error: BaseException, + problem_category: str | None, + timestamp: str, + ) -> None: + """Report failed completion at an occurrence timestamp.""" + self.report_execution_failed( + entity_type, + entity_name, + entity_metadata, + error, + problem_category, + ) + class ExecutionReporters: """Best-effort helpers for contexts that implement ExecutionReporter.""" @@ -97,6 +135,25 @@ def started( ), ) + @staticmethod + def started_at( + ctx: "RunnerContext", + entity_type: str, + entity_name: str, + entity_metadata: Mapping[str, Any] | None, + timestamp: str, + ) -> None: + """Report a start occurrence if the context supports it.""" + ExecutionReporters._report( + ctx, + lambda reporter: reporter.report_execution_started_at( + entity_type, + entity_name, + entity_metadata or _EMPTY_METADATA, + timestamp, + ), + ) + @staticmethod def succeeded( ctx: "RunnerContext", @@ -112,6 +169,25 @@ def succeeded( ), ) + @staticmethod + def succeeded_at( + ctx: "RunnerContext", + entity_type: str, + entity_name: str, + entity_metadata: Mapping[str, Any] | None, + timestamp: str, + ) -> None: + """Report a successful occurrence if the context supports it.""" + ExecutionReporters._report( + ctx, + lambda reporter: reporter.report_execution_succeeded_at( + entity_type, + entity_name, + entity_metadata or _EMPTY_METADATA, + timestamp, + ), + ) + @staticmethod def failed( ctx: "RunnerContext", @@ -133,6 +209,29 @@ def failed( ), ) + @staticmethod + def failed_at( + ctx: "RunnerContext", + entity_type: str, + entity_name: str, + entity_metadata: Mapping[str, Any] | None, + error: BaseException, + problem_category: str | None, + timestamp: str, + ) -> None: + """Report a failed occurrence if the context supports it.""" + ExecutionReporters._report( + ctx, + lambda reporter: reporter.report_execution_failed_at( + entity_type, + entity_name, + entity_metadata or _EMPTY_METADATA, + error, + problem_category, + timestamp, + ), + ) + @staticmethod def _report( ctx: "RunnerContext", report: Callable[[ExecutionReporter], None] diff --git a/python/flink_agents/plan/actions/tool_call_action.py b/python/flink_agents/plan/actions/tool_call_action.py index c6b68b56c..92b6a3b65 100644 --- a/python/flink_agents/plan/actions/tool_call_action.py +++ b/python/flink_agents/plan/actions/tool_call_action.py @@ -16,7 +16,10 @@ # limitations under the License. ################################################################################# import logging +from collections.abc import Callable from dataclasses import dataclass +from datetime import datetime, timezone +from functools import wraps from typing import Any from flink_agents.api.core_options import AgentExecutionOptions @@ -78,12 +81,30 @@ def _tool_entity_metadata( return metadata +@dataclass +class _ToolCallOccurrence: + started_at: datetime | None = None + finished_at: datetime | None = None + + def wrap(self, func: Callable[..., Any]) -> Callable[..., Any]: + @wraps(func) + def observed_call(*args: Any, **kwargs: Any) -> Any: + self.started_at = datetime.now(timezone.utc) + try: + return func(*args, **kwargs) + finally: + self.finished_at = datetime.now(timezone.utc) + + return observed_call + + @dataclass(frozen=True) class _ToolCallExecution: id: str name: str durable_call: DurableCall entity_metadata: dict[str, Any] + occurrence: _ToolCallOccurrence async def process_tool_request(event: Event, ctx: RunnerContext) -> None: @@ -166,10 +187,6 @@ def _build_tool_call_executions( entity_metadata = _tool_entity_metadata( event.id, call_id, external_id, name, tool, call_kwargs ) - ExecutionReporters.started( - ctx, ExecutionEntityTypes.TOOL, name, entity_metadata - ) - if not tool or preparation_error is not None: failure = preparation_error or RuntimeError( f"Tool `{name}` does not exist." @@ -191,15 +208,17 @@ def _build_tool_call_executions( ) continue + occurrence = _ToolCallOccurrence() executions.append( _ToolCallExecution( id=call_id, name=name, durable_call=DurableCall( - func=tool.call, + func=occurrence.wrap(tool.call), kwargs=call_kwargs, ), entity_metadata=entity_metadata, + occurrence=occurrence, ) ) return executions @@ -212,15 +231,28 @@ async def _execute_parallel( success: dict, error: dict, ) -> None: + outcomes: list[Outcome] = [] + result_observed_at = None try: outcomes = await ctx.durable_execute_all_async( [execution.durable_call for execution in executions] ) + result_observed_at = datetime.now(timezone.utc) for execution, outcome in zip(executions, outcomes, strict=True): - _record_outcome(execution, outcome, ctx, responses, success, error) + _record_outcome(execution, outcome, responses, success, error) except Exception as e: + if result_observed_at is None: + result_observed_at = datetime.now(timezone.utc) for execution in executions: - _record_execution_exception(execution, e, ctx, responses, success, error) + _record_execution_exception(execution, e, responses, success, error) + finally: + for index, execution in enumerate(executions): + _report_execution( + execution, + ctx, + outcomes[index] if index < len(outcomes) else None, + result_observed_at, + ) async def _execute_sequentially( @@ -233,6 +265,8 @@ async def _execute_sequentially( error: dict, ) -> None: for execution in executions: + outcome = None + result_observed_at = None try: call = execution.durable_call if tool_call_async: @@ -247,45 +281,36 @@ async def _execute_sequentially( *call.args, **(call.kwargs or {}), ) + result_observed_at = datetime.now(timezone.utc) + outcome = Outcome.success(response) responses[execution.id] = response success[execution.id] = True - ExecutionReporters.succeeded( - ctx, - ExecutionEntityTypes.TOOL, - execution.name, - execution.entity_metadata, - ) - except Exception as e: # noqa: PERF203 - _record_execution_exception(execution, e, ctx, responses, success, error) + except Exception as e: + if result_observed_at is None: + result_observed_at = datetime.now(timezone.utc) + outcome = Outcome.failure(e) + _record_execution_exception(execution, e, responses, success, error) + finally: + _report_execution(execution, ctx, outcome, result_observed_at) def _record_outcome( execution: _ToolCallExecution, outcome: Outcome, - ctx: RunnerContext, responses: dict, success: dict, error: dict, ) -> None: if outcome.is_failure(): - _record_execution_exception( - execution, outcome.error, ctx, responses, success, error - ) + _record_execution_exception(execution, outcome.error, responses, success, error) else: responses[execution.id] = outcome.value success[execution.id] = True - ExecutionReporters.succeeded( - ctx, - ExecutionEntityTypes.TOOL, - execution.name, - execution.entity_metadata, - ) def _record_execution_exception( execution: _ToolCallExecution, exception: BaseException, - ctx: RunnerContext, responses: dict, success: dict, error: dict, @@ -293,14 +318,48 @@ def _record_execution_exception( responses[execution.id] = f"Tool `{execution.name}` execute failed." success[execution.id] = False error[execution.id] = str(exception) - ExecutionReporters.failed( - ctx, - ExecutionEntityTypes.TOOL, - execution.name, - execution.entity_metadata, - exception, - ExecutionProblemCategories.TOOL_CALL_FAILED, - ) + + +def _report_execution( + execution: _ToolCallExecution, + ctx: RunnerContext, + outcome: Outcome | None, + result_observed_at: datetime | None, +) -> None: + finished_at = execution.occurrence.finished_at + started_at = execution.occurrence.started_at + if started_at is not None: + ExecutionReporters.started_at( + ctx, + ExecutionEntityTypes.TOOL, + execution.name, + execution.entity_metadata, + started_at.isoformat().replace("+00:00", "Z"), + ) + if outcome is None: + return + # A timed-out callable may finish after the Action already received its failure. + if finished_at is None or finished_at > result_observed_at: + finished_at = result_observed_at + finished_timestamp = finished_at.isoformat().replace("+00:00", "Z") + if outcome.is_success(): + ExecutionReporters.succeeded_at( + ctx, + ExecutionEntityTypes.TOOL, + execution.name, + execution.entity_metadata, + finished_timestamp, + ) + else: + ExecutionReporters.failed_at( + ctx, + ExecutionEntityTypes.TOOL, + execution.name, + execution.entity_metadata, + outcome.error, + ExecutionProblemCategories.TOOL_CALL_FAILED, + finished_timestamp, + ) def _resolve_injected_arguments(tool: object, ctx: RunnerContext) -> dict: diff --git a/python/flink_agents/plan/tests/actions/test_tool_call_action.py b/python/flink_agents/plan/tests/actions/test_tool_call_action.py index cc25d2438..a14c9b999 100644 --- a/python/flink_agents/plan/tests/actions/test_tool_call_action.py +++ b/python/flink_agents/plan/tests/actions/test_tool_call_action.py @@ -16,8 +16,13 @@ # limitations under the License. ################################################################################# import asyncio +import threading +from concurrent.futures import ThreadPoolExecutor +from datetime import datetime, timedelta, timezone from typing import Any -from unittest.mock import MagicMock +from unittest.mock import MagicMock, patch + +import pytest from flink_agents.api.core_options import AgentExecutionOptions from flink_agents.api.events.tool_event import ToolRequestEvent, ToolResponseEvent @@ -32,6 +37,7 @@ ExecutionReporter, ToolExecutionMetadataKeys, ) +from flink_agents.plan.actions import tool_call_action from flink_agents.plan.actions.tool_call_action import process_tool_request from flink_agents.plan.configuration import AgentConfiguration from flink_agents.plan.function import PythonFunction @@ -365,6 +371,356 @@ def test_tool_call_action_uses_parallel_batch_for_multiple_tools() -> None: assert ctx.durable_execute_async_calls == [] +def test_parallel_tool_calls_report_independent_occurrences() -> None: + config = AgentConfiguration({"tenant_id": "tenant-1"}) + config.set(AgentExecutionOptions.TOOL_CALL_ASYNC, True) + config.set(AgentExecutionOptions.TOOL_CALL_PARALLELISM, 4) + tool = MagicMock() + tool.tool_type.return_value = ToolType.FUNCTION + + def call_tool(**kwargs: Any) -> str: + query = kwargs["query"] + if query != "call-1": + message = f"{query} failed" + raise RuntimeError(message) + return "ok" + + tool.call = MagicMock(side_effect=call_tool) + ctx = MagicMock(spec=ExecutionReporter) + ctx.config = config + ctx.get_resource = MagicMock(return_value=tool) + sent_events = [] + ctx.send_event = MagicMock(side_effect=sent_events.append) + + async def execute_all(callables: list[Any]) -> list[Outcome]: + outcomes = [] + for durable_call in callables: + try: + outcomes.append( + Outcome.success( + durable_call.func( + *durable_call.args, **(durable_call.kwargs or {}) + ) + ) + ) + except Exception as error: # noqa: PERF203 + outcomes.append(Outcome.failure(error)) + return outcomes + + ctx.durable_execute_all_async = execute_all + + request = ToolRequestEvent( + model="model-a", + tool_calls=[ + { + "id": call_id, + "function": { + "name": "search", + "arguments": {"query": call_id}, + }, + } + for call_id in ("call-1", "call-2", "call-3") + ], + ) + + asyncio.run(process_tool_request(request, ctx)) + + assert ctx.report_execution_started_at.call_count == 3 + assert ctx.report_execution_succeeded_at.call_count == 1 + assert ctx.report_execution_failed_at.call_count == 2 + terminal_call_ids = { + report.args[2][ToolExecutionMetadataKeys.TOOL_CALL_ID] + for report in ( + ctx.report_execution_succeeded_at.call_args_list + + ctx.report_execution_failed_at.call_args_list + ) + } + assert terminal_call_ids == {"call-1", "call-2", "call-3"} + + response = ToolResponseEvent.from_event(sent_events[0]) + assert response.success == { + "call-1": True, + "call-2": False, + "call-3": False, + } + assert response.error == { + "call-2": "call-2 failed", + "call-3": "call-3 failed", + } + + +def test_response_processing_failure_does_not_repeat_occurrences() -> None: + tool = MagicMock() + tool.tool_type.return_value = ToolType.FUNCTION + tool.call.return_value = "ok" + ctx, sent_events = trace_context(tool) + ctx.config = AgentConfiguration({}) + ctx.config.set(AgentExecutionOptions.TOOL_CALL_ASYNC, True) + ctx.config.set(AgentExecutionOptions.TOOL_CALL_PARALLELISM, 3) + + async def execute_all(callables: list[Any]) -> list[Outcome]: + return [ + Outcome.success(call.func(*call.args, **(call.kwargs or {}))) + for call in callables + ] + + ctx.durable_execute_all_async = execute_all + with patch( + "flink_agents.plan.actions.tool_call_action._record_outcome", + side_effect=[None, RuntimeError("response processing failed")], + ): + asyncio.run(process_tool_request(parallel_trace_request(), ctx)) + + assert_occurrence_reports( + ctx, ["call-1", "call-2", "call-3"], ["call-1", "call-2", "call-3"], [] + ) + assert sent_events[0].success == dict.fromkeys( + ["call-1", "call-2", "call-3"], False + ) + + +@pytest.mark.parametrize("mode", ["sync", "serial_async", "parallel"]) +def test_durable_failure_is_reported_as_tool_failure(mode: str) -> None: + failure = RuntimeError("persist failed") + tool = MagicMock() + tool.tool_type.return_value = ToolType.FUNCTION + tool.call.return_value = "ok" + ctx, sent_events = trace_context(tool) + ctx.config = AgentConfiguration({}) + ctx.config.set(AgentExecutionOptions.TOOL_CALL_ASYNC, mode != "sync") + ctx.config.set( + AgentExecutionOptions.TOOL_CALL_PARALLELISM, 3 if mode == "parallel" else 1 + ) + + def execute(func: Any, **kwargs: Any) -> Any: + func(**kwargs) + raise failure + + async def execute_async(func: Any, **kwargs: Any) -> Any: + return execute(func, **kwargs) + + async def execute_all(callables: list[Any]) -> list[Outcome]: + outcomes = [] + for call in callables: + result = call.func(*call.args, **(call.kwargs or {})) + outcomes.append( + Outcome.failure(failure) + if call.kwargs["query"] == "call-2" + else Outcome.success(result) + ) + return outcomes + + ctx.durable_execute = execute + ctx.durable_execute_async = execute_async + ctx.durable_execute_all_async = execute_all + + asyncio.run(process_tool_request(parallel_trace_request(), ctx)) + + assert_occurrence_reports( + ctx, + ["call-1", "call-2", "call-3"], + ["call-1", "call-3"] if mode == "parallel" else [], + ["call-2"] if mode == "parallel" else ["call-1", "call-2", "call-3"], + ) + assert all( + call.args[3] is failure + for call in ctx.report_execution_failed_at.call_args_list + ) + assert sent_events[0].success["call-2"] is False + assert sent_events[0].error["call-2"] == "persist failed" + + +def test_timeout_reports_failure_without_repeating_on_late_completion() -> None: + failure = TimeoutError("request timed out") + started = threading.Event() + release = threading.Event() + tool = MagicMock() + tool.tool_type.return_value = ToolType.FUNCTION + + def call_tool(**kwargs: Any) -> str: + started.set() + assert release.wait(5) + return "ok" + + tool.call.side_effect = call_tool + ctx, sent_events = trace_context(tool) + ctx.config = AgentConfiguration({}) + ctx.config.set(AgentExecutionOptions.TOOL_CALL_ASYNC, True) + ctx.config.set(AgentExecutionOptions.TOOL_CALL_PARALLELISM, 1) + worker = ThreadPoolExecutor(max_workers=1) + pending = [] + reporting_started_at = [] + ctx.report_execution_started_at.side_effect = ( + lambda *args: reporting_started_at.append(datetime.now(timezone.utc)) + ) + + async def execute_async(func: Any, **kwargs: Any) -> Any: + pending.append(worker.submit(func, **kwargs)) + assert started.wait(5) + raise failure + + ctx.durable_execute_async = execute_async + try: + asyncio.run( + process_tool_request( + ToolRequestEvent(model="model-a", tool_calls=[trace_tool_call()]), ctx + ) + ) + assert_occurrence_reports(ctx, ["call-1"], [], ["call-1"]) + assert ctx.report_execution_failed_at.call_args.args[3] is failure + finished_at = ctx.report_execution_failed_at.call_args.args[-1] + assert ( + datetime.fromisoformat(finished_at.replace("Z", "+00:00")) + <= (reporting_started_at[0]) + ) + assert sent_events[0].success["call-1"] is False + finally: + release.set() + worker.shutdown(wait=True) + + assert pending[0].result() == "ok" + assert_occurrence_reports(ctx, ["call-1"], [], ["call-1"]) + + +@pytest.mark.parametrize("complete_during_reporting", [False, True]) +def test_parallel_timeout_timestamp_precedes_response_processing_and_reporting( + complete_during_reporting: bool, +) -> None: + failure = TimeoutError("batch timed out") + release = threading.Event() + started = {call_id: threading.Event() for call_id in ("call-2", "call-3")} + base = datetime(2026, 1, 1, tzinfo=timezone.utc) + clock = [base] + observed_at = base + timedelta(seconds=1) + tool = MagicMock() + tool.tool_type.return_value = ToolType.FUNCTION + + def call_tool(**kwargs: Any) -> str: + call_id = kwargs["query"] + if call_id != "call-1": + started[call_id].set() + assert release.wait(5) + return "ok" + + tool.call.side_effect = call_tool + ctx, sent_events = trace_context(tool) + ctx.config = AgentConfiguration({}) + ctx.config.set(AgentExecutionOptions.TOOL_CALL_ASYNC, True) + ctx.config.set(AgentExecutionOptions.TOOL_CALL_PARALLELISM, 3) + pending = [] + record_outcome = tool_call_action._record_outcome + + def process_response(*args: Any) -> None: + clock[0] = base + timedelta(seconds=2) + record_outcome(*args) + + def report_started(*args: Any) -> None: + clock[0] = base + timedelta(seconds=3) + if complete_during_reporting: + release.set() + for future in pending: + future.result(timeout=5) + + ctx.report_execution_started_at.side_effect = report_started + with ( + ThreadPoolExecutor(max_workers=2) as workers, + patch.object(tool_call_action, "datetime") as datetime_mock, + patch.object(tool_call_action, "_record_outcome", side_effect=process_response), + ): + datetime_mock.now.side_effect = lambda tz: clock[0] + + async def execute_all(callables: list[Any]) -> list[Outcome]: + first = callables[0] + result = first.func(*first.args, **(first.kwargs or {})) + pending.extend( + workers.submit(call.func, *call.args, **(call.kwargs or {})) + for call in callables[1:] + ) + assert all(event.wait(5) for event in started.values()) + clock[0] = observed_at + return [ + Outcome.success(result), + Outcome.failure(failure), + Outcome.failure(failure), + ] + + ctx.durable_execute_all_async = execute_all + try: + asyncio.run(process_tool_request(parallel_trace_request(), ctx)) + timestamps = [ + call.args[-1] for call in ctx.report_execution_failed_at.call_args_list + ] + assert timestamps == ["2026-01-01T00:00:01Z"] * 2 + assert sent_events[0].success == { + "call-1": True, + "call-2": False, + "call-3": False, + } + finally: + release.set() + for future in pending: + future.result(timeout=5) + + assert_occurrence_reports( + ctx, ["call-1", "call-2", "call-3"], ["call-1"], ["call-2", "call-3"] + ) + + +def test_partial_cache_replay_only_reports_start_for_invoked_tool() -> None: + tool = MagicMock() + tool.tool_type.return_value = ToolType.FUNCTION + tool.call.return_value = "ok" + ctx, sent_events = trace_context(tool) + ctx.config = AgentConfiguration({}) + ctx.config.set(AgentExecutionOptions.TOOL_CALL_ASYNC, True) + ctx.config.set(AgentExecutionOptions.TOOL_CALL_PARALLELISM, 3) + + async def execute_all(callables: list[Any]) -> list[Outcome]: + call = callables[1] + result = call.func(*call.args, **(call.kwargs or {})) + return [ + Outcome.success("cached"), + Outcome.success(result), + Outcome.success("cached"), + ] + + ctx.durable_execute_all_async = execute_all + + asyncio.run(process_tool_request(parallel_trace_request(), ctx)) + + assert_occurrence_reports(ctx, ["call-2"], ["call-1", "call-2", "call-3"], []) + assert all(sent_events[0].success.values()) + tool.call.assert_called_once() + + +def parallel_trace_request() -> ToolRequestEvent: + return ToolRequestEvent( + model="model-a", + tool_calls=[ + { + "id": call_id, + "function": {"name": "search", "arguments": {"query": call_id}}, + } + for call_id in ("call-1", "call-2", "call-3") + ], + ) + + +def assert_occurrence_reports( + ctx: MagicMock, started: list[str], succeeded: list[str], failed: list[str] +) -> None: + for method, expected in ( + (ctx.report_execution_started_at, started), + (ctx.report_execution_succeeded_at, succeeded), + (ctx.report_execution_failed_at, failed), + ): + actual = [ + call.args[2][ToolExecutionMetadataKeys.TOOL_CALL_ID] + for call in method.call_args_list + ] + assert sorted(actual) == sorted(expected) + + def test_tool_call_action_uses_serial_async_when_parallelism_is_one() -> None: config = AgentConfiguration({"tenant_id": "tenant-1"}) config.set(AgentExecutionOptions.TOOL_CALL_ASYNC, True) @@ -517,13 +873,16 @@ def test_tool_call_reports_started_and_succeeded() -> None: ToolExecutionMetadataKeys.EXTERNAL_ID: "external-call-1", ToolExecutionMetadataKeys.TOOL_TYPE: "function", } - ctx.report_execution_started.assert_called_once_with( - ExecutionEntityTypes.TOOL, "search", metadata + ctx.report_execution_started_at.assert_called_once() + started_args = ctx.report_execution_started_at.call_args.args + assert started_args[:3] == (ExecutionEntityTypes.TOOL, "search", metadata) + ctx.report_execution_succeeded_at.assert_called_once() + succeeded_args = ctx.report_execution_succeeded_at.call_args.args + assert succeeded_args[:3] == (ExecutionEntityTypes.TOOL, "search", metadata) + assert datetime.fromisoformat(succeeded_args[3].replace("Z", "+00:00")) >= ( + datetime.fromisoformat(started_args[3].replace("Z", "+00:00")) ) - ctx.report_execution_succeeded.assert_called_once_with( - ExecutionEntityTypes.TOOL, "search", metadata - ) - ctx.report_execution_failed.assert_not_called() + ctx.report_execution_failed_at.assert_not_called() def test_tool_call_reports_failed() -> None: @@ -535,13 +894,14 @@ def test_tool_call_reports_failed() -> None: asyncio.run(process_tool_request(request, ctx)) - ctx.report_execution_failed.assert_called_once() - args = ctx.report_execution_failed.call_args.args + ctx.report_execution_failed_at.assert_called_once() + args = ctx.report_execution_failed_at.call_args.args assert args[0] == ExecutionEntityTypes.TOOL assert args[1] == "search" assert args[2][ToolExecutionMetadataKeys.TOOL_CALL_ID] == "call-1" assert isinstance(args[3], RuntimeError) assert args[4] == ExecutionProblemCategories.TOOL_CALL_FAILED + assert datetime.fromisoformat(args[5].replace("Z", "+00:00")) def test_tool_call_includes_provider_metadata() -> None: @@ -564,10 +924,59 @@ def get_tool_execution_metadata( asyncio.run(process_tool_request(request, ctx)) - metadata = ctx.report_execution_started.call_args.args[2] + metadata = ctx.report_execution_started_at.call_args.args[2] assert metadata[ToolExecutionMetadataKeys.MCP_SERVER] == "search_server" +def test_tool_call_reports_registered_skill_metadata() -> None: + class SkillTool(ToolExecutionMetadataProvider): + @staticmethod + def tool_type() -> ToolType: + return ToolType.FUNCTION + + @staticmethod + def call(**kwargs: object) -> str: + return "skill content" + + def get_tool_execution_metadata( + self, parameters: dict[str, object] + ) -> dict[str, object]: + return { + ToolExecutionMetadataKeys.SKILL_NAME: "calculator", + ToolExecutionMetadataKeys.SKILL_REGISTERED: True, + } + + ctx, _ = trace_context(SkillTool()) + + asyncio.run( + process_tool_request( + ToolRequestEvent(model="model-a", tool_calls=[trace_tool_call()]), ctx + ) + ) + + metadata = ctx.report_execution_started_at.call_args.args[2] + assert metadata[ToolExecutionMetadataKeys.SKILL_NAME] == "calculator" + assert metadata[ToolExecutionMetadataKeys.SKILL_REGISTERED] is True + + +def test_durable_cache_hit_does_not_record_tool_call_latency() -> None: + tool = MagicMock() + tool.tool_type.return_value = ToolType.FUNCTION + tool.call = MagicMock(return_value="uncached") + ctx, _ = trace_context(tool) + ctx.durable_execute = MagicMock(return_value="cached") + + asyncio.run( + process_tool_request( + ToolRequestEvent(model="model-a", tool_calls=[trace_tool_call()]), ctx + ) + ) + + tool.call.assert_not_called() + ctx.report_execution_started_at.assert_not_called() + ctx.report_execution_succeeded_at.assert_called_once() + + def test_tool_execution_metadata_cannot_mutate_call_arguments() -> None: class MutatingMetadataTool(ToolExecutionMetadataProvider): @staticmethod diff --git a/python/flink_agents/runtime/flink_runner_context.py b/python/flink_agents/runtime/flink_runner_context.py index 284b3c6eb..41cb5b724 100644 --- a/python/flink_agents/runtime/flink_runner_context.py +++ b/python/flink_agents/runtime/flink_runner_context.py @@ -625,6 +625,21 @@ def report_execution_started( self._entity_metadata_json(entity_metadata), ) + @override + def report_execution_started_at( + self, + entity_type: str, + entity_name: str, + entity_metadata: Mapping[str, Any] | None, + timestamp: str, + ) -> None: + self._j_runner_context.reportExecutionStartedAtJson( + entity_type, + entity_name, + self._entity_metadata_json(entity_metadata), + timestamp, + ) + @override def report_execution_succeeded( self, @@ -638,6 +653,21 @@ def report_execution_succeeded( self._entity_metadata_json(entity_metadata), ) + @override + def report_execution_succeeded_at( + self, + entity_type: str, + entity_name: str, + entity_metadata: Mapping[str, Any] | None, + timestamp: str, + ) -> None: + self._j_runner_context.reportExecutionSucceededAtJson( + entity_type, + entity_name, + self._entity_metadata_json(entity_metadata), + timestamp, + ) + @override def report_execution_failed( self, @@ -658,6 +688,28 @@ def report_execution_failed( problem_category, ) + @override + def report_execution_failed_at( + self, + entity_type: str, + entity_name: str, + entity_metadata: Mapping[str, Any] | None, + error: BaseException, + problem_category: str | None, + timestamp: str, + ) -> None: + root_error = _root_cause(error) + error_message = str(root_error) + self._j_runner_context.reportExecutionFailedAtJson( + entity_type, + entity_name, + self._entity_metadata_json(entity_metadata), + _error_type(root_error), + error_message or None, + problem_category, + timestamp, + ) + @staticmethod def _entity_metadata_json(entity_metadata: Mapping[str, Any] | None) -> str: return json.dumps(dict(entity_metadata or {})) diff --git a/python/flink_agents/runtime/tests/test_flink_runner_context_trace.py b/python/flink_agents/runtime/tests/test_flink_runner_context_trace.py index 083a3ef73..eab9bf7fc 100644 --- a/python/flink_agents/runtime/tests/test_flink_runner_context_trace.py +++ b/python/flink_agents/runtime/tests/test_flink_runner_context_trace.py @@ -30,6 +30,38 @@ def test_flink_runner_context_is_execution_reporter() -> None: assert issubclass(FlinkRunnerContext, ExecutionReporter) +def test_timestamped_execution_reports_forward_to_java_context() -> None: + java_context = MagicMock() + ctx = FlinkRunnerContext.__new__(FlinkRunnerContext) + ctx._j_runner_context = java_context + + ctx.report_execution_started_at( + ExecutionEntityTypes.TOOL, + "search", + {"toolCallId": "call-1"}, + "2026-01-01T00:00:00.001Z", + ) + ctx.report_execution_succeeded_at( + ExecutionEntityTypes.TOOL, + "search", + {"toolCallId": "call-1"}, + "2026-01-01T00:00:00.025Z", + ) + + java_context.reportExecutionStartedAtJson.assert_called_once_with( + ExecutionEntityTypes.TOOL, + "search", + '{"toolCallId": "call-1"}', + "2026-01-01T00:00:00.001Z", + ) + java_context.reportExecutionSucceededAtJson.assert_called_once_with( + ExecutionEntityTypes.TOOL, + "search", + '{"toolCallId": "call-1"}', + "2026-01-01T00:00:00.025Z", + ) + + def test_failed_execution_reports_deepest_explicit_cause() -> None: java_context = MagicMock() ctx = FlinkRunnerContext.__new__(FlinkRunnerContext) diff --git a/runtime/src/main/java/org/apache/flink/agents/runtime/context/RunnerContextImpl.java b/runtime/src/main/java/org/apache/flink/agents/runtime/context/RunnerContextImpl.java index dcfc34ed0..a4e248d95 100644 --- a/runtime/src/main/java/org/apache/flink/agents/runtime/context/RunnerContextImpl.java +++ b/runtime/src/main/java/org/apache/flink/agents/runtime/context/RunnerContextImpl.java @@ -22,6 +22,7 @@ import com.fasterxml.jackson.databind.ObjectMapper; import com.fasterxml.jackson.datatype.jsr310.JavaTimeModule; import org.apache.flink.agents.api.Event; +import org.apache.flink.agents.api.EventContext; import org.apache.flink.agents.api.configuration.ReadableConfiguration; import org.apache.flink.agents.api.context.DurableCallable; import org.apache.flink.agents.api.context.MemoryObject; @@ -378,6 +379,22 @@ public void reportExecutionStarted( ExecutionLifecycleEvents.executionStarted()); } + @Override + public void reportExecutionStartedAt( + String entityType, + String entityName, + Map entityMetadata, + String timestamp) + throws Exception { + Event event = ExecutionLifecycleEvents.executionStarted(); + reportChildExecution( + entityType, + entityName, + entityMetadata, + new EventContext(event.getType(), timestamp), + event); + } + @Override public void reportExecutionSucceeded( String entityType, String entityName, Map entityMetadata) @@ -389,6 +406,22 @@ public void reportExecutionSucceeded( ExecutionLifecycleEvents.executionFinished()); } + @Override + public void reportExecutionSucceededAt( + String entityType, + String entityName, + Map entityMetadata, + String timestamp) + throws Exception { + Event event = ExecutionLifecycleEvents.executionFinished(); + reportChildExecution( + entityType, + entityName, + entityMetadata, + new EventContext(event.getType(), timestamp), + event); + } + @Override public void reportExecutionFailed( String entityType, @@ -404,8 +437,36 @@ public void reportExecutionFailed( ExecutionLifecycleEvents.executionFailed(error, problemCategory)); } + @Override + public void reportExecutionFailedAt( + String entityType, + String entityName, + Map entityMetadata, + Throwable error, + @Nullable String problemCategory, + String timestamp) + throws Exception { + Event event = ExecutionLifecycleEvents.executionFailed(error, problemCategory); + reportChildExecution( + entityType, + entityName, + entityMetadata, + new EventContext(event.getType(), timestamp), + event); + } + protected void reportChildExecution( String entityType, String entityName, Map entityMetadata, Event event) { + reportChildExecution( + entityType, entityName, entityMetadata, new EventContext(event), event); + } + + protected void reportChildExecution( + String entityType, + String entityName, + Map entityMetadata, + EventContext eventContext, + Event event) { mailboxThreadChecker.run(); if (actionTraceContext == null || executionEventSink == null @@ -439,7 +500,7 @@ protected void reportChildExecution( } } - executionEventSink.emit(event, reportTraceContext); + executionEventSink.emit(eventContext, event, reportTraceContext); } @Override diff --git a/runtime/src/main/java/org/apache/flink/agents/runtime/eventlog/EventLogWriter.java b/runtime/src/main/java/org/apache/flink/agents/runtime/eventlog/EventLogWriter.java index abffc76d1..2ef843534 100644 --- a/runtime/src/main/java/org/apache/flink/agents/runtime/eventlog/EventLogWriter.java +++ b/runtime/src/main/java/org/apache/flink/agents/runtime/eventlog/EventLogWriter.java @@ -99,10 +99,16 @@ public void appendBusinessEventAndFlush( /** Appends and flushes an execution lifecycle Event when Trace recording is enabled. */ public void appendExecutionEventAndFlush(Event event, ExecutionTraceContext traceContext) { + appendExecutionEventAndFlush(new EventContext(event), event, traceContext); + } + + /** Appends and flushes an execution lifecycle Event with its occurrence context. */ + public void appendExecutionEventAndFlush( + EventContext eventContext, Event event, ExecutionTraceContext traceContext) { if (!traceEnabled) { return; } - appendAndFlush(new EventContext(event), event, traceContext); + appendAndFlush(eventContext, event, traceContext); } private void appendAndFlush( diff --git a/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetrics.java b/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetrics.java index b80899f88..4bb0378e7 100644 --- a/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetrics.java +++ b/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetrics.java @@ -19,29 +19,27 @@ package org.apache.flink.agents.runtime.metrics; import org.apache.flink.agents.api.Event; +import org.apache.flink.agents.api.EventContext; import org.apache.flink.agents.api.trace.ExecutionLifecycleEvents; import org.apache.flink.agents.api.trace.ExecutionTraceContext; +import java.time.Duration; +import java.time.Instant; +import java.time.format.DateTimeParseException; import java.util.HashMap; import java.util.Map; -import java.util.concurrent.TimeUnit; -import java.util.function.LongSupplier; import java.util.function.Predicate; /** Derives built-in LLM and Tool metrics from execution lifecycle events. */ final class BuiltInExecutionMetrics { private final FlinkAgentsMetricGroupImpl agentMetricGroup; - private final LongSupplier nanoTime; private final Map metricRecordersByEntityType; - private final Map> startNanosByActionExecutionId = new HashMap<>(); + private final Map> startTimesByActionExecutionId = new HashMap<>(); BuiltInExecutionMetrics( - FlinkAgentsMetricGroupImpl agentMetricGroup, - LongSupplier nanoTime, - Predicate isRegisteredTool) { + FlinkAgentsMetricGroupImpl agentMetricGroup, Predicate isRegisteredTool) { this.agentMetricGroup = agentMetricGroup; - this.nanoTime = nanoTime; ExecutionMetricRecorder llmMetricRecorder = new LlmExecutionMetricRecorder(); ExecutionMetricRecorder toolMetricRecorder = new ToolExecutionMetricRecorder(isRegisteredTool); @@ -54,7 +52,10 @@ final class BuiltInExecutionMetrics { } void executionEventObserved( - String actionName, Event event, ExecutionTraceContext traceContext) { + String actionName, + EventContext eventContext, + Event event, + ExecutionTraceContext traceContext) { ExecutionMetricRecorder recorder = metricRecordersByEntityType.get(traceContext.getEntityType()); if (isBlank(actionName) || recorder == null) { @@ -64,10 +65,11 @@ void executionEventObserved( String executionId = traceContext.getExecutionId(); String actionExecutionId = traceContext.getParentExecutionId(); if (ExecutionLifecycleEvents.EXECUTION_STARTED_EVENT_TYPE.equals(event.getType())) { - if (!isBlank(actionExecutionId) && !isBlank(executionId)) { - startNanosByActionExecutionId + Instant startTime = parseTimestamp(eventContext); + if (startTime != null && !isBlank(actionExecutionId) && !isBlank(executionId)) { + startTimesByActionExecutionId .computeIfAbsent(actionExecutionId, ignored -> new HashMap<>()) - .putIfAbsent(executionId, nanoTime.getAsLong()); + .putIfAbsent(executionId, startTime); } return; } @@ -80,12 +82,9 @@ void executionEventObserved( return; } - Long startNanos = removeExecutionStart(actionExecutionId, executionId); - Long latencyMs = - startNanos == null - ? null - : TimeUnit.NANOSECONDS.toMillis( - Math.max(0L, nanoTime.getAsLong() - startNanos)); + Instant startTime = removeExecutionStart(actionExecutionId, executionId); + Instant terminalTime = parseTimestamp(eventContext); + Long latencyMs = latencyBetween(startTime, terminalTime); FlinkAgentsMetricGroupImpl actionMetricGroup = agentMetricGroup.getSubGroup("action", actionName); @@ -98,26 +97,41 @@ void executionEventObserved( void actionExecutionTerminated(String actionExecutionId) { if (!isBlank(actionExecutionId)) { - startNanosByActionExecutionId.remove(actionExecutionId); + startTimesByActionExecutionId.remove(actionExecutionId); } } - private Long removeExecutionStart(String actionExecutionId, String executionId) { + private Instant removeExecutionStart(String actionExecutionId, String executionId) { if (isBlank(actionExecutionId) || isBlank(executionId)) { return null; } - Map actionExecutionStarts = - startNanosByActionExecutionId.get(actionExecutionId); + Map actionExecutionStarts = + startTimesByActionExecutionId.get(actionExecutionId); if (actionExecutionStarts == null) { return null; } - Long startNanos = actionExecutionStarts.remove(executionId); + Instant startTime = actionExecutionStarts.remove(executionId); if (actionExecutionStarts.isEmpty()) { - startNanosByActionExecutionId.remove(actionExecutionId); + startTimesByActionExecutionId.remove(actionExecutionId); } - return startNanos; + return startTime; + } + + private static Instant parseTimestamp(EventContext eventContext) { + try { + return Instant.parse(eventContext.getTimestamp()); + } catch (DateTimeParseException | NullPointerException ignored) { + return null; + } + } + + private static Long latencyBetween(Instant startTime, Instant terminalTime) { + if (startTime == null || terminalTime == null) { + return null; + } + return Math.max(0L, Duration.between(startTime, terminalTime).toMillis()); } private static boolean isBlank(String value) { diff --git a/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInMetrics.java b/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInMetrics.java index 9fd2b23f1..7e39c89fd 100644 --- a/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInMetrics.java +++ b/runtime/src/main/java/org/apache/flink/agents/runtime/metrics/BuiltInMetrics.java @@ -20,6 +20,7 @@ package org.apache.flink.agents.runtime.metrics; import org.apache.flink.agents.api.Event; +import org.apache.flink.agents.api.EventContext; import org.apache.flink.agents.api.trace.ExecutionLifecycleEvents; import org.apache.flink.agents.api.trace.ExecutionReporter; import org.apache.flink.agents.api.trace.ExecutionTraceContext; @@ -70,8 +71,7 @@ public BuiltInMetrics( this.eventLogTruncatedEvents = parentMetricGroup.getCounter("eventLogTruncatedEvents"); this.eventLogWriteFailures = parentMetricGroup.getCounter("eventLogWriteFailures"); this.inputRunMetrics = new BuiltInInputRunMetrics(parentMetricGroup, System::nanoTime); - this.executionMetrics = - new BuiltInExecutionMetrics(parentMetricGroup, System::nanoTime, isRegisteredTool); + this.executionMetrics = new BuiltInExecutionMetrics(parentMetricGroup, isRegisteredTool); this.actionMetricGroups = new HashMap<>(); for (String actionName : agentPlan.getActions().keySet()) { @@ -146,13 +146,21 @@ public void restoreActionTask(ExecutionTraceContext traceContext, boolean execut public void markExecutionEvent( String actionName, Event event, ExecutionTraceContext traceContext) { + markExecutionEvent(actionName, new EventContext(event), event, traceContext); + } + + public void markExecutionEvent( + String actionName, + EventContext eventContext, + Event event, + ExecutionTraceContext traceContext) { if (ExecutionReporter.EntityTypes.ACTION.equals(traceContext.getEntityType())) { actionMetrics(actionName).executionEventObserved(event, traceContext); if (isTerminalExecutionEvent(event)) { executionMetrics.actionExecutionTerminated(traceContext.getExecutionId()); } } else { - executionMetrics.executionEventObserved(actionName, event, traceContext); + executionMetrics.executionEventObserved(actionName, eventContext, event, traceContext); } } diff --git a/runtime/src/main/java/org/apache/flink/agents/runtime/operator/ActionExecutionOperator.java b/runtime/src/main/java/org/apache/flink/agents/runtime/operator/ActionExecutionOperator.java index a71c0b056..a26edc1e7 100644 --- a/runtime/src/main/java/org/apache/flink/agents/runtime/operator/ActionExecutionOperator.java +++ b/runtime/src/main/java/org/apache/flink/agents/runtime/operator/ActionExecutionOperator.java @@ -18,6 +18,7 @@ package org.apache.flink.agents.runtime.operator; import org.apache.flink.agents.api.Event; +import org.apache.flink.agents.api.EventContext; import org.apache.flink.agents.api.OutputEvent; import org.apache.flink.agents.api.agents.AgentExecutionOptions; import org.apache.flink.agents.api.event.AgentRunBeginEvent; @@ -454,9 +455,9 @@ private void processActionTask(Object key, String contextKey, ActionTask actionT stateManager.getShortTermMemState(), pythonBridge.getPythonRunnerContext(), ltm, - (event, traceContext) -> + (eventContext, event, traceContext) -> notifyExecutionLifecycleEvent( - actionTask.action.getName(), traceContext, event)); + actionTask.action.getName(), eventContext, traceContext, event)); long sequenceNumber = stateManager.getSequenceNumber(); boolean isFinished; @@ -769,8 +770,16 @@ private void notifyActionFailed(ActionTask actionTask, Throwable error) { private void notifyExecutionLifecycleEvent( String actionName, ExecutionTraceContext traceContext, Event event) { - builtInMetrics.markExecutionEvent(actionName, event, traceContext); - executionEventLogger.emit(event, traceContext); + notifyExecutionLifecycleEvent(actionName, new EventContext(event), traceContext, event); + } + + private void notifyExecutionLifecycleEvent( + String actionName, + EventContext eventContext, + ExecutionTraceContext traceContext, + Event event) { + builtInMetrics.markExecutionEvent(actionName, eventContext, event, traceContext); + executionEventLogger.emit(eventContext, event, traceContext); } private ActionTask createActionTask( diff --git a/runtime/src/main/java/org/apache/flink/agents/runtime/python/context/PythonRunnerContextImpl.java b/runtime/src/main/java/org/apache/flink/agents/runtime/python/context/PythonRunnerContextImpl.java index 633538725..f36bca139 100644 --- a/runtime/src/main/java/org/apache/flink/agents/runtime/python/context/PythonRunnerContextImpl.java +++ b/runtime/src/main/java/org/apache/flink/agents/runtime/python/context/PythonRunnerContextImpl.java @@ -21,6 +21,7 @@ import com.fasterxml.jackson.core.type.TypeReference; import com.fasterxml.jackson.databind.ObjectMapper; import org.apache.flink.agents.api.Event; +import org.apache.flink.agents.api.EventContext; import org.apache.flink.agents.api.trace.ExecutionLifecycleEvents; import org.apache.flink.agents.plan.AgentPlan; import org.apache.flink.agents.runtime.ResourceCache; @@ -76,11 +77,25 @@ public void reportExecutionStartedJson( reportExecutionStarted(entityType, entityName, parseEntityMetadata(entityMetadataJson)); } + public void reportExecutionStartedAtJson( + String entityType, String entityName, String entityMetadataJson, String timestamp) + throws Exception { + reportExecutionStartedAt( + entityType, entityName, parseEntityMetadata(entityMetadataJson), timestamp); + } + public void reportExecutionSucceededJson( String entityType, String entityName, String entityMetadataJson) throws Exception { reportExecutionSucceeded(entityType, entityName, parseEntityMetadata(entityMetadataJson)); } + public void reportExecutionSucceededAtJson( + String entityType, String entityName, String entityMetadataJson, String timestamp) + throws Exception { + reportExecutionSucceededAt( + entityType, entityName, parseEntityMetadata(entityMetadataJson), timestamp); + } + public void reportExecutionFailedJson( String entityType, String entityName, @@ -96,6 +111,25 @@ public void reportExecutionFailedJson( ExecutionLifecycleEvents.executionFailed(errorType, errorMessage, problemCategory)); } + public void reportExecutionFailedAtJson( + String entityType, + String entityName, + String entityMetadataJson, + String errorType, + String errorMessage, + String problemCategory, + String timestamp) + throws Exception { + Event event = + ExecutionLifecycleEvents.executionFailed(errorType, errorMessage, problemCategory); + reportChildExecution( + entityType, + entityName, + parseEntityMetadata(entityMetadataJson), + new EventContext(event.getType(), timestamp), + event); + } + public void checkMailboxThread() { // this method will be invoked by PythonActionExecutor's python interpreter. this.mailboxThreadChecker.run(); diff --git a/runtime/src/main/java/org/apache/flink/agents/runtime/trace/ExecutionEventLogger.java b/runtime/src/main/java/org/apache/flink/agents/runtime/trace/ExecutionEventLogger.java index 21e092114..33253accd 100644 --- a/runtime/src/main/java/org/apache/flink/agents/runtime/trace/ExecutionEventLogger.java +++ b/runtime/src/main/java/org/apache/flink/agents/runtime/trace/ExecutionEventLogger.java @@ -18,6 +18,7 @@ package org.apache.flink.agents.runtime.trace; import org.apache.flink.agents.api.Event; +import org.apache.flink.agents.api.EventContext; import org.apache.flink.agents.api.trace.ExecutionTraceContext; import org.apache.flink.agents.runtime.eventlog.EventLogWriter; import org.apache.flink.annotation.Internal; @@ -37,7 +38,7 @@ private ExecutionEventLogger(EventLogWriter eventLogWriter) { } @Override - public void emit(Event event, ExecutionTraceContext traceContext) { - eventLogWriter.appendExecutionEventAndFlush(event, traceContext); + public void emit(EventContext eventContext, Event event, ExecutionTraceContext traceContext) { + eventLogWriter.appendExecutionEventAndFlush(eventContext, event, traceContext); } } diff --git a/runtime/src/main/java/org/apache/flink/agents/runtime/trace/ExecutionEventSink.java b/runtime/src/main/java/org/apache/flink/agents/runtime/trace/ExecutionEventSink.java index 1195c6574..6af5a2a05 100644 --- a/runtime/src/main/java/org/apache/flink/agents/runtime/trace/ExecutionEventSink.java +++ b/runtime/src/main/java/org/apache/flink/agents/runtime/trace/ExecutionEventSink.java @@ -18,6 +18,7 @@ package org.apache.flink.agents.runtime.trace; import org.apache.flink.agents.api.Event; +import org.apache.flink.agents.api.EventContext; import org.apache.flink.agents.api.trace.ExecutionTraceContext; import org.apache.flink.annotation.Internal; @@ -25,5 +26,5 @@ @Internal @FunctionalInterface public interface ExecutionEventSink { - void emit(Event event, ExecutionTraceContext traceContext); + void emit(EventContext eventContext, Event event, ExecutionTraceContext traceContext); } diff --git a/runtime/src/test/java/org/apache/flink/agents/runtime/context/RunnerContextImplExecutionReporterTest.java b/runtime/src/test/java/org/apache/flink/agents/runtime/context/RunnerContextImplExecutionReporterTest.java index be3090ae5..a25a1a0b1 100644 --- a/runtime/src/test/java/org/apache/flink/agents/runtime/context/RunnerContextImplExecutionReporterTest.java +++ b/runtime/src/test/java/org/apache/flink/agents/runtime/context/RunnerContextImplExecutionReporterTest.java @@ -18,6 +18,7 @@ package org.apache.flink.agents.runtime.context; import org.apache.flink.agents.api.Event; +import org.apache.flink.agents.api.EventContext; import org.apache.flink.agents.api.trace.ExecutionLifecycleEvents; import org.apache.flink.agents.api.trace.ExecutionReporter; import org.apache.flink.agents.api.trace.ExecutionTraceContext; @@ -45,14 +46,15 @@ void reportedExecutionReusesChildTraceContextBetweenStartAndFinish() throws Exce ExecutionTraceContext.forInputRun("business-key", "agent") .childExecution("action", "chat_model_action"); runnerContext.setExecutionEventSink( - (event, context) -> reports.add(new RecordedReport(event, context))); + (eventContext, event, context) -> + reports.add(new RecordedReport(eventContext, event, context))); runnerContext.switchActionContext( "chat_model_action", null, "business-key", actionTraceContext, new HashMap<>()); - runnerContext.reportExecutionStarted( - ExecutionReporter.EntityTypes.LLM, "model-a", Map.of()); - runnerContext.reportExecutionSucceeded( - ExecutionReporter.EntityTypes.LLM, "model-a", Map.of()); + runnerContext.reportExecutionStartedAt( + ExecutionReporter.EntityTypes.LLM, "model-a", Map.of(), "2026-01-01T00:00:00.001Z"); + runnerContext.reportExecutionSucceededAt( + ExecutionReporter.EntityTypes.LLM, "model-a", Map.of(), "2026-01-01T00:00:00.025Z"); assertThat(reports).hasSize(2); RecordedReport started = reports.get(0); @@ -73,6 +75,8 @@ void reportedExecutionReusesChildTraceContextBetweenStartAndFinish() throws Exce assertThat(started.traceContext().getEntityType()) .isEqualTo(ExecutionReporter.EntityTypes.LLM); assertThat(started.traceContext().getEntityName()).isEqualTo("model-a"); + assertThat(started.eventContext.getTimestamp()).isEqualTo("2026-01-01T00:00:00.001Z"); + assertThat(finished.eventContext.getTimestamp()).isEqualTo("2026-01-01T00:00:00.025Z"); } @Test @@ -81,7 +85,8 @@ void reportedExecutionStateFollowsActionContextAcrossSwitches() throws Exception RunnerContextImpl runnerContext = new RunnerContextImpl(null, () -> {}, emptyAgentPlan(), null, "job"); runnerContext.setExecutionEventSink( - (event, context) -> reports.add(new RecordedReport(event, context))); + (eventContext, event, context) -> + reports.add(new RecordedReport(eventContext, event, context))); ExecutionTraceContext actionA = ExecutionTraceContext.forInputRun("business-key", "agent") @@ -129,20 +134,22 @@ void pythonReporterBridgePreservesMetadataAndPythonErrorFields() throws Exceptio ExecutionTraceContext.forInputRun("business-key", "agent") .childExecution("action", "tool_call_action"); runnerContext.setExecutionEventSink( - (event, context) -> reports.add(new RecordedReport(event, context))); + (eventContext, event, context) -> + reports.add(new RecordedReport(eventContext, event, context))); runnerContext.switchActionContext( "tool_call_action", null, "business-key", actionTraceContext, new HashMap<>()); String metadata = "{\"toolCallId\":\"call-1\",\"toolType\":\"function\"}"; - runnerContext.reportExecutionStartedJson( - ExecutionReporter.EntityTypes.TOOL, "search", metadata); - runnerContext.reportExecutionFailedJson( + runnerContext.reportExecutionStartedAtJson( + ExecutionReporter.EntityTypes.TOOL, "search", metadata, "2026-01-01T00:00:01.001Z"); + runnerContext.reportExecutionFailedAtJson( ExecutionReporter.EntityTypes.TOOL, "search", metadata, "builtins.ValueError", "bad response", - ExecutionReporter.ProblemCategories.TOOL_CALL_FAILED); + ExecutionReporter.ProblemCategories.TOOL_CALL_FAILED, + "2026-01-01T00:00:01.125Z"); assertThat(reports).hasSize(2); RecordedReport started = reports.get(0); @@ -159,6 +166,8 @@ void pythonReporterBridgePreservesMetadataAndPythonErrorFields() throws Exceptio assertThat(failed.event.getAttr("errorMessage")).isEqualTo("bad response"); assertThat(failed.event.getAttr(ExecutionLifecycleEvents.PROBLEM_CATEGORY_ATTRIBUTE)) .isEqualTo(ExecutionReporter.ProblemCategories.TOOL_CALL_FAILED); + assertThat(started.eventContext.getTimestamp()).isEqualTo("2026-01-01T00:00:01.001Z"); + assertThat(failed.eventContext.getTimestamp()).isEqualTo("2026-01-01T00:00:01.125Z"); } private static AgentPlan emptyAgentPlan() { @@ -166,10 +175,13 @@ private static AgentPlan emptyAgentPlan() { } private static class RecordedReport { + private final EventContext eventContext; private final Event event; private final ExecutionTraceContext traceContext; - private RecordedReport(Event event, ExecutionTraceContext traceContext) { + private RecordedReport( + EventContext eventContext, Event event, ExecutionTraceContext traceContext) { + this.eventContext = eventContext; this.event = event; this.traceContext = traceContext; } diff --git a/runtime/src/test/java/org/apache/flink/agents/runtime/eventlog/EventLogWriterTest.java b/runtime/src/test/java/org/apache/flink/agents/runtime/eventlog/EventLogWriterTest.java index e682e35d7..ca51d822e 100644 --- a/runtime/src/test/java/org/apache/flink/agents/runtime/eventlog/EventLogWriterTest.java +++ b/runtime/src/test/java/org/apache/flink/agents/runtime/eventlog/EventLogWriterTest.java @@ -131,10 +131,12 @@ void traceEnabledWritesExecutionEventWithTraceContext() throws Exception { ExecutionTraceContext.forInputRun("business-key", "agent") .childExecution("action", "action1"); Event executionEvent = ExecutionLifecycleEvents.executionStarted(); + EventContext eventContext = + new EventContext(executionEvent.getType(), "2026-01-01T00:00:00.123Z"); - writer.appendExecutionEventAndFlush(executionEvent, traceContext); + writer.appendExecutionEventAndFlush(eventContext, executionEvent, traceContext); - verify(mockLogger).append(any(EventContext.class), eq(executionEvent), eq(traceContext)); + verify(mockLogger).append(eq(eventContext), eq(executionEvent), eq(traceContext)); verify(mockLogger).flush(); } diff --git a/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetricsTest.java b/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetricsTest.java index 7716287b6..c4b458d9d 100644 --- a/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetricsTest.java +++ b/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetricsTest.java @@ -18,6 +18,8 @@ */ package org.apache.flink.agents.runtime.metrics; +import org.apache.flink.agents.api.Event; +import org.apache.flink.agents.api.EventContext; import org.apache.flink.agents.api.trace.ExecutionLifecycleEvents; import org.apache.flink.agents.api.trace.ExecutionReporter; import org.apache.flink.agents.api.trace.ExecutionTraceContext; @@ -27,9 +29,9 @@ import org.junit.jupiter.api.BeforeEach; import org.junit.jupiter.api.Test; +import java.time.Instant; import java.util.Map; import java.util.Set; -import java.util.concurrent.atomic.AtomicLong; import static org.assertj.core.api.Assertions.assertThat; @@ -37,7 +39,6 @@ class BuiltInExecutionMetricsTest { private static final String ACTION_NAME = "chat_model_action"; - private final AtomicLong nanoTime = new AtomicLong(); private FlinkAgentsMetricGroupImpl metricGroup; private BuiltInExecutionMetrics metrics; @@ -47,29 +48,23 @@ void setUp() { UnregisteredMetricGroups.createUnregisteredOperatorMetricGroup(); metricGroup = new FlinkAgentsMetricGroupImpl(parentMetricGroup); Set registeredTools = Set.of("search", "fetch", "load_skill"); - metrics = - new BuiltInExecutionMetrics(metricGroup, nanoTime::get, registeredTools::contains); + metrics = new BuiltInExecutionMetrics(metricGroup, registeredTools::contains); } @Test void recordsLlmOutcomeByModelResource() { ExecutionTraceContext success = execution(ExecutionReporter.EntityTypes.LLM, "primary_model", Map.of()); - metrics.executionEventObserved( - ACTION_NAME, ExecutionLifecycleEvents.executionStarted(), success); - nanoTime.addAndGet(25_000_000L); - metrics.executionEventObserved( - ACTION_NAME, ExecutionLifecycleEvents.executionFinished(), success); + observe(ExecutionLifecycleEvents.executionStarted(), success, 0); + observe(ExecutionLifecycleEvents.executionFinished(), success, 25); ExecutionTraceContext failure = execution(ExecutionReporter.EntityTypes.LLM, "primary_model", Map.of()); - metrics.executionEventObserved( - ACTION_NAME, ExecutionLifecycleEvents.executionStarted(), failure); - nanoTime.addAndGet(40_000_000L); - metrics.executionEventObserved( - ACTION_NAME, + observe(ExecutionLifecycleEvents.executionStarted(), failure, 100); + observe( ExecutionLifecycleEvents.executionFailed(new RuntimeException("failed")), - failure); + failure, + 140); FlinkAgentsMetricGroupImpl modelResource = actionMetricGroup().getSubGroup("model_resource", "primary_model"); @@ -94,21 +89,16 @@ void recordsLlmOutcomeByModelResource() { void recordsToolOutcomeByToolName() { ExecutionTraceContext success = execution(ExecutionReporter.EntityTypes.TOOL, "search", Map.of()); - metrics.executionEventObserved( - ACTION_NAME, ExecutionLifecycleEvents.executionStarted(), success); - nanoTime.addAndGet(15_000_000L); - metrics.executionEventObserved( - ACTION_NAME, ExecutionLifecycleEvents.executionFinished(), success); + observe(ExecutionLifecycleEvents.executionStarted(), success, 0); + observe(ExecutionLifecycleEvents.executionFinished(), success, 15); ExecutionTraceContext failure = execution(ExecutionReporter.EntityTypes.TOOL, "search", Map.of()); - metrics.executionEventObserved( - ACTION_NAME, ExecutionLifecycleEvents.executionStarted(), failure); - nanoTime.addAndGet(20_000_000L); - metrics.executionEventObserved( - ACTION_NAME, + observe(ExecutionLifecycleEvents.executionStarted(), failure, 5); + observe( ExecutionLifecycleEvents.executionFailed(new RuntimeException("failed")), - failure); + failure, + 25); FlinkAgentsMetricGroupImpl tool = actionMetricGroup().getSubGroup("tool", "search"); assertThat(tool.getCounter(ToolExecutionMetricRecorder.NUM_TOOL_CALLS_SUCCEEDED).getCount()) @@ -117,6 +107,11 @@ void recordsToolOutcomeByToolName() { .isEqualTo(1); assertThat(tool.getHistogram(ToolExecutionMetricRecorder.TOOL_CALL_LATENCY_MS).getCount()) .isEqualTo(2); + assertThat( + tool.getHistogram(ToolExecutionMetricRecorder.TOOL_CALL_LATENCY_MS) + .getStatistics() + .getMax()) + .isEqualTo(20L); } @Test @@ -126,14 +121,14 @@ void aggregatesUnregisteredToolNamesIntoUnknownScope() { ExecutionTraceContext second = execution(ExecutionReporter.EntityTypes.TOOL, "hallucinated_two", Map.of()); - metrics.executionEventObserved( - ACTION_NAME, + observe( ExecutionLifecycleEvents.executionFailed(new RuntimeException("missing")), - first); - metrics.executionEventObserved( - ACTION_NAME, + first, + 0); + observe( ExecutionLifecycleEvents.executionFailed(new RuntimeException("missing")), - second); + second, + 1); FlinkAgentsMetricGroupImpl unknown = actionMetricGroup() @@ -153,11 +148,8 @@ void recordsExplicitSkillLoads() { "calculator", ToolExecutionMetadataKeys.SKILL_REGISTERED, true)); - metrics.executionEventObserved( - ACTION_NAME, ExecutionLifecycleEvents.executionStarted(), loadSkill); - nanoTime.addAndGet(12_000_000L); - metrics.executionEventObserved( - ACTION_NAME, ExecutionLifecycleEvents.executionFinished(), loadSkill); + observe(ExecutionLifecycleEvents.executionStarted(), loadSkill, 0); + observe(ExecutionLifecycleEvents.executionFinished(), loadSkill, 12); FlinkAgentsMetricGroupImpl skill = actionMetricGroup().getSubGroup("skill", "calculator"); assertThat(skill.getCounter(ToolExecutionMetricRecorder.NUM_SKILL_LOADS).getCount()) @@ -194,10 +186,8 @@ void aggregatesUnregisteredSkillNamesIntoUnknownScope() { ToolExecutionMetadataKeys.SKILL_REGISTERED, false)); - metrics.executionEventObserved( - ACTION_NAME, ExecutionLifecycleEvents.executionFinished(), first); - metrics.executionEventObserved( - ACTION_NAME, ExecutionLifecycleEvents.executionFinished(), second); + observe(ExecutionLifecycleEvents.executionFinished(), first, 0); + observe(ExecutionLifecycleEvents.executionFinished(), second, 1); FlinkAgentsMetricGroupImpl unknown = actionMetricGroup() @@ -213,24 +203,19 @@ void aggregatesMcpToolOutcomesByServer() { ExecutionReporter.EntityTypes.TOOL, "search", Map.of(ToolExecutionMetadataKeys.MCP_SERVER, "search_server")); - metrics.executionEventObserved( - ACTION_NAME, ExecutionLifecycleEvents.executionStarted(), success); - nanoTime.addAndGet(30_000_000L); - metrics.executionEventObserved( - ACTION_NAME, ExecutionLifecycleEvents.executionFinished(), success); + observe(ExecutionLifecycleEvents.executionStarted(), success, 0); + observe(ExecutionLifecycleEvents.executionFinished(), success, 30); ExecutionTraceContext failure = execution( ExecutionReporter.EntityTypes.TOOL, "fetch", Map.of(ToolExecutionMetadataKeys.MCP_SERVER, "search_server")); - metrics.executionEventObserved( - ACTION_NAME, ExecutionLifecycleEvents.executionStarted(), failure); - nanoTime.addAndGet(50_000_000L); - metrics.executionEventObserved( - ACTION_NAME, + observe(ExecutionLifecycleEvents.executionStarted(), failure, 10); + observe( ExecutionLifecycleEvents.executionFailed(new RuntimeException("failed")), - failure); + failure, + 60); FlinkAgentsMetricGroupImpl mcpServer = actionMetricGroup().getSubGroup("mcp_server", "search_server"); @@ -256,8 +241,7 @@ void aggregatesMcpToolOutcomesByServer() { void terminalEventWithoutLocalStartDoesNotRecordLatency() { ExecutionTraceContext llm = execution(ExecutionReporter.EntityTypes.LLM, "restored_model", Map.of()); - metrics.executionEventObserved( - ACTION_NAME, ExecutionLifecycleEvents.executionFinished(), llm); + observe(ExecutionLifecycleEvents.executionFinished(), llm, 0); FlinkAgentsMetricGroupImpl modelResource = actionMetricGroup().getSubGroup("model_resource", "restored_model"); @@ -273,6 +257,15 @@ void terminalEventWithoutLocalStartDoesNotRecordLatency() { .isZero(); } + private void observe(Event event, ExecutionTraceContext traceContext, long timestampMillis) { + metrics.executionEventObserved( + ACTION_NAME, + new EventContext( + event.getType(), Instant.EPOCH.plusMillis(timestampMillis).toString()), + event, + traceContext); + } + private FlinkAgentsMetricGroupImpl actionMetricGroup() { return metricGroup.getSubGroup("action", ACTION_NAME); } diff --git a/runtime/src/test/java/org/apache/flink/agents/runtime/operator/ActionExecutionOperatorTest.java b/runtime/src/test/java/org/apache/flink/agents/runtime/operator/ActionExecutionOperatorTest.java index 1885cd8b9..b7057b81f 100644 --- a/runtime/src/test/java/org/apache/flink/agents/runtime/operator/ActionExecutionOperatorTest.java +++ b/runtime/src/test/java/org/apache/flink/agents/runtime/operator/ActionExecutionOperatorTest.java @@ -487,7 +487,7 @@ void testMailboxSubmittedActionTaskPropagatesErrorAndClosesActionLifecycle() thr } @Test - void testToolLinkageErrorEmitsFailedLifecycleBeforeActionFailure() throws Exception { + void testToolLinkageErrorPropagatesWithoutInferringToolOutcome() throws Exception { AgentPlan basePlan = TestAgent.getLinkageErrorToolAgentPlan(); AgentPlan agentPlan = new AgentPlan( @@ -521,14 +521,22 @@ void testToolLinkageErrorEmitsFailedLifecycleBeforeActionFailure() throws Except RecordedEvent failed = findRecordedLifecycleEvent( ExecutionLifecycleEvents.EXECUTION_FAILED_EVENT_TYPE, - "linkageErrorTool", + "tool_call_action", ExecutionLifecycleEvents.STATUS_FAILED); assertThat(started.traceContext().getEntityType()) .isEqualTo(ExecutionReporter.EntityTypes.TOOL); assertThat(failed.traceContext().getExecutionId()) - .isEqualTo(started.traceContext().getExecutionId()); + .isEqualTo(started.traceContext().getParentExecutionId()); assertThat(failed.event.getAttr("errorType")) .isEqualTo(NoClassDefFoundError.class.getName()); + assertThat(RecordingEventLogger.events()) + .filteredOn( + record -> + started.traceContext() + .getExecutionId() + .equals(record.traceContext().getExecutionId())) + .extracting(record -> record.event.getType()) + .containsExactly(ExecutionLifecycleEvents.EXECUTION_STARTED_EVENT_TYPE); } @Test diff --git a/runtime/src/test/java/org/apache/flink/agents/runtime/operator/ActionTaskContextManagerTest.java b/runtime/src/test/java/org/apache/flink/agents/runtime/operator/ActionTaskContextManagerTest.java index a1ea1b0c8..44f94d94f 100644 --- a/runtime/src/test/java/org/apache/flink/agents/runtime/operator/ActionTaskContextManagerTest.java +++ b/runtime/src/test/java/org/apache/flink/agents/runtime/operator/ActionTaskContextManagerTest.java @@ -272,7 +272,7 @@ void reportedExecutionStateFollowsActionExecutionAcrossContinuationTasks() throw ActionTask to = new JavaActionTask("k", new InputEvent(1L), action, from.getTraceContext()); List reports = new ArrayList<>(); - ExecutionEventSink sink = (event, context) -> reports.add(context); + ExecutionEventSink sink = (eventContext, event, context) -> reports.add(context); invokeCreateAndSetRunnerContext(mgr, from, sink); from.getRunnerContext() @@ -295,7 +295,7 @@ void completingActionExecutionDropsReportedExecutionState() throws Exception { try (ActionTaskContextManager mgr = new ActionTaskContextManager(1)) { ActionTask task = new JavaActionTask("k", new InputEvent(1L), TestActions.noopAction()); List reports = new ArrayList<>(); - ExecutionEventSink sink = (event, context) -> reports.add(context); + ExecutionEventSink sink = (eventContext, event, context) -> reports.add(context); invokeCreateAndSetRunnerContext(mgr, task, sink); task.getRunnerContext() @@ -317,7 +317,7 @@ void completingActionExecutionDropsReportedExecutionState() throws Exception { void activeExecutionReportsDoNotEnterActionTaskState() throws Exception { try (ActionTaskContextManager mgr = new ActionTaskContextManager(1)) { ActionTask task = new JavaActionTask("k", new InputEvent(1L), TestActions.noopAction()); - invokeCreateAndSetRunnerContext(mgr, task, (event, context) -> {}); + invokeCreateAndSetRunnerContext(mgr, task, (eventContext, event, context) -> {}); task.getRunnerContext() .reportExecutionStarted( ExecutionReporter.EntityTypes.TOOL, From dc1a7ea1127fa05ccdcde4992ec3249e5fb63a6f Mon Sep 17 00:00:00 2001 From: Joey Tong Date: Thu, 3 Sep 2026 19:09:14 +0800 Subject: [PATCH 10/10] [plan][python] Exclude late Tool starts from timeout latency Only report a Tool start at or before durable result observation when an Outcome is available. Preserve terminal status and business responses. Add Java/Python boundary regressions and verify terminal-only Tool failures still increment counters without latency samples. Document the boundary. Validated with 40 Java and 35 Python tests, Spotless, and Ruff. Generated-by: Codex CLI 0.153.0-alpha.5 (GPT-5; exact model variant not exposed) Co-Authored-By: Codex AI-Model: gpt-5 AI-Contributed/Feature: 8/8 AI-Contributed/UT: 149/149 --- docs/content/docs/operations/monitoring.md | 4 +- .../agents/plan/actions/ToolCallAction.java | 2 +- .../actions/ToolCallActionReportTest.java | 75 +++++++++++++++++++ .../plan/actions/tool_call_action.py | 2 +- .../tests/actions/test_tool_call_action.py | 58 ++++++++++++++ .../metrics/BuiltInExecutionMetricsTest.java | 16 ++++ 6 files changed, 153 insertions(+), 4 deletions(-) diff --git a/docs/content/docs/operations/monitoring.md b/docs/content/docs/operations/monitoring.md index 4fb422024..bcd72eae1 100644 --- a/docs/content/docs/operations/monitoring.md +++ b/docs/content/docs/operations/monitoring.md @@ -88,9 +88,9 @@ Tool outcomes follow the existing language-specific Tool contracts. In both Java `numOfSkillLoads` counts terminal calls rather than successful loads. Under the current Tool contracts, a `load_skill` not-found response returns normally and is therefore observed as a successful Tool outcome. Consequently, Tool and MCP outcome metrics use the same names and scopes in both runtimes, but explicit error-result semantics are not yet identical. This alignment, including explicit failure results for framework Tools such as `load_skill`, is tracked in [Issue #956](https://github.com/apache/flink-agents/issues/956). -Execution latency tracking is process-local and uses the occurrence timestamps in matching start and terminal Events. Both Events must be observed in the same task attempt. A Tool latency sample additionally requires the Tool callable to run; queueing and parallel-batch fan-in are excluded. LLM and Tool terminal counters are still updated when no matching start Event is available. +Execution latency tracking is process-local and uses the occurrence timestamps in matching start and terminal Events. Both Events must be observed in the same task attempt. A Tool latency sample additionally requires the Tool callable to start no later than the Action observes its durable result; queueing and parallel-batch fan-in are excluded. LLM and Tool terminal counters are still updated when no matching start Event is available. -A request timeout does not necessarily stop a running Tool. ToolCallAction records when the durable call returns or raises, before processing responses or publishing Events. If a Tool has not finished by that time, its terminal Event uses this fixed observation time; a later Tool completion cannot extend it or produce another terminal Event. This excludes response-processing and Event-publication delays, but is not the execution framework's exact timeout-decision time: any delay before the durable result reaches the Action remains included. Cached results and failures before invocation retain terminal-only reporting, without an invocation latency sample. If a batch aborts without returning per-call Outcomes, known starts may be reported without terminal Events; individual results are not inferred from timestamps or the batch exception. These observation rules do not change the execution framework's timeout, failure, or durable-persistence behavior. +A request timeout does not necessarily stop a running Tool. ToolCallAction records when the durable call returns or raises, before processing responses or publishing Events. If a Tool has not finished by that time, its terminal Event uses this fixed observation time; a later Tool completion cannot extend it or produce another terminal Event. This excludes response-processing and Event-publication delays, but is not the execution framework's exact timeout-decision time: any delay before the durable result reaches the Action remains included. A callable that starts after this observation retains its timeout terminal Event without a start Event or latency sample, even if it later completes in the background. Cached results and failures before invocation also retain terminal-only reporting. If a batch aborts without returning per-call Outcomes, known starts may be reported without terminal Events; no terminal execution Events are inferred from timestamps or the batch exception. Existing business ToolResponseEvent error handling is unchanged. These observation rules do not change the execution framework's timeout, failure, or durable-persistence behavior. In previous releases, `retryCount` and `retryWaitSec` used the `model.` scope. They now use `model_resource.` so retries are attributed to the configured ChatModel resource. Existing queries and dashboards for these two metrics must use the new scope. diff --git a/plan/src/main/java/org/apache/flink/agents/plan/actions/ToolCallAction.java b/plan/src/main/java/org/apache/flink/agents/plan/actions/ToolCallAction.java index 1861c7d18..dc6779319 100644 --- a/plan/src/main/java/org/apache/flink/agents/plan/actions/ToolCallAction.java +++ b/plan/src/main/java/org/apache/flink/agents/plan/actions/ToolCallAction.java @@ -281,7 +281,7 @@ private static void reportExecution( Instant resultObservedAt) { Instant finishedAt = execution.occurrence.finishedAt; Instant startedAt = execution.occurrence.startedAt; - if (startedAt != null) { + if (startedAt != null && (outcome == null || !startedAt.isAfter(resultObservedAt))) { ExecutionReporters.startedAt( ctx, ExecutionReporter.EntityTypes.TOOL, diff --git a/plan/src/test/java/org/apache/flink/agents/plan/actions/ToolCallActionReportTest.java b/plan/src/test/java/org/apache/flink/agents/plan/actions/ToolCallActionReportTest.java index 52ceb8bae..08ff3f088 100644 --- a/plan/src/test/java/org/apache/flink/agents/plan/actions/ToolCallActionReportTest.java +++ b/plan/src/test/java/org/apache/flink/agents/plan/actions/ToolCallActionReportTest.java @@ -37,6 +37,7 @@ import org.junit.jupiter.params.ParameterizedTest; import org.junit.jupiter.params.provider.ValueSource; import org.mockito.ArgumentCaptor; +import org.mockito.MockedStatic; import java.time.Instant; import java.util.ArrayList; @@ -58,6 +59,7 @@ import static org.mockito.ArgumentMatchers.eq; import static org.mockito.Mockito.doAnswer; import static org.mockito.Mockito.mock; +import static org.mockito.Mockito.mockStatic; import static org.mockito.Mockito.never; import static org.mockito.Mockito.times; import static org.mockito.Mockito.verify; @@ -485,6 +487,79 @@ void parallelTimeoutTimestampPrecedesResponseProcessingAndReporting( List.of("call-2", "call-3")); } + @ParameterizedTest + @ValueSource(booleans = {false, true}) + void parallelTimeoutOmitsStartsAfterResultObservation(boolean startsAfterObservation) + throws Exception { + TimeoutException failure = new TimeoutException("batch timed out"); + Instant base = Instant.parse("2026-01-01T00:00:00Z"); + Instant observedAt = base.plusSeconds(1); + Instant delayedStart = startsAfterObservation ? observedAt.plusSeconds(1) : observedAt; + AtomicReference now = new AtomicReference<>(base); + List> delayed = new ArrayList<>(); + Tool tool = mock(Tool.class); + when(tool.call(any())).thenReturn(ToolResponse.success("ok")); + RunnerContext ctx = parallelContext(tool); + doAnswer( + invocation -> { + List> callables = + invocation.getArgument(0); + ToolResponse first = callables.get(0).call(); + delayed.addAll(callables.subList(1, callables.size())); + now.set(observedAt); + return List.of( + Outcome.success(first), + Outcome.failure(failure), + Outcome.failure(failure)); + }) + .when(ctx) + .durableExecuteAllAsync(any()); + doAnswer( + invocation -> { + Map metadata = invocation.getArgument(2); + if ("call-1" + .equals(metadata.get(ToolExecutionMetadataKeys.TOOL_CALL_ID))) { + // The delayed calls enter after the Action has observed the + // timeout. + now.set(delayedStart); + for (DurableCallable callable : delayed) { + callable.call(); + } + } + return null; + }) + .when((ExecutionReporter) ctx) + .reportExecutionStartedAt(anyString(), anyString(), anyMap(), anyString()); + + try (MockedStatic clock = mockStatic(Instant.class)) { + clock.when(Instant::now).thenAnswer(invocation -> now.get()); + ToolCallAction.processToolRequest(parallelRequest(), ctx); + } + + assertReports( + ctx, + startsAfterObservation ? List.of("call-1") : List.of("call-1", "call-2", "call-3"), + List.of("call-1"), + List.of("call-2", "call-3")); + verify(tool, times(3)).call(any()); + ArgumentCaptor finishedAt = ArgumentCaptor.forClass(String.class); + verify((ExecutionReporter) ctx, times(2)) + .reportExecutionFailedAt( + anyString(), + anyString(), + anyMap(), + eq(failure), + anyString(), + finishedAt.capture()); + assertThat(finishedAt.getAllValues()) + .containsExactly(observedAt.toString(), observedAt.toString()); + ArgumentCaptor response = ArgumentCaptor.forClass(Event.class); + verify(ctx).sendEvent(response.capture()); + assertThat(((ToolResponseEvent) response.getValue()).getSuccess()) + .containsExactlyInAnyOrderEntriesOf( + Map.of("call-1", true, "call-2", false, "call-3", false)); + } + private static RunnerContext parallelContext(Tool tool) throws Exception { RunnerContext ctx = mock(RunnerContext.class, withSettings().extraInterfaces(ExecutionReporter.class)); diff --git a/python/flink_agents/plan/actions/tool_call_action.py b/python/flink_agents/plan/actions/tool_call_action.py index 92b6a3b65..6a56753f0 100644 --- a/python/flink_agents/plan/actions/tool_call_action.py +++ b/python/flink_agents/plan/actions/tool_call_action.py @@ -328,7 +328,7 @@ def _report_execution( ) -> None: finished_at = execution.occurrence.finished_at started_at = execution.occurrence.started_at - if started_at is not None: + if started_at is not None and (outcome is None or started_at <= result_observed_at): ExecutionReporters.started_at( ctx, ExecutionEntityTypes.TOOL, diff --git a/python/flink_agents/plan/tests/actions/test_tool_call_action.py b/python/flink_agents/plan/tests/actions/test_tool_call_action.py index a14c9b999..448410a7a 100644 --- a/python/flink_agents/plan/tests/actions/test_tool_call_action.py +++ b/python/flink_agents/plan/tests/actions/test_tool_call_action.py @@ -666,6 +666,64 @@ async def execute_all(callables: list[Any]) -> list[Outcome]: ) +@pytest.mark.parametrize("starts_after_observation", [False, True]) +def test_parallel_timeout_omits_starts_after_result_observation( + starts_after_observation: bool, +) -> None: + failure = TimeoutError("batch timed out") + base = datetime(2026, 1, 1, tzinfo=timezone.utc) + observed_at = base + timedelta(seconds=1) + delayed_start = ( + observed_at + timedelta(seconds=1) if starts_after_observation else observed_at + ) + clock = [base] + delayed = [] + tool = MagicMock() + tool.tool_type.return_value = ToolType.FUNCTION + tool.call.return_value = "ok" + ctx, sent_events = trace_context(tool) + ctx.config = AgentConfiguration({}) + ctx.config.set(AgentExecutionOptions.TOOL_CALL_ASYNC, True) + ctx.config.set(AgentExecutionOptions.TOOL_CALL_PARALLELISM, 3) + + async def execute_all(callables: list[Any]) -> list[Outcome]: + first = callables[0] + result = first.func(*first.args, **(first.kwargs or {})) + delayed.extend(callables[1:]) + clock[0] = observed_at + return [ + Outcome.success(result), + Outcome.failure(failure), + Outcome.failure(failure), + ] + + def report_started(*args: Any) -> None: + if args[2][ToolExecutionMetadataKeys.TOOL_CALL_ID] == "call-1": + # The delayed calls enter after the Action has observed the timeout. + clock[0] = delayed_start + for call in delayed: + call.func(*call.args, **(call.kwargs or {})) + + ctx.durable_execute_all_async = execute_all + ctx.report_execution_started_at.side_effect = report_started + with patch.object(tool_call_action, "datetime") as datetime_mock: + datetime_mock.now.side_effect = lambda tz: clock[0] + asyncio.run(process_tool_request(parallel_trace_request(), ctx)) + + starts = ["call-1"] if starts_after_observation else ["call-1", "call-2", "call-3"] + assert_occurrence_reports(ctx, starts, ["call-1"], ["call-2", "call-3"]) + assert tool.call.call_count == 3 + assert all( + call.args[3] is failure and call.args[-1] == "2026-01-01T00:00:01Z" + for call in ctx.report_execution_failed_at.call_args_list + ) + assert sent_events[0].success == { + "call-1": True, + "call-2": False, + "call-3": False, + } + + def test_partial_cache_replay_only_reports_start_for_invoked_tool() -> None: tool = MagicMock() tool.tool_type.return_value = ToolType.FUNCTION diff --git a/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetricsTest.java b/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetricsTest.java index c4b458d9d..4ac2e1f97 100644 --- a/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetricsTest.java +++ b/runtime/src/test/java/org/apache/flink/agents/runtime/metrics/BuiltInExecutionMetricsTest.java @@ -257,6 +257,22 @@ void terminalEventWithoutLocalStartDoesNotRecordLatency() { .isZero(); } + @Test + void toolFailureWithoutStartCountsFailureWithoutLatency() { + ExecutionTraceContext traceContext = + execution(ExecutionReporter.EntityTypes.TOOL, "search", Map.of()); + observe( + ExecutionLifecycleEvents.executionFailed(new RuntimeException("timed out")), + traceContext, + 1000); + + FlinkAgentsMetricGroupImpl tool = actionMetricGroup().getSubGroup("tool", "search"); + assertThat(tool.getCounter(ToolExecutionMetricRecorder.NUM_TOOL_CALLS_FAILED).getCount()) + .isEqualTo(1); + assertThat(tool.getHistogram(ToolExecutionMetricRecorder.TOOL_CALL_LATENCY_MS).getCount()) + .isZero(); + } + private void observe(Event event, ExecutionTraceContext traceContext, long timestampMillis) { metrics.executionEventObserved( ACTION_NAME,