Created
March 13, 2014 00:10
-
-
Save benweint/9519384 to your computer and use it in GitHub Desktop.
Ruby GC timing discrepancy
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
#!/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] |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
#!/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 |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment