Attribute Time and Tokens per Agent Step: Build a Trace Ledger Before You Optimize

A run fails at 2am. The trace has 41 tool calls and zero errors. The model was not slow. Your orchestrator was.

You cannot see that from totals. A 94-second run says nothing about which step ate 27 of those seconds. This article builds a small ledger that answers one question per run: where did the time and the tokens actually go?

The artifact is a single-file script. It reads a JSONL span trace, subtracts child time from parent time, and prints an exclusive-cost table. It is not a new tracing system. It is an accounting pass over traces you probably already record.

Totals hide the step that hurts

Most agent traces log a duration per span. Two traps follow.

• Nested spans double count. A tool.search span inside an llm.plan span inflates both rows. Sum the column and you exceed wall time.
• Retries look like one step. Three attempts under the same name read as a slow call, not a loop.

Exclusive time fixes the first trap. A step's exclusive time is its duration minus the duration of its direct children. Sum exclusive time across a well-formed tree and you get the root duration exactly. That identity makes shares trustworthy: the percentages sum to 100.

The span record you need

Five fields carry the whole analysis. Add them to whatever you already emit.

1. span_id — stable, unique within the run.
2. parent_id — null for the root span.
3. start_ms / end_ms — integers on one monotonic clock. Do not mix wall clocks per step.
4. input_tokens / output_tokens — zero for pure tool spans, if your provider reports nothing there.
5. name and status — stable names like llm.plan, tool.search, tool.write_file.

Keep the names boring and finite. Free-form names destroy grouping later.

{"span_id":"r1","parent_id":null,"name":"run","start_ms":0,"end_ms":94000,"input_tokens":1800,"output_tokens":600,"status":"ok"}
{"span_id":"s1","parent_id":"r1","name":"llm.plan","start_ms":100,"end_ms":4200,"input_tokens":1600,"output_tokens":420,"status":"ok"}
{"span_id":"s2","parent_id":"r1","name":"tool.search","start_ms":4300,"end_ms":31000,"input_tokens":0,"output_tokens":0,"status":"ok"}

The ledger script

Save as ledger.py. Standard library only. No install step.

#!/usr/bin/env python3
"""ledger.py - exclusive wall time and token attribution per agent step."""
import argparse
import json
import sys
from collections import defaultdict


def load(path):
    spans = []
    with open(path, encoding="utf-8") as fh:
        for line in fh:
            line = line.strip()
            if line:
                spans.append(json.loads(line))
    return spans


def duration(s):
    return max(0, s.get("end_ms", 0) - s.get("start_ms", 0))


def children_index(spans):
    idx = defaultdict(list)
    for s in spans:
        parent = s.get("parent_id")
        if parent:
            idx[parent].append(s)
    return idx


def exclusive(s, idx):
    child_ms = sum(duration(c) for c in idx.get(s["span_id"], []))
    return max(0, duration(s) - child_ms)


def tokens(s):
    return s.get("input_tokens", 0) + s.get("output_tokens", 0)


def main():
    ap = argparse.ArgumentParser()
    ap.add_argument("trace")
    ap.add_argument("--top", type=int, default=8)
    ap.add_argument("--fail-over", type=float, default=0.0,
                    help="exit 1 if one step exceeds this share of exclusive time")
    args = ap.parse_args()

    spans = load(args.trace)
    idx = children_index(spans)

    rows, total_ms, total_tok = [], 0, 0
    for s in spans:
        ex, tk = exclusive(s, idx), tokens(s)
        total_ms += ex
        total_tok += tk
        rows.append((s.get("name", s["span_id"]), s.get("status", "?"), ex, tk))

    rows.sort(key=lambda r: r[2], reverse=True)
    print(f"{'step':32} {'status':7} {'excl_ms':>8} {'time%':>6} {'tokens':>7} {'tok%':>6}")

    worst = 0.0
    for name, status, ex, tk in rows[: args.top]:
        t_share = ex / total_ms if total_ms else 0.0
        k_share = tk / total_tok if total_tok else 0.0
        worst = max(worst, t_share)
        print(f"{name[:32]:32} {status:7} {ex:8d} {t_share:6.1%} {tk:7d} {k_share:6.1%}")

    print(f"\ntotal exclusive {total_ms} ms | attributed tokens {total_tok}")
    if args.fail_over and worst > args.fail_over:
        print(f"FAIL: one step holds {worst:.1%} of exclusive time "
              f"(limit {args.fail_over:.0%})")
        sys.exit(1)


if __name__ == "__main__":
    main()

Run it:

python ledger.py spans.jsonl --top 5
python ledger.py spans.jsonl --fail-over 0.40

The second form is the useful one in CI. It fails the build when a single step owns more than 40% of exclusive time. That threshold is a starting point, not a law.

Illustrative output

The table below uses a synthetic trace. Treat the numbers as a format demo, not a benchmark.

step                             status  excl_ms  time%  tokens   tok%
tool.search                      ok        26700  28.4%       0   0.0%
llm.plan                         ok         4100   4.4%    2020  33.0%
llm.compress_context             ok         1800   1.9%    1500  24.5%
tool.write_file                  ok          900   1.0%       0   0.0%
run                              ok         6000   6.4%     600   9.8%

total exclusive 94000 ms | attributed tokens 6120

Two readings matter. tool.search owns 28% of wall time but 0% of tokens. llm.plan owns 4% of wall time but a third of the token spend. They are different problems with different fixes.

The four-step debug loop

Use the same loop for every slow or expensive run.

1. Confirm the root. Root exclusive time should be small. If the root owns half the run, your orchestration code is the bottleneck, not the model or the tools.
2. Split by resource. Sort once by exclusive time, once by tokens. Two lists, two suspects.
3. Group by name across runs. One slow run is noise. The same name at the top of ten runs is a design problem.
4. Re-run one variable. Change only the flagged step, then diff the ledger. Same input trace shape, different numbers.

The fourth step is where most teams skip discipline. Changing a prompt and a timeout together tells you nothing.

What the pattern tells you to do

Symptom in the ledger	Likely cause	First action
Root span owns > 40%	Orchestration loop, serial glue code	Move work into a child span and re-measure
One tool name repeats with rising excl_ms	Retry without backoff, or a loop	Cap attempts, log attempt index as a child span
Tool spans hold time, token spans hold cost	Normal split	Optimize the two lists separately
llm.* spans dominate tokens, few calls	Oversized context carried per step	Trim context between steps, then re-diff
Shares look stable but the run still feels slow	Fixed startup or network floor	Subtract the floor before optimizing anything

That last row saves a lot of wasted work. A constant 8-second setup is not a per-step regression, and no prompt edit will remove it.

Where free model access fits

The ledger needs volumes of traces to be useful. Ten runs prove nothing. You want fifty runs of the same task with small variations.

That is a compute and spend problem, not a cleverness problem. MonkeyCode offers free model access and a free server option, and both are relevant here. Free model access lets you generate a batch of traces without a per-run bill. The free server option gives the collector and ledger.py a place to run continuously, so a laptop going to sleep does not truncate a batch. Check the current allowance and limits on the project page before you plan a batch size, because free-tier numbers change and any figure quoted in an article can be stale.

Disclosure: This article was prepared as part of MonkeyCode's product outreach.

Keep the ledger provider-agnostic. If you later move the same spans to OpenTelemetry, map span_id, parent_id, start_ms, and end_ms to the standard span fields and the accounting still holds.

Limitations and who should skip this

• Small runs do not need it. Under about 20 spans, eyeballing the trace is faster than writing a ledger.
• Clock skew breaks it. Mixed wall clocks across services produce negative exclusive time. Use one monotonic source.
• It attributes, it does not explain. A high share tells you where to look. It never tells you why.
• Token counts are provider-reported. If your provider omits usage for a step, that step shows zero tokens and the shares mislead.
• Already on OpenTelemetry? Use your existing collector and compute exclusive time in the backend. Do not run two tracing stacks.

A one-hour reproduction plan

1. Add the five fields to your span emitter. Ship it behind a flag.
2. Record ten runs of one fixed task. Same seed, same tools.
3. Run ledger.py on each. Save the tables.
4. Sort by tokens. Find the top name across all ten.
5. Change one thing about that step only. Record ten more runs.
6. Diff the two tables. Keep the change only if the flagged share drops.

If you want those first batches without paying per run, MonkeyCode's free model access is a reasonable place to start, and its free server option can host the collector while the batch finishes.

The rule is simple. Do not tune a prompt because the run felt slow. Find the step, measure the share, change one variable, measure again.