PtcRunner.Tracer (PtcRunner v0.4.1)

View Source

Immutable trace recorder for SubAgent execution.

Traces are built by prepending entries for efficiency, then reversed on finalize. Each Tracer has a unique trace_id for correlation in parallel/nested execution.

Design Goals

  1. Immutable traces - No shared mutable state
  2. Correlation IDs - Link parent and child executions
  3. Timestamp ordering - Reconstruct parallel timelines
  4. Process isolation - Each SubAgent owns its trace
  5. Safe aggregation - Merge traces without race conditions

Usage

tracer = Tracer.new()
tracer = Tracer.add_entry(tracer, %{type: :llm_call, data: %{turn: 1}})
tracer = Tracer.add_entry(tracer, %{type: :llm_response, data: %{tokens: 100}})
result = Tracer.finalize(tracer)

Parallel Traces

When SubAgents run in parallel via Task.async_stream, their traces are generated concurrently. Use merge_parallel/2 to combine child traces into a unified timeline sorted by timestamp:

parent = Tracer.new()
children = [child1, child2, child3]  # finalized tracers
merged = Tracer.merge_parallel(parent, children)
usage = Tracer.aggregate_usage(merged)

Note: Step.trace is always a list [trace_entry()]. The merged map structure returned by merge_parallel/2 is a separate aggregation result, not a replacement for Step.trace.

Nested Traces

For SubAgents calling other SubAgents via tools, use record_nested_call/3:

tracer = Tracer.record_nested_call(tracer, tool_call, child_step)

Trace ID Generation

Trace IDs are 32-character hex strings generated from cryptographically secure random bytes. No external dependencies required.

Summary

Types

entry()

A single trace entry.

entry_type()

Valid trace entry types.

merged_trace()

Aggregated trace from parallel execution.

t()

Tracer struct for recording execution traces.

usage_stats()

Aggregated usage statistics.

Functions

add_entry(tracer, entry)

Adds an entry to the tracer.

aggregate_usage(tracer)

Aggregate usage statistics from a tracer or merged trace.

entries(tracer)

Returns entries in chronological order.

finalize(tracer)

Finalizes the tracer, reversing entries to chronological order.

find_by_type(tracer, type)

Returns entries matching the given type.

llm_calls(tracer)

Returns all entries with type :llm_call.

merge_parallel(parent, child_tracers)

Merge multiple traces from parallel execution.

new(opts \\ [])

Creates a new tracer with a unique trace ID.

record_nested_call(tracer, tool_call, child_step)

Record a nested SubAgent execution within a tool call.

slowest_entries(tracer, n)

Returns entries with duration_ms in data, sorted by duration descending.

tool_calls(tracer)

Returns all entries with type :tool_call.

total_duration(tracer)

Total duration in milliseconds from started_at to finalized_at.

usage_summary(tracer)

Enhanced usage summary with duration breakdown.

Types

entry()

@type entry() :: %{type: entry_type(), timestamp: DateTime.t(), data: map()}

A single trace entry.

Fields:

  • type: The type of event being traced
  • timestamp: When the entry was recorded
  • data: Additional data for this entry

entry_type()

@type entry_type() ::
  :llm_call
  | :llm_response
  | :tool_call
  | :tool_result
  | :program_start
  | :program_end
  | :return
  | :fail
  | :nested_call

Valid trace entry types.

merged_trace()

@type merged_trace() :: %{
  root_trace_id: String.t(),
  entries: [entry()],
  metadata: %{
    agent_count: non_neg_integer(),
    parallel: boolean(),
    wall_time_ms: non_neg_integer(),
    total_turns: non_neg_integer()
  }
}

Aggregated trace from parallel execution.

Returned by merge_parallel/2 - separate from Tracer.t().

t()

@type t() :: %PtcRunner.Tracer{
  entries: [entry()],
  finalized_at: DateTime.t() | nil,
  parent_id: String.t() | nil,
  started_at: DateTime.t(),
  trace_id: String.t()
}

Tracer struct for recording execution traces.

Fields:

  • trace_id: Unique 32-character hex ID for this execution
  • parent_id: Parent trace ID for nested agent calls (nil for root)
  • started_at: When the tracer was created
  • entries: List of trace entries (prepended for efficiency, reversed on finalize)
  • finalized_at: When finalize/1 was called (nil until finalized)

usage_stats()

@type usage_stats() :: %{
  total_duration_ms: non_neg_integer(),
  llm_calls: non_neg_integer(),
  tool_calls: non_neg_integer(),
  total_turns: non_neg_integer(),
  agent_count: non_neg_integer()
}

Aggregated usage statistics.

Returned by aggregate_usage/1.

Functions

add_entry(tracer, entry)

@spec add_entry(t(), map()) :: t()

Adds an entry to the tracer.

Entries are prepended for efficiency and reversed on finalize/1. A timestamp is added automatically if not provided.

Raises FunctionClauseError if called on a finalized tracer.

Examples

iex> tracer = PtcRunner.Tracer.new()
iex> tracer = PtcRunner.Tracer.add_entry(tracer, %{type: :llm_call, data: %{turn: 1}})
iex> length(tracer.entries)
1
iex> hd(tracer.entries).type
:llm_call

aggregate_usage(tracer)

@spec aggregate_usage(t() | merged_trace()) :: usage_stats()

Aggregate usage statistics from a tracer or merged trace.

Works on both Tracer.t() and merged_trace() maps.

Examples

iex> tracer = PtcRunner.Tracer.new()
iex> tracer = PtcRunner.Tracer.add_entry(tracer, %{type: :llm_call, data: %{}})
iex> tracer = PtcRunner.Tracer.add_entry(tracer, %{type: :tool_call, data: %{}})
iex> tracer = PtcRunner.Tracer.finalize(tracer)
iex> usage = PtcRunner.Tracer.aggregate_usage(tracer)
iex> usage.llm_calls
1
iex> usage.tool_calls
1

entries(tracer)

@spec entries(t()) :: [entry()]

Returns entries in chronological order.

If the tracer is not finalized, entries are reversed to chronological order. If already finalized, entries are already in chronological order.

Examples

iex> tracer = PtcRunner.Tracer.new()
iex> tracer = PtcRunner.Tracer.add_entry(tracer, %{type: :llm_call, data: %{}})
iex> tracer = PtcRunner.Tracer.add_entry(tracer, %{type: :llm_response, data: %{}})
iex> entries = PtcRunner.Tracer.entries(tracer)
iex> hd(entries).type
:llm_call

finalize(tracer)

@spec finalize(t()) :: t()

Finalizes the tracer, reversing entries to chronological order.

Sets the finalized_at timestamp. After finalization, add_entry/2 will raise a FunctionClauseError.

Raises FunctionClauseError if called on an already finalized tracer.

Examples

iex> tracer = PtcRunner.Tracer.new()
iex> tracer = PtcRunner.Tracer.add_entry(tracer, %{type: :llm_call, data: %{}})
iex> tracer = PtcRunner.Tracer.add_entry(tracer, %{type: :llm_response, data: %{}})
iex> result = PtcRunner.Tracer.finalize(tracer)
iex> hd(result.entries).type
:llm_call
iex> is_struct(result.finalized_at, DateTime)
true

find_by_type(tracer, type)

@spec find_by_type(t(), entry_type()) :: [entry()]

Returns entries matching the given type.

Examples

iex> tracer = PtcRunner.Tracer.new()
iex> tracer = PtcRunner.Tracer.add_entry(tracer, %{type: :llm_call, data: %{turn: 1}})
iex> tracer = PtcRunner.Tracer.add_entry(tracer, %{type: :tool_call, data: %{name: "search"}})
iex> tracer = PtcRunner.Tracer.add_entry(tracer, %{type: :llm_call, data: %{turn: 2}})
iex> entries = PtcRunner.Tracer.find_by_type(tracer, :llm_call)
iex> length(entries)
2
iex> Enum.all?(entries, & &1.type == :llm_call)
true

llm_calls(tracer)

@spec llm_calls(t()) :: [entry()]

Returns all entries with type :llm_call.

Examples

iex> tracer = PtcRunner.Tracer.new()
iex> tracer = PtcRunner.Tracer.add_entry(tracer, %{type: :llm_call, data: %{turn: 1}})
iex> tracer = PtcRunner.Tracer.add_entry(tracer, %{type: :tool_call, data: %{name: "search"}})
iex> PtcRunner.Tracer.llm_calls(tracer) |> length()
1

merge_parallel(parent, child_tracers)

@spec merge_parallel(t(), [t()]) :: merged_trace()

Merge multiple traces from parallel execution.

Returns a merged trace map (not a Tracer.t()) with all entries sorted by timestamp. The parent tracer provides the root trace ID, while child tracers provide the entries.

Examples

iex> parent = PtcRunner.Tracer.new()
iex> child1 = PtcRunner.Tracer.new(parent_id: parent.trace_id)
iex> child1 = PtcRunner.Tracer.add_entry(child1, %{type: :llm_call, data: %{turn: 1}})
iex> child1 = PtcRunner.Tracer.finalize(child1)
iex> merged = PtcRunner.Tracer.merge_parallel(parent, [child1])
iex> merged.root_trace_id == parent.trace_id
true
iex> merged.metadata.agent_count
1
iex> merged.metadata.parallel
true

new(opts \\ [])

@spec new(keyword()) :: t()

Creates a new tracer with a unique trace ID.

Options

  • :parent_id - Parent trace ID for nested agent calls

Examples

iex> tracer = PtcRunner.Tracer.new()
iex> String.length(tracer.trace_id)
32
iex> tracer.parent_id
nil
iex> tracer.entries
[]
iex> tracer.finalized_at
nil

iex> tracer = PtcRunner.Tracer.new(parent_id: "abc123")
iex> tracer.parent_id
"abc123"

record_nested_call(tracer, tool_call, child_step)

@spec record_nested_call(t(), map(), map()) :: t()

Record a nested SubAgent execution within a tool call.

Adds a :nested_call entry with the tool call and child step's return value and trace.

Examples

iex> tracer = PtcRunner.Tracer.new()
iex> tool_call = %{name: "sub_agent", args: %{prompt: "test"}}
iex> child_step = %{return: "result", trace: [%{turn: 1}]}
iex> tracer = PtcRunner.Tracer.record_nested_call(tracer, tool_call, child_step)
iex> [entry] = PtcRunner.Tracer.entries(tracer)
iex> entry.type
:nested_call
iex> entry.data.result.return
"result"

slowest_entries(tracer, n)

@spec slowest_entries(t(), non_neg_integer()) :: [entry()]

Returns entries with duration_ms in data, sorted by duration descending.

Only includes entries that have a :duration_ms key in their data map.

Examples

iex> tracer = PtcRunner.Tracer.new()
iex> tracer = PtcRunner.Tracer.add_entry(tracer, %{type: :llm_call, data: %{duration_ms: 100}})
iex> tracer = PtcRunner.Tracer.add_entry(tracer, %{type: :tool_call, data: %{duration_ms: 50}})
iex> tracer = PtcRunner.Tracer.add_entry(tracer, %{type: :llm_call, data: %{duration_ms: 200}})
iex> [slowest | _] = PtcRunner.Tracer.slowest_entries(tracer, 1)
iex> slowest.data.duration_ms
200

tool_calls(tracer)

@spec tool_calls(t()) :: [entry()]

Returns all entries with type :tool_call.

Examples

iex> tracer = PtcRunner.Tracer.new()
iex> tracer = PtcRunner.Tracer.add_entry(tracer, %{type: :llm_call, data: %{turn: 1}})
iex> tracer = PtcRunner.Tracer.add_entry(tracer, %{type: :tool_call, data: %{name: "search"}})
iex> PtcRunner.Tracer.tool_calls(tracer) |> length()
1

total_duration(tracer)

@spec total_duration(t()) :: non_neg_integer()

Total duration in milliseconds from started_at to finalized_at.

Returns 0 if the tracer is not finalized or timestamps are nil.

Examples

iex> tracer = %PtcRunner.Tracer{
...>   trace_id: "test",
...>   parent_id: nil,
...>   started_at: ~U[2024-01-15 10:00:00Z],
...>   entries: [],
...>   finalized_at: ~U[2024-01-15 10:00:02Z]
...> }
iex> PtcRunner.Tracer.total_duration(tracer)
2000

iex> tracer = PtcRunner.Tracer.new()
iex> PtcRunner.Tracer.total_duration(tracer)
0

usage_summary(tracer)

@spec usage_summary(t()) :: map()

Enhanced usage summary with duration breakdown.

Includes total duration, LLM and tool call durations (summed from entries with duration_ms in their data), and counts.

Examples

iex> tracer = PtcRunner.Tracer.new()
iex> tracer = PtcRunner.Tracer.add_entry(tracer, %{type: :llm_call, data: %{duration_ms: 100}})
iex> tracer = PtcRunner.Tracer.add_entry(tracer, %{type: :tool_call, data: %{duration_ms: 50}})
iex> tracer = PtcRunner.Tracer.finalize(tracer)
iex> summary = PtcRunner.Tracer.usage_summary(tracer)
iex> summary.llm_duration_ms
100
iex> summary.tool_duration_ms
50
iex> summary.llm_call_count
1
iex> summary.tool_call_count
1