Building a Production AI Agent in Spring Boot: Observability for Tool Calls and Latency (Part 4)

"The same question took forty seconds today. Last week it took ten."

The tester from Parts 2 and 3 again. She asked the agent "can I return the blue jacket from my last order?" That question needs two tool calls: one to find the order, one to read the return policy. Last week it took about ten seconds. That day it took forty.

Nothing had changed. No release, no config change, no new data. The code had not been touched in a week.

And I could not explain it, because I had no number for any single step. I had logs, but they were a wall of text from the HTTP layer. I could not say whether the extra thirty seconds went into the memory advisor, the first model call, the order lookup, the policy lookup, or the final model call. When you cannot say where the time went, you cannot fix it. The easiest conclusion is "the model is bad," which is usually the wrong one.

Later that week the agent answered a different question badly. "Show me blue jackets" returned sweaters. I blamed the model again. It turned out the model had picked the semantic search tool for a keyword query, and the semantic path is fuzzy by design. I only learned that after I could see which tool ran, with which arguments, in which order.

Both answers were inside my application the whole time. This part of the series makes them visible.

I am a Senior Software Engineer II at BS23 in Dhaka, and I have been building production AI agents with Spring Boot and Spring AI for over a year. Everything below is what I added to the same agent from Parts 1, 2, and 3 (tools, memory, streaming). No new behavior. Just visibility.

Why an Agent Call Is Not One Request

A normal REST call is one request, one response, one duration you can measure. An agent call is a chain. For that two-tool question, the sequence is:

• prompt assembly plus the memory advisor from Part 2
• a model call that decides to use tools
• tool call 1: look up the order
• tool call 2: read the return policy
• a second model call that writes the answer

Any link in that chain can be slow. Any link can be wrong. The user sees one result, and you need to see every step.

Spring AI instruments these steps for you. From the observability reference, Spring AI records metrics and traces for its core components: ChatClient (including advisors), ChatModel, EmbeddingModel, and VectorStore. Tool calls get their own observations as well. Most of what I did in this part was wiring, not writing.

Two terms before the code. A trace is the full chain of spans for one user question. A span is one step in that chain, with a name, a duration, and attributes. An observation is the named measurement that produces metrics and spans. When you see gen_ai. in the names below, that is the standard naming used across AI tooling.

Metrics First: The Numbers You Already Have

The cheapest step is the one where Spring AI does the measuring and you only add the plumbing. Two dependencies in the pom.xml:

<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-actuator</artifactId>
</dependency>
<dependency>
    <groupId>io.micrometer</groupId>
    <artifactId>micrometer-registry-prometheus</artifactId>
</dependency>

And one block in application.yml to expose the endpoint:

management:
  endpoints:
    web:
      exposure:
        include: health,info,prometheus

By default Spring Boot exposes only /actuator/health over HTTP. The include line above also exposes the Prometheus scrape endpoint, which requires the micrometer-registry-prometheus dependency (the Spring Boot actuator docs confirm both details).

Scrape /actuator/prometheus and you will find the Spring AI series. The three I actually watch:

• gen_ai_chat_client_operation_seconds_* - the whole call or stream, from prompt to final answer. Has a spring_ai_chat_client_stream label so you can compare sync vs streaming calls.
• gen_ai_client_operation_seconds_* - the model provider execution itself.
• gen_ai_client_token_usage_total - tokens, labeled by gen_ai_token_type as input, output, or total.

There is a fourth for retrieval: db_vector_client_operation_seconds_* covers vector store adds, deletes, and queries, with a db_system label (mine says simple, the in-memory store).

Timers appear in Prometheus with the standard suffixes. _seconds_sum and _seconds_count give you average latency by division, _seconds_max is the high-water mark, and _active_count is the number of calls in flight right now. The reference documentation spells this out, including the formula that average latency is sum / count.

The queries I keep in a scratch file:

# requests per second to the model provider
rate(gen_ai_client_operation_seconds_count[5m])

# average model latency
gen_ai_client_operation_seconds_sum / gen_ai_client_operation_seconds_count

# tokens by direction, per minute
sum(rate(gen_ai_client_token_usage_total[5m])) by (gen_ai_token_type)

What the numbers told me on my setup: the tools were never the bottleneck. The database-backed tools (searchProducts, getProductDetails, viewCart) are a few milliseconds each. The semantic search tool is the one exception, because SimpleVectorStore embeds the query before it searches, it carries a model call of its own. Everything else in those ten to twelve seconds was the model, twice. Streaming from Part 3 is what the user feels; these metrics are what the bill actually is.

The token series is the one that pays for itself. Watch input tokens: with the memory advisor prepending history, input tokens climb with every turn of a conversation. That is the concrete argument for the sliding window from Part 2, and it is the number to show before a cost discussion, not after.

Traces: Which Tool, How Long, With What Arguments

Metrics tell you the agent is slow. Traces tell you which step. For that I added OpenTelemetry tracing, the setup the Spring Boot tracing docs describe:

<dependency>
    <groupId>io.micrometer</groupId>
    <artifactId>micrometer-tracing-bridge-otel</artifactId>
</dependency>
<dependency>
    <groupId>io.opentelemetry</groupId>
    <artifactId>opentelemetry-exporter-otlp</artifactId>
</dependency>

Point the exporter at any OpenTelemetry collector (Jaeger and Grafana Tempo both speak OTLP) with the management.opentelemetry.tracing.export.otlp.* properties. One more thing to set deliberately: sampling. Spring Boot samples 10 percent of requests by default to protect the trace backend. That is fine until you are chasing one specific conversation, and then you raise management.tracing.sampling.probability or filter in the collector.

The trace of that two-tool question is a tree, and every node is documented in the observability reference:

• the spring.ai.chat.client span at the root covers the whole call, and it carries the conversation id (spring.ai.chat.client.conversation.id) plus the list of tool names as attributes. I can search one conversation's entire trace.
• spring.ai.advisor spans cover the memory advisor from Part 2, so history loading and saving are timed separately.
• gen_ai.client.operation spans cover each model call, with the model name, temperature, and token usage as attributes.
• each tool call produces a spring.ai.tool span. The tool name is a first-class attribute (spring.ai.tool.definition.name), the operation is execute_tool, and the span measures the time the tool took to complete. This is where "the model called the wrong tool" stops being a feeling and becomes a line in a trace.

One switch to know about: spring.ai.tools.observations.include-content. Set it to true and the tool span also carries the input arguments and the result. For a shopping agent that means shipping addresses and cart contents. I keep it off in production and turn it on in a dev profile when I am debugging one specific call. The docs warn about exactly this, and they are right.

The same caution applies to the prompt logging switches: spring.ai.chat.client.observations.log-prompt and spring.ai.chat.observations.log-completion write the full prompt and completion into the logs. They default to false for good reason. Dev profile only.

One documented quirk to expect: for OpenAI and Anthropic, the HTTP span of a streaming call is not parented under the model span. The SDK's async streaming path hops onto a shared thread pool before it reaches the HTTP client, so the observation context is dropped at that boundary, and the HTTP span shows up as a separate root span. The docs tie this to the OpenAI and Anthropic providers specifically. My agent runs Ollama today, but the tutorial's hardening list says the model provider is a swap away, and when I make that swap I will know not to chase that orphan span as a bug.

Structured Logs: The Cheap Layer the Framework Skips

Traces are what you open when something is wrong. Logs are what you search at 3 a.m. with one grep. Spring AI logs HTTP and model events at INFO, but it does not log the agent loop: which tool ran, in what order, for how long. I added that myself, in the user-controlled tool loop from Part 3:

long requestStart = System.nanoTime();

while (true) {
    // ... stream and aggregate as in Part 3 ...

    if (response.chatResponse() == null || !response.chatResponse().hasToolCalls()) {
        break;
    }

    sendStatus(emitter, "Running a tool...");

    long start = System.nanoTime();
    ToolExecutionResult result = toolCallingManager.executeToolCalls(prompt, response.chatResponse());
    long tookMs = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - start);

    log.info("event=tool_call conversationId={} tookMs={}", conversationId, tookMs);

    prompt = new Prompt(result.conversationHistory(), chatOptions);
    ref.set(null);
}

log.info("event=agent_reply conversationId={} tookMs={}",
        conversationId, TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - requestStart));

Key=value lines, one idea per line, greppable by conversation id. What it looks like in practice:

event=tool_call conversationId=8f3ac1f tookMs=41
event=tool_call conversationId=8f3ac1f tookMs=12
event=agent_reply conversationId=8f3ac1f tookMs=10430

Two choices in that snippet are deliberate. I log the conversation id, not the message content. And I log durations, not arguments. The arguments of a checkout tool are a shipping address, and I do not want those in my log aggregation. If I ever need them, the trace has them behind the include-content switch, per call, in development.

This is the layer that answered the forty-second question for me. The numbers were finally in one place, per step, per conversation. I could see that the model call was the line item, and I could stop guessing.

What the Numbers Changed

Three things happened once the numbers were in, none of which I predicted.

The blame moved off the tools. Every time a user said "slow," I opened the model span first. The tool spans were never the story. That changed how I debug, and it changed how I talk to non-technical stakeholders: the agent's latency is the model's latency, and the fixes are the ones from Parts 2 and 3 (memory windows, streaming, status events).

A wrong-tool bug became visible in minutes. The trace showed semanticSearchProducts firing on keyword queries like "blue jacket", where searchProducts with a filter was the right call. The semantic path then returned fuzzy matches, which is what produced the sweaters. The fix was not a code change. It was prompt engineering: I rewrote the tool descriptions to say when to use each one and when not to. The tools reference is explicit that the model picks tools from their descriptions, and the current descriptions in the project reflect that lesson: "use this when the shopper gives concrete criteria such as a keyword" versus "use this for vague or vibe-based requests". Without the trace, that diagnosis takes a week and ends in "the model is dumb."

The token metric made memory cost concrete. Input tokens climb as a conversation ages, because history gets prepended every turn. That single series justified the sliding window cap from Part 2 with a number, and it is the number to watch before anyone argues about inference cost.

One Alert, Then Stop

It is easy to spend a week building dashboards. I stopped at one alert, the one that would have caught the forty-second answer:

- alert: AgentReplySlow
  expr: rate(gen_ai_chat_client_operation_seconds_sum[5m])
        / rate(gen_ai_chat_client_operation_seconds_count[5m]) > 30
  for: 5m

That is the average ChatClient duration over the last five minutes (the sum / count average from the docs, expressed as rates so it is a moving window). Thirty seconds is triple my normal answer time, so it fires early enough to matter and rarely enough to be heard. Tool failures surface in the error path of the observations and in the exception logs; when this agent gets real traffic, I will add a failure-rate alert, and not before.

The Observability Checklist

If you take nothing else from this part, take this list:

• Add actuator and the Prometheus registry before you need them. Two dependencies and a few lines of config. The first incident will not wait for you.
• Know the series names. Chat client (whole call), model (provider), token usage (cost), vector store (retrieval).
• Use metrics and traces together. Metrics answer "is it slow right now". Traces answer "which step, which tool". They are not interchangeable.
• Keep tool arguments out of production traces. spring.ai.tools.observations.include-content stays off in production, on in development.
• Log the agent loop yourself. Conversation id and duration per step, key=value format. The framework does not do it for you.
• Set sampling deliberately. Ten percent is the Spring Boot default and it is fine until you are chasing a specific conversation.
• Expect the orphan HTTP span on streaming. When you move to OpenAI or Anthropic, the streaming HTTP span is not parented under the model span. Documented behavior, not a bug.
• Alert on one latency number before you build any dashboard.

What Comes Next

I planned to fit the multi-agent pattern into this part, and it did not fit. Part 5 covers the pattern where one agent delegates to another: a supervisor that hands a task to a specialist agent and waits for the result, and how to keep that chain observable the same way.

Have you traced your agent's tool calls? What was the first thing you found that you did not expect? I read every response.

I write about Java, Spring Boot, and AI agents every week. Subscribe, it's free. Part 5 goes out soon.

If this was useful, bookmark it. The checklist at the end is the part you will reach for when the agent is slow and the logs are quiet.