Ruby GC timing discrepancy

standalone.rb

#!/usr/bin/env ruby

puts "Run this in another terminal:"
puts ""
puts "  sudo ./trace-gc-standalone.sh #{$$}"
puts ""
puts "... wait for the 'Ready!' message, switch back here and press enter to start."

GC::Profiler.enable
$stdin.gets

GC::Profiler.clear
time_before = GC::Profiler.total_time

# Generate some GC stress...
300.times do
  symbols = (1..1000).to_a.map { |i| "s#{i}".to_sym }.shuffle
  10.times { symbols.sort }
end

time_after = GC::Profiler.total_time
records = GC::Profiler.raw_data

total_gc_time = time_after - time_before

mark_times  = records.map { |r| r[:GC_MARK_TIME] }.compact
sweep_times = records.map { |r| r[:GC_SWEEP_TIME] }.compact
total_mark_time = mark_times.inject(:+)
total_sweep_time = sweep_times.inject(:+)

puts "Total mark time:  %.1f ms" % [total_mark_time * 1000]
puts "Total sweep time: %.1f ms" % [total_sweep_time * 1000]
puts "Total GC time:    %.1f ms" % [total_gc_time * 1000]

trace-gc-standalone.sh

#!/bin/bash

PID=$1

cat > /tmp/dtracetmp.$$ <<EOF
#!/usr/sbin/dtrace -s

#pragma D option bufsize=16m
#pragma D option dynvarsize=16m
#pragma D option cleanrate=50Hz

BEGIN {
  printf("Ready! (Go press enter on the original script.)\n");
}

ruby${PID}:::gc-mark-begin {
  self->mark_begin = timestamp;
}

ruby${PID}:::gc-mark-end /self->mark_begin/ {
  elapsed = timestamp - self->mark_begin;
  @mark_total = sum(elapsed);
  @total = sum(elapsed);
  self->mark_begin = 0;
}

ruby${PID}:::gc-sweep-begin {
  self->sweep_begin = timestamp;
}

ruby${PID}:::gc-sweep-end /self->sweep_begin/ {
  elapsed = timestamp - self->sweep_begin;
  @sweep_total = sum(elapsed);
  @total = sum(elapsed);
  self->sweep_begin = 0;
}

END {
  normalize(@mark_total,  1000000);
  normalize(@sweep_total, 1000000);
  normalize(@total,       1000000);
  printa("Mark total:         %@d ms\n", @mark_total);
  printa("Sweep total:        %@d ms\n", @sweep_total);
  printa("Mark + sweep total: %@d ms\n", @total)
}

EOF

dtrace -q -s /tmp/dtracetmp.$$ -p $PID