43 seconds to 8: what one trace of an AI analyst agent showed us

We build an analyst agent for a travel and fintech group. A business user types a question, the agent writes read-only SQL against a governed warehouse, and a short answer comes back. The data platform and the agent run on a staging environment; this post is about the agent, and about one afternoon spent reading a single trace of it.

The question was a short one: how were sales for one product line yesterday. On one traced question, the answer took 43.5 seconds, ran three queries and consumed 137,040 tokens. After four changes (and a narration model swap, described below), the same question took 8.3 seconds, ran one query and cost about 2.1k full-price input tokens. All of those figures are from one traced question. They are not a benchmark, they are not an average, and we have not run the before and after versions across a question set. What they are is a worked example of what a trace can show you that logs cannot, and of four causes that each look obvious once you can see them.

We found these problems by reading that trace ourselves. No alert or automated check flagged them.

The constraints that shaped what we could change

An agent loop has properties that decide which fixes are available. These came first, and two of them turned out to decide the whole outcome.

Constraint	Consequence for the fix
The model, not our code, decides how many queries to run	The step count is a property of the prompt, not of the graph
A checkpointer stores the whole message list and replays it on every later turn	Anything the model writes is shown back to it, every turn, for the life of the conversation
Every call in a turn re-sends the system prompt, and ours is large	Anything identical across calls is a candidate for caching
Prompt caching only pays when the cached prefix is byte-identical	Any edit to earlier messages, even a harmless one, can throw the cache away
The tool API requires every tool call to keep its matching tool result	We can shrink a message but not delete one

The agent is a bounded tool-calling loop on LangGraph, with the default recursion limit of 25 as the backstop. The loop’s own text is hidden from the user; only the narration step streams. A planning model reads the question and calls run_sql. When it stops calling tools, a deterministic step shapes the last result into a table or chart, and a separate narration step writes two to four sentences. At the time of the trace the planner was a Sonnet-class model on Bedrock and narration ran on the same model.

The system prompt holds the rules, a data dictionary built from Postgres comments, and a library of verified example queries. The last two are about 21k tokens (20,910 measured from cache on a warm call) and do not change between calls.

What we could see, and why it was one trace

Reading a trace requires one trace per turn. Our first instrumentation attached the Langfuse callback to the model factory, so one question produced four flat, unrelated traces. We moved the handler to the graph invocation, where LangGraph propagates it through every node. A turn is now one trace with nested observations: each planning call with the exact prompt it saw, each run_sql call with its SQL and result preview, and the narration call, with token counts and latency.

With four flat traces, 43.5 seconds (on one traced question) is a number. With one nested trace it is a timeline you can read.

Symptom

On that one traced question, the timeline showed the planner calling run_sql three times: a daily summary, then top products, then a country breakdown. Each call was a full round trip to the model with the whole conversation attached. The loop ended with a long markdown report, which the narration step then summarised in a few sentences. Total: 43.5 seconds and 137,040 tokens for a question whose answer was a headline figure.

The agent was not failing. It was slow and expensive in a way an error log would never mention.

The tempting guess

A 43-second answer invites an infrastructure explanation: a slow model region, a cold connection, a heavy query. The trace pointed elsewhere. The time was spent in three rounds of the loop, each a model call carrying the whole conversation, plus a long final report. It was a volume problem: too many calls, each carrying too much. Four separate things made it so.

Cause 1: the prompt invited a report

The system prompt said, in so many words, to run more than one query when it helps: explore, verify a number, combine results. The docstring on the run_sql tool repeated the invitation. For a question about yesterday’s sales the model ran a summary, a breakdown by product and a breakdown by country.

The edit was to the wording, not the loop. The prompt now says, in abridged and edited form (wording lightly rewritten, identifying example removed):

Answer the question that was asked, at the scope it was asked. Match the
size of the answer to the size of the question; a one-line question gets
a one-line answer, and a request for a report gets a report. Do not
volunteer extra dimensions the user did not ask for.

Default to ONE query: write the single aggregate that answers the question
and stop. Run another only when the question genuinely spans more than one
result, when a number needs verifying, or to correct a query that errored.
Each extra query costs the user seconds of latency and resends the whole
conversation, so it has to earn its place.

The tool docstring changed to match.

The last sentence tells the model something it had no way to know: each extra query resends the whole conversation.

Cause 2: the agent was teaching itself to write reports

This was the least obvious cause. When the loop stops calling tools, the planning model tends to write a closing report, even though the prompt tells it not to. Nothing reads that text. The deterministic step uses the stored result and the narration step writes the answer the user sees. The loop’s own text is also suppressed from the stream.

The checkpointer, though, keeps every message. So the closing report from turn one is replayed into turn two, and the report from turn two into turn three. That wastes several hundred tokens per turn, but the bigger effect is on behaviour. After three turns whose transcripts each ended in a long report, a one-line question got a report too. The conversation itself was few-shot teaching the model to over-answer.

Our fix is to throw the text away at the point it is produced, and keep the message (excerpt abridged, comment condensed):

# When the agent stops calling tools it tends to write a full report that
# nothing reads. The checkpointer would replay it forever and it teaches the
# model, by example, to write reports. Keep the message (tool-call pairing
# and sequence stay intact) but replace the text.
if not getattr(resp, "tool_calls", None):
    resp = resp.model_copy(update={"content": "(done querying)"})

The message stays so tool pairing and the message sequence are untouched. Only the lesson goes.

Cause 3: an uncached prefix, about 21k tokens, paid for on every call

The data dictionary plus the example library is identical on every call. In a loop that makes several model calls per turn, and then more on every later turn, the same 21k tokens were re-sent at full price each time. The loop alone resends it four or five times in a single turn, by our own estimate in the code comment.

The fix is a cache point at the end of the static block (abridged, as at the time of the trace, on Bedrock):

def _system_message(text: str) -> SystemMessage:
    """System prompt with a cache point after the whole static block."""
    return SystemMessage(content=[{"text": text}, {"cachePoint": {"type": "default"}}])

On a warm call the trace reported 20,910 tokens served from cache. We expect cache reads to cost about a tenth of regular input, which is the estimate in our own code comment; we have not measured the invoice and do not quote a cost figure here.

The cache point only helps if the prefix is byte-stable, and two things protect that. The temporal block in the prompt, which tells the model today’s date, is date-only. If it ever grew a clock time, the prefix would change on every request and the hit rate would fall to zero without any error. And the cache point sits after the whole static block and before the conversation, so everything that varies is outside the cached part. We also verify with the usage metadata: a warm call should report cache-read tokens, not input tokens.

When we later moved to the direct Anthropic API, the cache point became a cache_control marker on the same block, and a warm cache read was confirmed again.

Cause 4: old tool results never shrank

The fourth cause was history again. A tool result for a 30-row query is a few thousand tokens of JSON, and it never left the conversation. The model needs to remember that it ran a query and roughly what came back, not the whole grid. Our code comment puts a four-turn conversation at about 16k tokens of stale query output re-sent on every call.

The fix truncates tool results from previous turns to 240 characters and leaves the current turn untouched (simplified from the original: docstring and type hints removed):

_STALE_TOOL_CHARS = 240

def _trim_history(messages):
    cut = 0
    for i, m in enumerate(messages):
        if getattr(m, "type", None) == "human":
            cut = i            # the last human message is the turn boundary
    out = []
    for i, m in enumerate(messages):
        content = getattr(m, "content", None)
        if (i < cut and getattr(m, "type", None) == "tool"
                and isinstance(content, str) and len(content) > _STALE_TOOL_CHARS):
            out.append(m.model_copy(update={
                "content": content[:_STALE_TOOL_CHARS] + " ...[earlier result truncated]"}))
        else:
            out.append(m)
    return out

Only the content of tool messages is rewritten, never the message itself. The tool API requires every tool call to keep its matching result, so dropping a message would make the request invalid rather than smaller.

The sliding-window trap

The natural way to bound history is a sliding window: trim anything more than N messages back. It is the first design most people reach for, and by our reasoning, for caching it is the wrong one.

A cached prefix has to be identical from one call to the next. In an agent loop, every call appends a message. If trimming is anchored to a position counted from the end, then each appended message moves the window, which rewrites part of the earlier messages, which changes the bytes of the prefix, which invalidates the cache on every call. By our reasoning, you pay to write the cache each time and read it never, which would cost more than not caching, and no error is raised.

So the boundary is the last human message. Within one turn the loop appends messages after that point and nothing before it changes. The prefix is byte-stable for the whole turn. Previous turns are trimmed once, at the turn boundary, and are then constant.

We should be honest about the status of this argument. The trap is reasoned from how the cache behaves, and our commit message says a sliding window “would have” invalidated the cache on every call. We did not build the sliding-window version, measure it, and compare. It is the reason for the design, not a measured result.

The fix, and what the trace said afterwards

The same commit also moved narration to the smaller model and removed temperature=0, which newer models reject outright. Those are outside the four causes, and we have not isolated their effect on the numbers below.

The four changes landed in one commit. We then asked three questions in sequence on one thread against the staging warehouse, and compared the answers to the warehouse directly.

Turn on one thread	Time	Queries	Matched the warehouse
A this-year profit question	10.2 s	1	Yes
The original question (sales yesterday), on one traced question	8.3 s	1	Yes
A follow-up: “and the day before?”	9.2 s	1	Yes, and it resolved against memory

Against the original trace, all figures on one traced question, not a benchmark or an average:

	Before	After
Time	43.5 s	8.3 s
Queries	3	1
Tokens (before: trace total; after: full-price input only)	137,040	about 2.1k full-price input tokens
Static prefix per call	about 21k tokens, full price	20,910 tokens from cache on a warm call

Two notes. The commit message states the token comparison as roughly 135k full-price input tokens down to about 2.1k, while 137,040 is the total for the trace; we use each as written. And the three turns in the first table are spot checks, not a sample. They say nothing about accuracy in general; we have no accuracy percentage.

The wrong number in the same trace

The same trace held a second problem that had nothing to do with tokens, and it is why we think reading traces pays for itself.

The agent anchors “today” and “yesterday” to a configured timezone, computed in code rather than guessed by the model. That timezone was the business’s local one, a few hours ahead of UTC. The warehouse’s date column is a UTC calendar date. For the hours each night between local midnight and UTC midnight, the agent’s calendar is a day ahead of the warehouse’s.

The question was asked late in the evening UTC, before the UTC day had ended. The agent resolved “yesterday” to the current UTC day, which was hours from over, and answered with a partial day’s figures, stated with full confidence and with nothing in the output hinting that the day was incomplete. The real previous day was about six times larger. A roughly 6x understatement, every night, for a few hours.

We found it by reading the trace, which shows the date range the agent resolved. No alert or automated check detected it.

The fix was to anchor the agent to UTC, which is what the date columns are in. If the business wants local-time days, the right place to change is the mart, by deriving the date column in local time from the source timestamp. Moving the agent’s setting alone would bring the skew straight back.

Lessons

Read the trace before you form a theory. The nested timeline with token counts per call is what separated four volume problems from a latency problem.

Treat the prompt as something the model obeys. “Run more than one when it helps” was written to be helpful. The same pattern showed up in a neighbouring commit: our configuration listed three schemas in the prompt while the read-only role could only see one, so the model was invited to write queries the database would refuse, and each one burned a retry that could never succeed. A prompt line is an instruction, including the careless ones.

History is training data for the next turn. If output is not needed, do not store it.

Pay for the prefix once, then design everything else around keeping it still.

Where it fails

• One trace is one trace. The headline figures are from a single question. We do not know how the before and after versions compare over a mixed set of questions, and we have not run that comparison. A question that genuinely needs three queries will still take three.
• One query by default can be too strict. For a question that spans two results, a model told to stop early may stop early. The three spot checks did not exercise that.
• The cache is only as stable as the prefix. The dictionary is built once per process and the cache lives briefly. The first call of each new turn also rewrites the truncated history, so only the static prompt block is guaranteed a hit at that point. A new deployment, a new mart or a changed description changes the bytes, and the first call after that pays full price. Caching also has a time-to-live, so a quiet hour means the next question rebuilds it.
• Truncating old results loses detail. A follow-up that needs a number from a result two turns back sees 240 characters of it. The model will usually rerun the query, which costs a call. We chose that trade deliberately, but it is a trade.
• The marker patches a habit. It stops the model learning to write reports, not writing them, which still costs output tokens.
• The timezone fix moves the problem. UTC days are correct against UTC columns, and wrong for a user who thinks in local days at 23:00. Moving the date column into local time in the warehouse is the real fix, and it has not been done.
• We have no scored evaluation yet. Spot checks against the warehouse are not an accuracy measure. A golden set of verified questions, run against the current agent, is the missing piece, and until it exists we will not put a percentage on this agent.

What we would tell another team

Trace each turn as one tree, count tokens per call and see which repeat, and check the resolved date range of any question that says yesterday. The numbers will not carry over to your system. The method will.

---

CloudGuys builds agents and the data foundations under them for startups and teams. Tell us what you are building.