See What Your Agent Did — Tracing and Observability with NVIDIA NIM

#nvidia #ai #python #tutorial

Somewhere around your twentieth conversation with the agent we've built, it will do something strange. Call a tool twice for no reason. Refuse a question it answered yesterday. Take nine seconds on something that usually takes two. And you'll ask the only question that matters in production: why did it do that?

Rerunning won't tell you. Models aren't deterministic; the moment is gone. The debugging print statements from Part 6 scroll away with the terminal. What you need is a trace: a durable record of what actually happened — every tool call with its arguments and result, every model call with its latency, whether the JSON answer needed repair, and what the agent finally said.

This post adds exactly that, in plain Python — nothing outside the standard library. Every turn appends one JSON line to a file. That one-line-per-turn shape is deliberate: the next post (evals) will load a line and get everything an assertion needs — the input, the tool path, and Part 9's validated six-key answer — with no regrouping. Observability isn't a product you install; it's a file you write.

I'm B Torkian, NVIDIA Developer Champion at USC. Part 10 of the series.

What you're adding

Workshop 9:  turn happens → answer returned → details lost forever
Workshop 10: turn happens → answer returned → one JSON line survives:
             {user_message, steps: [model calls, tool calls, validation], final, latency}

The Workshop 9 loop is unchanged. A small JsonlTracer hooks its five natural seams: turn start, each model call, each tool call, the validation outcome, and the final answer.

Step 1 — Decide what one turn's record holds

{
  "schema_version": "ws10.turn.v1",
  "trace_id": "a3f9c2e81b04",
  "turn_id": 2,
  "timestamp": "2026-07-06T18:22:31+00:00",
  "model": "nvidia/llama-3.3-nemotron-super-49b-v1.5",
  "mode": "chat",
  "user_message": "How many days until that?",
  "steps": [
    {"type": "model_call", "step": 1, "latency_ms": 842,
     "usage": {"prompt_tokens": 1204, "completion_tokens": 31, "total_tokens": 1235},
     "tool_calls": [{"id": "call_abc", "name": "days_until_weekday", "arguments": "{\"weekday\": \"Thursday\"}"}]},
    {"type": "tool_call", "step": 1, "tool_call_id": "call_abc", "name": "days_until_weekday",
     "arguments": {"weekday": "Thursday"}, "result": "The next Thursday is in 3 day(s)...", "latency_ms": 0},
    {"type": "model_call", "step": 2, "latency_ms": 1130, "usage": {"...": "..."}, "tool_calls": []},
    {"type": "validation", "parse_ok": true, "errors": [], "repair_attempted": false, "repair_succeeded": false}
  ],
  "final": {"status": "answered", "answer": "The USC AI Club meets in 3 days...", "category": "campus_event",
            "items": [{"name": "USC AI Club", "day": "Thursday", "days_until": 3}], "missing": [], "sources": ["..."]},
  "total_latency_ms": 1990
}

Everything a "why" question needs is in one line: the model asked for days_until_weekday (so memory resolved "that" correctly), the tool ran in under a millisecond, the second model call produced clean JSON on the first try, and the whole turn took two seconds — most of it the second model call.

A schema_version field costs nothing today and saves you when the shape evolves — future tooling can tell old lines from new.

Step 2 — The tracer (plain file I/O)

class JsonlTracer:
    SCHEMA_VERSION = "ws10.turn.v1"

    def __init__(self, path: Path = TRACE_PATH):
        self.path = Path(path)
        self.path.parent.mkdir(parents=True, exist_ok=True)
        self.trace_id = uuid.uuid4().hex[:12]     # one id per session
        self.turn_id = 0
        self._turn = None

    def begin_turn(self, user_message: str, mode: str) -> None:
        if self._turn is not None:            # last turn crashed before end_turn — flush it
            self.abort_turn("turn abandoned without end_turn")
        self.turn_id += 1
        self._turn = {"schema_version": self.SCHEMA_VERSION, "trace_id": self.trace_id,
                      "turn_id": self.turn_id, "timestamp": datetime.now(ZoneInfo("UTC")).isoformat(),
                      "model": MODEL, "mode": mode, "user_message": user_message,
                      "steps": [], "final": None, "total_latency_ms": None}
        self._start = time.perf_counter()

    # record_model_call / record_tool_call / record_validation append step
    # events — see the repo for the three small methods.

    def end_turn(self, final: dict) -> None:
        self._turn["final"] = final
        self._turn["total_latency_ms"] = int((time.perf_counter() - self._start) * 1000)
        with self.path.open("a") as f:
            f.write(json.dumps(self._turn) + "\n")
        self._turn = None

No logging framework, no decorators, no globals. The session owns a tracer; the tracer owns a file.

("Why not OpenTelemetry?" Same answer as Part 9's "why not Pydantic": OpenTelemetry — and LLM-observability platforms built on it — is what production teams use for exactly this, with spans, exporters, and dashboards. We hand-roll the tracer so you can see what those tools record and why. Once this JSONL file makes sense to you, an OTel span is just this record with a standard schema and somewhere nicer to live.)

Step 3 — Hook the loop at its seams

The session gains one line in __init__ — self.tracer = JsonlTracer(trace_path) — and the loop gains a timing wrapper at each seam:

def _run_turn(self, user_message: str, stream: bool) -> dict:
    self.messages.append({"role": "user", "content": user_message})
    self.tracer.begin_turn(user_message, mode="stream" if stream else "chat")

    for step in range(1, MAX_STEPS + 1):
        t0 = time.perf_counter()
        text, tool_calls, assistant_msg, usage = self._complete(stream)
        self.tracer.record_model_call(step, int((time.perf_counter() - t0) * 1000), usage, tool_calls)

        if tool_calls:
            self.messages.append(assistant_msg)
            for tc in tool_calls:
                # ...parse arguments as in Part 9...
                t1 = time.perf_counter()
                result = run_tool(tc["name"], arguments)
                self.tracer.record_tool_call(step, tc["id"], tc["name"], arguments,
                                             str(result), int((time.perf_counter() - t1) * 1000))
                # ...append the role="tool" result as in Part 9...
            continue

        data, vmeta = self._finalize_json(text)       # now also returns what happened
        self.tracer.record_validation(vmeta["parse_ok"], vmeta["errors"],
                                      vmeta["repair_attempted"], vmeta["repair_succeeded"])
        self.messages.append({"role": "assistant", "content": json.dumps(data)})
        self._trim()
        self.tracer.end_turn(data)
        return data

(One detail the abridged snippet hides: in the real file, _run_turn wraps this loop in a try/except that calls tracer.abort_turn(...) before re-raising — so a crash mid-turn still writes the partial trace. A crash is exactly the moment you'll want the record.)

Two small refactors make this clean, and they're worth naming honestly:

_complete now also returns usage — best-effort token accounting. Non-streaming NIM responses usually include response.usage (prompt, completion, total tokens); streamed responses usually don't. (Some OpenAI-compatible endpoints accept stream_options={"include_usage": true} to report usage on the final chunk — support varies, which is exactly why we log null rather than guess.) Never log zeros you didn't measure — a zero looks like a measurement, a null tells the truth.
_finalize_json now returns (data, validation_meta) — so the tracer can record whether parsing failed and whether the repair call ran, without the parsing code knowing traces exist.

Step 4 — Run it, then ask the file your questions

session = ChatSession(verbose=True)
for q in ["When does the USC AI Club meet?",
          "How many days until that?",
          "Which is sooner, that meeting or the AI/ML office hours?",
          "What is the campus wifi password?"]:
    session.chat(q)

Four turns, four lines in traces/campus_assistant.jsonl. Now the payoff — a dozen-line analysis instead of guesswork (the repo version adds an empty-file guard):

def analyze_traces(path=TRACE_PATH):
    turns = [json.loads(line) for line in Path(path).read_text().splitlines()]
    slowest = max(turns, key=lambda t: t["total_latency_ms"])
    tool_counts, repairs = {}, 0
    for t in turns:
        for e in t["steps"]:
            if e["type"] == "tool_call":
                tool_counts[e["name"]] = tool_counts.get(e["name"], 0) + 1
            if e["type"] == "validation" and e["repair_attempted"]:
                repairs += 1
    print(f"turns:       {len(turns)}")
    print(f"slowest:     turn {slowest['turn_id']} ({slowest['total_latency_ms']} ms) — {slowest['user_message']!r}")
    print(f"tool calls:  {tool_counts}")
    print(f"repair rate: {repairs}/{len(turns)}")

Which turn was slowest, and was it the model or a tool? Did the comparison question really call days_until_weekday twice? How often does the JSON need repair? The trace answers all of it without rerunning the agent — that's the entire point.

Sidebar — the second layer: server metrics on self-hosted NIM

Everything above is app-side observability, and it works identically against the hosted API Catalog and a local NIM container. If you self-host NIM (Part 4), you get a second layer for free: the container exposes Prometheus metrics — GPU utilization, time-to-first-token, requests in flight — on its HTTP port:

# Local NIM container only. The hosted endpoint does NOT expose this.
curl -s http://localhost:8000/v1/metrics | head -20

Mind the path: metrics live under /v1 alongside the inference routes — :8000/v1/metrics, not :8000/metrics. App traces tell you what your agent did; server metrics tell you what the model server did. Production runs both. Docs: https://docs.nvidia.com/nim/large-language-models/latest/reference/logging-and-observability.html

Step 5 — The rule that saves you later: traces hold user data

Look at what we're logging: the user's message, tool results, the final answer. In this demo that's club schedules. In a real deployment it's names, emails, student IDs — whatever people type at your assistant. So three habits, from day one:

Never log secrets. No API keys, no request headers, no environment. (Notice the tracer never touches client or os.environ.)
Never log the full messages array. It re-accumulates the whole conversation every turn — one leak away from a disaster and redundant anyway: the per-turn records already reconstruct it.
Keep trace files out of git. traces/ is in .gitignore in the repo. Trace files are data, not code.

Step 6 — What you actually built

Workshops 1–9 built an agent that retrieves, refuses, plans, remembers, streams, and returns validated JSON.
Workshop 10 made it observable: every turn leaves a one-line record that answers "what happened?" after the fact.

And it set up the next chapter perfectly. With traces on disk and a fixed answer contract, we can finally test the agent like software: evals — replay the questions, assert on status, category, and missing, and catch regressions before students do. That's Part 11.

The agent is still a while loop around a model call. Now it's a while loop that keeps receipts.

Get the code

Repo: github.com/torkian/nvidia-nim-workshop
One-click Colab: Open part10_traces.ipynb
Local Python: part10_traces.py in the repo (python3 part10_traces.py after pip install -r requirements.txt).

MIT licensed. I run this at USC — fork it, swap the knowledge base and the tools for your school, your club, your project.