Class: Brute::Middleware::Tracing

Inherits:
Base
  • Object
show all
Defined in:
lib/brute/middleware/tracing.rb

Overview

Logs timing and token usage for every LLM call, and tracks cumulative timing data in env[:timing].

As the outermost middleware, it sees the full pipeline elapsed time per call. It also tracks total wall-clock time across all calls in a turn (including tool execution gaps between LLM calls).

A new turn is detected when env is nil (the orchestrator sets this on the first call of each run()).

Stores in env[:timing]:

total_elapsed:     wall-clock since the turn began (includes tool gaps)
total_llm_elapsed: cumulative time spent inside LLM calls only
llm_call_count:    number of LLM calls so far
last_call_elapsed: duration of the most recent LLM call

Instance Method Summary collapse

Constructor Details

#initialize(app, logger:) ⇒ Tracing

Returns a new instance of Tracing.



27
28
29
30
31
32
33
 
# File 'lib/brute/middleware/tracing.rb', line 27

def initialize(app, logger:)
  super(app)
  @logger = logger
  @call_count = 0
  @total_llm_elapsed = 0.0
  @turn_start = nil
end

Instance Method Details

#call(env) ⇒ Object 



35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
 
# File 'lib/brute/middleware/tracing.rb', line 35

def call(env)
  @call_count += 1

  # Detect new turn: tool_results is nil on the first pipeline call
  if env[:tool_results].nil?
    @turn_start = Process.clock_gettime(Process::CLOCK_MONOTONIC)
    @total_llm_elapsed = 0.0
  end

  messages = env[:context].messages.to_a
  @logger.debug("[brute] LLM call ##{@call_count} (#{messages.size} messages in context)")

  start = Process.clock_gettime(Process::CLOCK_MONOTONIC)
  response = @app.call(env)
  now = Process.clock_gettime(Process::CLOCK_MONOTONIC)
  elapsed = now - start

  @total_llm_elapsed += elapsed

  tokens = response.respond_to?(:usage) ? response.usage&.total_tokens : '?'
  @logger.info("[brute] LLM response ##{@call_count}: #{tokens} tokens, #{elapsed.round(2)}s")

  env[:metadata][:timing] = {
    total_elapsed: now - (@turn_start || start),
    total_llm_elapsed: @total_llm_elapsed,
    llm_call_count: @call_count,
    last_call_elapsed: elapsed
  }

  response
end