Izzet Yildirim
Notes

Tracing an LLM agent from its reasoning down to the system calls

·9 min read

An agent run happens in two places. In the harness, the model decides what to do next and asks for a tool. Then the tool runs as a process of its own and touches the machine: it opens files, reads them, allocates memory. Decisions and effects are written by different processes, so they are easy to look at separately and hard to look at together.

This note traces both for one small agent, then grows the data it works on to see which layer explains what. It is one agent, one model, and one task, so it describes what these traces show, not agents in general.

The agent

The agent is a plain tool-calling loop of about a hundred lines of Python. The model is bonsai-27b, a 27B reasoning model that LM Studio serves on my laptop. A reasoning model thinks before it answers, and the API reports those thinking tokens separately. The agent and its tools run in WSL2 (Ubuntu 24.04, 8 cores, 8 GB).

It has three tools: list_dir, read_file, and run_python, which runs code in a subprocess and returns what it prints. The task is a folder of 12 sensor logs, CSV files with the columns t, temp, and pressure, where one sensor drifts 1.5 °C warm. The question is which file has the highest mean temperature. The answer is sensor_07.csv.

At temperature 0 the agent did the same thing in every run I made, more than fifty of them. It lists the folder, writes one program that computes every file’s mean, runs it, and answers. The core of that program is a loop that reads each file with pandas:

for filename in sorted(os.listdir(data_dir)):
    if filename.endswith('.csv'):
        filepath = os.path.join(data_dir, filename)
        df = pd.read_csv(filepath)
        mean_temp = df['temp'].mean()
        ...

Install

pip install --pre dftracer pydftracer dftracer-analyzer

The agent spans are new, so for now they are only in pre-release builds. I ran dftracer 2.2.0.post8.dev0, pydftracer 2.0.6.post2.dev0, and DFAnalyzer 0.0.9.post61.dev0.

Annotate the loop

DFTracer’s agent spans give the loop standard names: workflow, agent_step, llm, and tool. Here is the loop with the chat request, the tool dispatch, and the IDs left out:

from dftracer.python import dftracer
from dftracer.python.agent_init import agent_step, llm, tool, workflow

log = dftracer.initialize_log(None, None, -1)  # paths come from DFTRACER_* variables

with workflow.run(args={"workflow_id": wf, "model_name": MODEL}):
    for step in range(MAX_TURNS):
        with agent_step.plan(args={"step": step, ...}):
            with llm.call(args={"step": step, "model_name": MODEL, ...}) as span:
                resp = chat(messages)
                span.update_args({
                    "prompt_tokens": usage["prompt_tokens"],
                    "completion_tokens": usage["completion_tokens"],
                    "reasoning_tokens": usage["completion_tokens_details"]["reasoning_tokens"],
                })
        if not tool_calls:
            break
        with agent_step.act(args={"step": step, ...}):
            for call in tool_calls:
                run_tool(call, step)  # opens a tool.call span around the process
        with agent_step.observe(args={"step": step, ...}):
            messages.extend(tool_results)

log.finalize()
  • Every span carries a span_id and a parent_span_id, so the tree can be rebuilt, and a step, the turn number, which groups the spans of one turn.
  • The model span gets its token counts after the response arrives, with update_args. Reasoning tokens are the part of the output the model spent thinking.
  • Annotate what you want a duration for. Appending a message takes microseconds and gets no span.

Capture the calls

The spans come from the harness. The calls come from somewhere else: each tool runs as a process of its own, with DFTracer preloaded, and writes its own trace file.

env = {
    **os.environ,  # start from the harness's variables, then override
    "DFTRACER_INIT": "PRELOAD",
    "DFTRACER_DISABLE_IO": "0",
    "DFTRACER_ENABLE_AGGREGATION": "0",  # one event per call
    "DFTRACER_LOG_FILE": f"{out_dir}/tool_trace_{name}_{step}_{k}",
    "DFTRACER_DATA_DIR": data_dir,
    "LD_PRELOAD": preload_lib,  # libdftracer_preload.so, inside the dftracer package
}
done = subprocess.run(cmd, env=env, cwd=data_dir, capture_output=True, text=True)

The tool gets its own copy of the environment, so the harness keeps its settings and LD_PRELOAD never reaches it.

The harness itself records only spans:

DFTRACER_ENABLE=1 \
DFTRACER_INIT=FUNCTION \
DFTRACER_DISABLE_IO=1 \
DFTRACER_LOG_FILE=traces/run/harness_trace \
DFTRACER_DATA_DIR=data-task \
  python agent.py traces/run data-task
  • DFTRACER_DATA_DIR lists the paths whose calls get traced, here only the data folder. With all instead, list_dir made 1,194 calls instead of 23, almost all of them the interpreter starting up.
  • DFTracer intercepts a fixed set of libc functions: opens, reads, directory and memory calls, and so on. That is not every system call, and it doesn’t see network traffic. The model call is only a span.

Every run reads its data cold. Before the loop starts, I evict the 12 files from the page cache (posix_fadvise with DONTNEED) and check that under 5% of them is still in memory. I also throw away the first run at each size, because WSL2 releases its cache while idle.

What the trace looks like

A run leaves one file for the harness and one for each tool call. Here are two kinds of lines from the run with 16 MiB of data, trimmed to the interesting keys:

{"name":"call","cat":"llm","pid":1362,"ts":1793115114848617,"dur":6723460,"args":{"step":1,"model_name":"prism-ml/bonsai-27b","prompt_tokens":631,"completion_tokens":226,"reasoning_tokens":47,"total_tokens":857,"finish_reason":"tool_calls"}}
{"name":"call","cat":"tool","pid":1362,"ts":1793115121572429,"dur":552811,"args":{"step":1,"tool_name":"run_python"}}
{"name":"open64","cat":"POSIX","pid":1377,"ts":1793115121880903,"dur":5,"args":{"fhash":"2b34caa450ed73cb"}}
{"name":"read","cat":"POSIX","pid":1377,"ts":1793115121881017,"dur":983,"args":{"ret":262144,"count":262144,"fhash":"2b34caa450ed73cb"}}
  • The first two are in the harness’s file. The model call took 6.7 s and carries its token counts. The tool call took 0.55 s.
  • The last two are in run_python’s own file: an open, and a read of 262,144 bytes that took 0.98 ms. pandas reads in 256 KiB chunks, which is why the number of reads below follows the size of the data. ts and dur are in microseconds, and the calls’ timestamps fall inside their tool span’s window.

The agent’s side

The spans alone already tell the story of the run. This is the run with 16 MiB of data, built from the harness’s file only:

Step Model Tokens in Tokens out Reasoning Tool Tool time
0 4.3 s 486 131 93 list_dir 0.04 s
1 6.7 s 631 226 47 run_python 0.55 s
2 2.9 s 1,024 77 69 — —
One run of the agent, 16 MiB of dataModellist_dirModelrun_pythonModelStep 0Step 1Step 200 s01 s02 s03 s04 s05 s06 s07 s08 s09 s10 s11 s12 s13 s14 s

The run took 14.5 s, and the model calls took 14.0 s of it, 96%.

  • The model is the run. It generates about 30 tokens per second here, so 226 tokens take 6.7 s.
  • The prompt grows. 486, 631, then 1,024 tokens, because every step sends the whole conversation again, now with the tool’s output in it.
  • Thinking is a visible share of the output. 93 of the 131 tokens in step 0, 47 of 226 in step 1, 69 of 77 in step 2.

While the model thinks, nothing touches the machine, and while a tool runs the model waits. That idle time is what the AgentStage note puts to use.

The machine’s side

The same run, from the tool processes’ files. Each row is one tool call:

Step Tool Calls Data Metadata Other Moved POSIX
0 list_dir 23 0 17 6 0 0.2 ms
1 run_python 669 96 182 391 16 MiB 17 ms

Data calls are reads and writes. Metadata calls are opens, closes, stats, seeks, and directory reads. Other is mostly memory management (mprotect, munmap) and path lookups (getcwd, stat64). Moved is the bytes the data calls carried, and POSIX is the time spent inside all of them.

A tool is a program, not an operation: the one-line list_dir is 23 calls, and the pandas script makes 669 for 12 small files. And the calls are cheap. All 669 took 17 ms together, in a tool step of 553 ms. They are spread across the whole step, so the process isn’t idle between them. It is computing, parsing CSV, and that doesn’t show up as a call.

DFAnalyzer’s auto preset gives the same picture with no code from me:

dfanalyzer analyzer/preset=auto trace_path=traces/run cluster=none
Layer               Time (s)    Ops   Size (MiB)
workflow            14.548      1
step                14.547      7
llm                 13.953      3
tool                 0.593      2
posix, data folder  0.015    295       16
posix, other        0.002    397

DFAnalyzer sorts POSIX calls by path, not by type. Every call on a file under a /data path, which includes the data folder here, goes to one layer, and the calls without such a path, mostly memory management and lookups, go to the other. That is a different split from the table above. It also groups all steps together, so it can’t give the per-step table.

Growing the data

Now one knob: the size of the data. I made two more datasets, 16 and 256 times the original, 256 MiB and 4 GiB in total over the same 12 files. The folder keeps its name, so the prompt is identical, and the model wrote the same program at every size. I ran each size three times, cold.

Total data Tool step Share of the run Calls POSIX
16 MiB 0.58–0.60 s 4% 669 17–36 ms
256 MiB 1.93–2.41 s 12–15% 1,641 213–268 ms
4 GiB 27.1–30.4 s 67–69% 16,233 2.5–3.9 s

The model’s time doesn’t move, 13.5–14.5 s at every size, because it never sees the data, only what the program prints. The tool step goes from 0.6 s to 27–30 s, and its share of the run from 4% to about 68%. Somewhere between 256 MiB and 4 GiB it overtakes the model. The spans alone show the whole transition:

One run of the agent, 4 GiB of dataModellist_dirModelrun_pythonModelStep 0Step 1Step 200 s05 s10 s15 s20 s25 s30 s35 s40 s

The calls scale exactly with the data, and the bytes moved were the size of the files. But the calls explain a minority of the step: about 3%, 11%, and 9–13% of it. The rest is pandas parsing CSV, at about 160 MB/s here, against storage that reads at about 1.2 GB/s, and no call shows that. This is the lesson of the earlier note on deep learning I/O again: a call trace alone reports a small number, and the layer above it says what the rest is made of. DFAnalyzer’s layers agree. For the 4 GiB run it reports 27.894 s for tool and 2.7 s for the POSIX calls. By this arithmetic, the calls would dominate only on storage slower than the parser, below roughly 160 MB/s. I didn’t measure that.

What I take from it

  1. Annotate the loop with spans first. They alone gave the picture of the run: 96% model time at 16 MiB, a prompt that grows each step, and thinking as a measurable share of the output.
  2. Run each tool as its own traced process, so its calls land in a file of their own.
  3. Use the calls for what a tool did to the machine. They count exactly, but they explained only 3–13% of the tool step’s time here.
  4. Run your own size sweep. Where the tool overtakes the model depends on your tool and your storage. Here it was between 256 MiB and 4 GiB.

Open questions

It was easy to line the calls up with the steps here. The step is in the file name, and a tool’s calls sit inside its span’s time window. Neither is general. With parallel tool calls, several agents, or a tool that starts processes of its own, neither says which step caused a call.

How should a tracer attribute a call to the agent step that caused it? And what should the call-level view of an agent measure, so that it explains more than a tenth of the step? The spans gave the story of the run, and the calls gave the detail. Joining the two is what’s left.