EventProf for Plans

EventProf for Plans: TestProf taught test suites to answer "where does the time GO?" by group, not by file. Same question for plans: tag every task by its kind (llm:, db:, render:), collect durations from the lifecycle hooks, and report task-seconds by tag - plus the number nobody computes: how much of that time ran in parallel, and how much of the wall clock one tag owns hostage.

source on github

a real captured run

EVENT PROF (task-seconds by tag; wall clock 349ms, 3 lanes)

  tag      seconds    share    tasks    worst offender
  llm         651ms    77.5%   3        llm:draft (250ms)  ##########################
  db          107ms    12.7%   3        db:fetch_orders (42ms)  ####
  render       82ms     9.8%   3        render:pdf (50ms)  ###

  task-seconds: 840ms across 349ms of wall = 2.4x effective parallelism

  the TestProf move is reading the SHARE column before touching any
  code: llm owns 77% of all task-seconds, so a 20% win there is
  worth more than deleting the entire render stage - optimizing
  db: or render: is polishing doorknobs on a burning building.
  and the parallelism line is the second lesson: 2.4x on 3 lanes
  means the stage barriers are eating part of the overlap -
  llm tasks can't start until ALL db tasks finish. profile by
  group, fix the biggest group, re-profile. boring, effective,
  and the hooks made it fifteen lines.

source

# frozen_string_literal: true

# EventProf for Plans: TestProf taught test suites to answer "where
# does the time GO?" by group, not by file. Same question for plans:
# tag every task by its kind (llm:, db:, render:), collect durations
# from the lifecycle hooks, and report task-seconds by tag - plus the
# number nobody computes: how much of that time ran in parallel, and
# how much of the wall clock one tag owns hostage.
#
#   bundle exec ruby examples/event_prof.rb
#
# Runs offline; durations are scripted, accounting is real.

require class="s">"bundler/setup"
require class="s">"agentic"

Agentic.logger.level = class="y">:fatal

WORK = {
  class="s">"db:fetch_users" => 0.03, class="s">"db:fetch_orders" => 0.04, class="s">"db:fetch_stock" => 0.03,
  class="s">"llm:summarize" => 0.22, class="s">"llm:classify" => 0.18, class="s">"llm:draft" => 0.25,
  class="s">"render:header" => 0.01, class="s">"render:body" => 0.02, class="s">"render:pdf" => 0.05
}.freeze

samples = []
hooks = {
  after_task_success: ->(task_id:, task:, result:, duration:) {
    samples << [task.description, duration]
  }
}

orchestrator = Agentic:class="y">:PlanOrchestrator.new(concurrency_limit: 3, lifecycle_hooks: hooks)
tasks = WORK.to_h { |name, cost| [name, Agentic:class="y">:Task.new(description: name, agent_spec: {class="s">"name" => name, class="s">"instructions" => class="s">"w"})] }

# db feeds llm feeds render - three stages, three lanes
db, llm, render = %w[db llm render].map { |prefix| tasks.select { |n, _| n.start_with?(prefix) }.values }
db.each { |t| orchestrator.add_task(t, agent: ->(task) { sleep(WORK[task.description]) }) }
llm.each { |t| orchestrator.add_task(t, db, agent: ->(task) { sleep(WORK[task.description]) }) }
render.each { |t| orchestrator.add_task(t, llm, agent: ->(task) { sleep(WORK[task.description]) }) }

wall_start = Process.clock_gettime(Process:class="y">:CLOCK_MONOTONIC)
orchestrator.execute_plan
wall = Process.clock_gettime(Process:class="y">:CLOCK_MONOTONIC) - wall_start

# --- the profile ----------------------------------------------------------------
by_tag = samples.group_by { |name, _| name[/\A\w+/] }
  .transform_values { |rows| {seconds: rows.sum { |_, d| d }, count: rows.size, worst: rows.max_by { |_, d| d }} }
task_seconds = samples.sum { |_, d| d }

puts class="s">"EVENT PROF (task-seconds by tag; wall clock #{(wall * 1000).round}ms, 3 lanes)"
puts
puts format(class="s">"  %-8s %-10s %-8s %-8s %s", class="s">"tag", class="s">"seconds", class="s">"share", class="s">"tasks", class="s">"worst offender")
by_tag.sort_by { |_, v| -v[class="y">:seconds] }.each do |tag, stats|
  share = stats[class="y">:seconds] / task_seconds * 100
  puts format(class="s">"  %-8s %6.0fms   %5.1f%%   %-8d %s (%.0fms)  %s",
    tag, stats[class="y">:seconds] * 1000, share, stats[class="y">:count],
    stats[class="y">:worst][0], stats[class="y">:worst][1] * 1000, class="s">"#" * (share / 3).round)
end

parallelism = task_seconds / wall
puts
puts format(class="s">"  task-seconds: %.0fms across %.0fms of wall = %.1fx effective parallelism", task_seconds * 1000, wall * 1000, parallelism)
puts
llm_share = by_tag[class="s">"llm"][class="y">:seconds] / task_seconds * 100
puts class="s">"  the TestProf move is reading the SHARE column before touching any"
puts format(class="s">"  code: llm owns %.0f%% of all task-seconds, so a 20%% win there is", llm_share)
puts class="s">"  worth more than deleting the entire render stage - optimizing"
puts class="s">"  db: or render: is polishing doorknobs on a burning building."
puts format(class="s">"  and the parallelism line is the second lesson: %.1fx on 3 lanes", parallelism)
puts class="s">"  means the stage barriers are eating part of the overlap -"
puts class="s">"  llm tasks can't start until ALL db tasks finish. profile by"
puts class="s">"  group, fix the biggest group, re-profile. boring, effective,"
puts class="s">"  and the hooks made it fifteen lines."