The Observer Effect

The Observer Effect: profilers are not free, and the strangest number in performance work is the one almost nobody measures - the cost of measuring. This example instruments a workload with 0, 1, 2, and 3 layers of probes (each probe is what real profilers do: read the clock, append an event), times each configuration, and derives the PER-GLANCE cost of observation. Then it says the quiet part with an exit code: the act of watching has a price, the price is linear in the …

source on github

a real captured run

THE OBSERVER EFFECT (the most unmeasured number in profiling is the profiler)

  observers  wall (min)   overhead       events recorded per run
  0          3.29ms       -              0
  1          12.05ms      +8.76ms        20000
  2          16.54ms      +13.25ms       40000
  3          25.47ms      +22.18ms       60000

  the observer tax, derived: ~370ns per glance (clock read + event append)
  linearity check: 1 layer costs 8.76ms; a third of 3 layers costs 7.39ms

  what to do with the number: an always-on profiler at one glance
  per unit of work costs you ~370ns each - multiply by your
  requests-per-second and you have the REAL price of the pretty
  flamegraph, in CPU you could have spent serving users. usually
  it's worth it! visibility pays rent. but 'usually' is a
  measurement, not a vibe: min-of-five to shed scheduler noise,
  the workload's ANSWER asserted unchanged under observation (the
  probe must never touch the physics), and the tax checked for
  linearity, because a profiler whose cost curves is a profiler
  with a bug. watch everything - but first, watch the watcher.

source

# frozen_string_literal: true

# The Observer Effect: profilers are not free, and the strangest
# number in performance work is the one almost nobody measures -
# the cost of measuring. This example instruments a workload with
# 0, 1, 2, and 3 layers of probes (each probe is what real
# profilers do: read the clock, append an event), times each
# configuration, and derives the PER-GLANCE cost of observation.
# Then it says the quiet part with an exit code: the act of watching
# has a price, the price is linear in the watching, and you can -
# and therefore must - know the number before you turn on the
# always-on profiler in production.
#
#   bundle exec ruby examples/observer_effect.rb
#
# Runs offline; exits 1 unless the observer tax is real, positive,
# and roughly linear in the number of observers.

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

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

def mono = Process.clock_gettime(Process:class="y">:CLOCK_MONOTONIC)

ITERATIONS = 20_000
DEPTHS = [0, 1, 2, 3].freeze
TRIALS = 5

# The workload: honest arithmetic. The probes: what every profiler
# actually does per sample - read the clock, record an event.
def run_workload(probe_layers, events)
  total = 0
  ITERATIONS.times do |i|
    probe_layers.times { events << Process.clock_gettime(Process:class="y">:CLOCK_MONOTONIC, class="y">:nanosecond) }
    total += (i * 31) % 97
  end
  total
end

# Each depth measured as a task; one lane, because timing tasks in
# parallel is how you measure your scheduler instead of your code
orchestrator = Agentic:class="y">:PlanOrchestrator.new(concurrency_limit: 1)
timings = {}
answers = {}
DEPTHS.each do |depth|
  task = Agentic:class="y">:Task.new(description: class="s">"depth #{depth}", agent_spec: {class="s">"name" => class="s">"d#{depth}", class="s">"instructions" => class="s">"w"})
  orchestrator.add_task(task, agent: ->(_t) {
    samples = TRIALS.times.map {
      events = []
      started = mono
      answers[depth] = run_workload(depth, events)
      mono - started
    }
    timings[depth] = samples.min # min-of-N: the least-disturbed run is the truest
    class="y">:measured
  })
end
orchestrator.execute_plan

puts class="s">"THE OBSERVER EFFECT (the most unmeasured number in profiling is the profiler)"
puts
puts format(class="s">"  %-10s %-12s %-14s %s", class="s">"observers", class="s">"wall (min)", class="s">"overhead", class="s">"events recorded per run")
DEPTHS.each do |depth|
  overhead = timings[depth] - timings[0]
  puts format(class="s">"  %-10d %-12s %-14s %s", depth, class="s">"#{(timings[depth] * 1000).round(2)}ms",
    depth.zero? ? class="s">"-" : class="s">"+#{(overhead * 1000).round(2)}ms", depth * ITERATIONS)
end
puts

# The derived number: nanoseconds per glance
per_glance_ns = ((timings[3] - timings[0]) / (3 * ITERATIONS) * 1_000_000_000).round
step1 = timings[1] - timings[0]
step3 = (timings[3] - timings[0]) / 3.0
puts class="s">"  the observer tax, derived: ~#{per_glance_ns}ns per glance (clock read + event append)"
puts class="s">"  linearity check: 1 layer costs #{(step1 * 1000).round(2)}ms; a third of 3 layers costs #{(step3 * 1000).round(2)}ms"
puts

failures = []
failures << class="s">"the workload changed under observation (impossible - it's arithmetic)" unless answers.values.uniq.size == 1
failures << class="s">"observation was free (suspicious beyond words)" unless timings[3] > timings[0]
failures << class="s">"per-glance cost implausible (#{per_glance_ns}ns)" unless per_glance_ns.between?(5, 100_000)
failures << class="s">"observer tax wildly non-linear" unless step3.between?(step1 * 0.2, step1 * 5)

puts class="s">"  what to do with the number: an always-on profiler at one glance"
puts class="s">"  per unit of work costs you ~#{per_glance_ns}ns each - multiply by your"
puts class="s">"  requests-per-second and you have the REAL price of the pretty"
puts class="s">"  flamegraph, in CPU you could have spent serving users. usually"
puts class="s">"  it's worth it! visibility pays rent. but 'usually' is a"
puts class="s">"  measurement, not a vibe: min-of-five to shed scheduler noise,"
puts class="s">"  the workload's ANSWER asserted unchanged under observation (the"
puts class="s">"  probe must never touch the physics), and the tax checked for"
puts class="s">"  linearity, because a profiler whose cost curves is a profiler"
puts class="s">"  with a bug. watch everything - but first, watch the watcher."
exit(failures.empty? ? 0 : 1)