The Write Path Profile

The Write Path Profile: everyone's first instinct about a slow journal is "switch JSON libraries". Before holding that opinion, weigh each layer of the write separately - serialize, write, flush, fsync - because optimization budgets get spent where the profiler points or they get wasted. Spoiler: the disk's honesty is the product, and it is also the bill.

source on github

a real captured run

WRITE PATH PROFILE (300 events per layer, microseconds each)

  JSON.generate only                   1.0us   #
  + buffered write                     2.8us   #####
  + flush to kernel                    5.4us   #########
  journal.record (flock+fsync)       359.9us   ###############################
  journal fsync_every: 20             47.5us   ####################

  the ledger: serialization is 0.3% of the real write. swapping
  JSON libraries would optimize a rounding error - the other
  99.7% is the price of the fsync, which is to say the price of
  the journal's ONLY promise (a crash cannot unwrite what record
  returned from). the honest knob is group commit - and since
  round 13 it's a real constructor argument: fsync_every: 20
  drops the write to 47us, and the constructor's docs name what
  was traded (a crash may eat up to 19 acknowledged events).
  that's the correct shape for a durability tradeoff: explicit,
  named, greppable in the diff that chose it - not folklore in a
  wiki. profile first, name the tradeoff second, and never let
  anyone optimize the layer the profiler acquitted.

source

# frozen_string_literal: true

# The Write Path Profile: everyone's first instinct about a slow
# journal is "switch JSON libraries". Before holding that opinion,
# weigh each layer of the write separately - serialize, write, flush,
# fsync - because optimization budgets get spent where the profiler
# points or they get wasted. Spoiler: the disk's honesty is the
# product, and it is also the bill.
#
#   bundle exec ruby examples/write_path_profile.rb
#
# Runs offline; timings are real syscalls on this machine.

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

EVENTS = 300
PAYLOAD = {event: class="s">"task_succeeded", task_id: class="s">"t-123", description: class="s">"sync:orders",
           duration: 0.412, output: class="s">"x" * 200}.freeze

def bench(events = EVENTS)
  t0 = Process.clock_gettime(Process:class="y">:CLOCK_MONOTONIC)
  events.times { |i| yield(i) }
  (Process.clock_gettime(Process:class="y">:CLOCK_MONOTONIC) - t0) / events * 1_000_000 # us/event
end

dir = Dir.mktmpdir(class="s">"agentic_write_path")

# Layer 1: serialization only
serialize = bench { JSON.generate(PAYLOAD) }

# Layer 2: + buffered write (kernel may keep it in page cache forever)
buffered_file = File.open(File.join(dir, class="s">"buffered.jsonl"), class="s">"a")
buffered = bench { buffered_file.puts(JSON.generate(PAYLOAD)) }

# Layer 3: + flush (userland buffer to kernel, still not durable)
flushed_file = File.open(File.join(dir, class="s">"flushed.jsonl"), class="s">"a")
flushed = bench { |i|
  flushed_file.puts(JSON.generate(PAYLOAD))
  flushed_file.flush
}

# Layer 4: the real thing - open, flock, puts, flush, FSYNC per event
journal = Agentic:class="y">:ExecutionJournal.new(path: File.join(dir, class="s">"real.jsonl"))
real = bench { |i| journal.record(class="y">:task_succeeded, PAYLOAD.merge(task_id: class="s">"t-#{i}")) }

# The alternative promise: group commit, now a real constructor knob
# (fsync_every: - the round-13 release cashing this file's own ask)
group_journal = Agentic:class="y">:ExecutionJournal.new(path: File.join(dir, class="s">"group.jsonl"), fsync_every: 20)
group = bench { |i| group_journal.record(class="y">:task_succeeded, PAYLOAD.merge(task_id: class="s">"t-#{i}")) }
group_journal.sync # the crash-window closes here, explicitly

puts class="s">"WRITE PATH PROFILE (#{EVENTS} events per layer, microseconds each)"
puts
rows = {
  class="s">"JSON.generate only" => serialize,
  class="s">"+ buffered write" => buffered,
  class="s">"+ flush to kernel" => flushed,
  class="s">"journal.record (flock+fsync)" => real,
  class="s">"journal fsync_every: 20" => group
}
rows.each do |name, us|
  puts format(class="s">"  %-30s %9.1fus   %s", name, us, class="s">"#" * [(Math.log10([us, 1].max) * 12).round, 1].max)
end

puts
json_share = serialize / real * 100
puts format(class="s">"  the ledger: serialization is %.1f%% of the real write. swapping", json_share)
puts class="s">"  JSON libraries would optimize a rounding error - the other"
puts format(class="s">"  %.1f%% is the price of the fsync, which is to say the price of", 100 - json_share)
puts class="s">"  the journal's ONLY promise (a crash cannot unwrite what record"
puts class="s">"  returned from). the honest knob is group commit - and since"
puts class="s">"  round 13 it's a real constructor argument: fsync_every: 20"
puts format(class="s">"  drops the write to %.0fus, and the constructor's docs name what", group)
puts class="s">"  was traded (a crash may eat up to 19 acknowledged events)."
puts class="s">"  that's the correct shape for a durability tradeoff: explicit,"
puts class="s">"  named, greppable in the diff that chose it - not folklore in a"
puts class="s">"  wiki. profile first, name the tradeoff second, and never let"
puts class="s">"  anyone optimize the layer the profiler acquitted."