weiqingy commented on code in PR #955:
URL: https://github.com/apache/flink-agents/pull/955#discussion_r3999008203
##########
plan/src/main/java/org/apache/flink/agents/plan/actions/ToolCallAction.java:
##########
@@ -201,26 +205,29 @@ private static void executeParallel(
for (ToolCallExecution execution : executions) {
callables.add(execution.callable);
}
+ List<Outcome<ToolResponse>> outcomes = List.of();
+ Instant resultObservedAt = null;
try {
- List<Outcome<ToolResponse>> 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 {
Review Comment:
The Tool start is now written only after the durable result comes back, here
and at `:258-259` (Python `tool_call_action.py:248-255`, `:293-294`). On
`main`, `ToolCallAction.java:136-137` and `tool_call_action.py:169-171` write
it before the call runs. I see why: reporting must run on the mailbox thread
(`RunnerContextImpl.java:470`), and the tool can run on a worker.
If a tool hangs (`tool-call.batch.timeout.ms` is off by default,
`AgentExecutionOptions.java:93`) or the TaskManager dies mid-call, Agent Trace
now has no Tool record for that call. On `main` it has the start record. Was
keeping an early start record considered, with the real start time carried on
the finish record? Or could the Agent Trace section (`monitoring.md:239-241`)
say this in one sentence?
##########
docs/content/docs/operations/monitoring.md:
##########
@@ -36,11 +36,64 @@ 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.\<action_name\>.numOfActionsExecuted | The total number
of actions this operator has executed for a specific action name. | Count |
| **Action** | action.\<action_name\>.numOfActionsExecutedPerSec | The number
of actions this operator has executed per second for a specific action name. |
Meter |
+| **Action** | action.\<action_name\>.actionSchedulingLatencyMs | Time from
enqueuing the initial Action task until it is selected for execution. |
Histogram |
+| **Action** | action.\<action_name\>.actionExecutionLatencyMs | End-to-end
latency of one logical Action execution, including asynchronous waits and
continuations. | Histogram |
+| **Action** | action.\<action_name\>.numOfPendingActionTasks | Current number
of physical Action task segments waiting to run, including continuations. |
Gauge |
+| **Action** | action.\<action_name\>.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
+
+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 |
+|-------|---------|-------------|------|
+| **Model Resource** |
action.\<action_name\>.model_resource.\<resource_name\>.numOfLlmCallsSucceeded
| The number of framework-observed model invocations that returned
successfully. | Count |
+| **Model Resource** |
action.\<action_name\>.model_resource.\<resource_name\>.numOfLlmCallsFailed |
The number of framework-observed model invocations that failed. | Count |
+| **Model Resource** |
action.\<action_name\>.model_resource.\<resource_name\>.llmCallLatencyMs |
Latency of each framework-observed model invocation, excluding
structured-output parsing and retry wait time. | Histogram |
+| **Model Resource** |
action.\<action_name\>.model_resource.\<resource_name\>.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.\<action_name\>.model_resource.\<resource_name\>.retryWaitSec | The
total backoff time, in seconds, accumulated when `ErrorHandlingStrategy.RETRY`
is configured. Only recorded when at least one retry occurs. | Count |
+| **Tool** | action.\<action_name\>.tool.\<tool_name\>.numOfToolCallsSucceeded
| The number of successful calls to the Tool. | Count |
+| **Tool** | action.\<action_name\>.tool.\<tool_name\>.numOfToolCallsFailed |
The number of failed calls to the Tool. | Count |
+| **Tool** | action.\<action_name\>.tool.\<tool_name\>.toolCallLatencyMs |
Time spent invoking the individual Tool, excluding time waiting for other calls
in the same parallel batch. | Histogram |
+| **Skill** | action.\<action_name\>.skill.\<skill_name\>.numOfSkillLoads |
The number of terminal explicit `load_skill` calls attributed to the Skill,
regardless of outcome. | Count |
+| **Skill** | action.\<action_name\>.skill.\<skill_name\>.skillLoadLatencyMs |
Time spent invoking an explicit `load_skill` call. | Histogram |
+| **MCP Server** |
action.\<action_name\>.mcp_server.\<server_name\>.numOfMcpToolCallsSucceeded |
The number of successful Tool calls served by the MCP Server. | Count |
+| **MCP Server** |
action.\<action_name\>.mcp_server.\<server_name\>.numOfMcpToolCallsFailed | The
number of failed Tool calls served by the MCP Server. | Count |
+| **MCP Server** |
action.\<action_name\>.mcp_server.\<server_name\>.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. 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, 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.
Review Comment:
This sentence is not true for Python's sequential path. There,
`_record_call_completion` catches the persistence error and only logs a warning
(`flink_runner_context.py:786-796`, reached from `:973` and `:1012`). The call
is then reported as succeeded. Python uses that path for every single-call
request (`tool_call_action.py:133`). Java and the Python parallel path do turn
it into a failure (`RunnerContextImpl.java:644`,
`flink_runner_context.py:1149-1150`). The runtime behavior is not new, only the
sentence is. The clause at `:63` ("including failures during result
persistence") has the same issue.
Which fits better: scoping the sentence to Java and the Python parallel
batch, or dropping the persistence clause in both places?
##########
docs/content/docs/operations/monitoring.md:
##########
@@ -36,11 +36,62 @@ 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.\<action_name\>.numOfActionsExecuted | The total number
of actions this operator has executed for a specific action name. | Count |
| **Action** | action.\<action_name\>.numOfActionsExecutedPerSec | The number
of actions this operator has executed per second for a specific action name. |
Meter |
+| **Action** | action.\<action_name\>.actionSchedulingLatencyMs | Time from
enqueuing the initial Action task until it is selected for execution. |
Histogram |
+| **Action** | action.\<action_name\>.actionExecutionLatencyMs | End-to-end
latency of one logical Action execution, including asynchronous waits and
continuations. | Histogram |
+| **Action** | action.\<action_name\>.numOfPendingActionTasks | Current number
of physical Action task segments waiting to run, including continuations. |
Gauge |
+| **Action** | action.\<action_name\>.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.\<action_name\>.model_resource.\<resource_name\>.numOfLlmCallsSucceeded
| The number of framework-observed model invocations that returned
successfully. | Count |
+| **Model Resource** |
action.\<action_name\>.model_resource.\<resource_name\>.numOfLlmCallsFailed |
The number of framework-observed model invocations that failed. | Count |
+| **Model Resource** |
action.\<action_name\>.model_resource.\<resource_name\>.llmCallLatencyMs |
Latency of each framework-observed model invocation, excluding
structured-output parsing and retry wait time. | Histogram |
+| **Model Resource** |
action.\<action_name\>.model_resource.\<resource_name\>.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.\<action_name\>.model_resource.\<resource_name\>.retryWaitSec | The
total backoff time, in seconds, accumulated when `ErrorHandlingStrategy.RETRY`
is configured. Only recorded when at least one retry occurs. | Count |
+| **Tool** | action.\<action_name\>.tool.\<tool_name\>.numOfToolCallsSucceeded
| The number of successful calls to the Tool. | Count |
+| **Tool** | action.\<action_name\>.tool.\<tool_name\>.numOfToolCallsFailed |
The number of failed calls to the Tool. | Count |
+| **Tool** | action.\<action_name\>.tool.\<tool_name\>.toolCallLatencyMs |
Tool call latency. | Histogram |
Review Comment:
Yes, this fixes it. Each call now has its own start and finish time, on the
parallel and sequential paths in both languages and on Java's serial fallback.
One gap: no test checks that a call which finishes early reports its own
finish time. If `tool_call_action.py:342` always used `result_observed_at`, a
fast tool would report the batch's end again, and all 35 tests in
`test_tool_call_action.py` would still pass. The success test only checks
finish >= start (`test_tool_call_action.py:940-942`). Java's success test has
the same `>=` check (`ToolCallActionReportTest.java:120-121`). Would it be
worth adding a mocked-clock test with two parallel calls, where one finishes
early, that asserts its finish is its own time rather than the batch time?
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
