我们通过“进入”和“离开”事件计量中断时间。增量垃圾收集（增量标记和延迟清理）引入中断标记和清理阶段。“进入“是”进入垃圾清理“事件，”离开“是”离开垃圾清理“事件。
下图显示了当前增量垃圾收集器的事件时间。
垃圾收集器事件
我们可以计量每一个事件的当前时间（在 Linux 上当前时间是通过 gettimeofday() 获得）。所以我们可以通过“进入”和“离开”事件计量垃圾收集器的中断时间。
我使用 ko1-test-app 做为我们中断时间的基准。ko1-test-app 是我们的一个英雄“Aaron Patterson"为我写的一个小的 rails app
为了使用 gc_tracer，我添加了一条命名为“test_gc_tracer”的规则，如下：
diff --git a/perf.rake b/perf.rake
index f336e33..7f4f1bd 100644
--- a/perf.rake
+++ b/perf.rake
@@ -54,7 +54,7 @@ def do_test_task app
body.close
end
-task :test do
+def test_run
app = Ko1TestApp::Application.instance
app.app
@@ -67,6 +67,22 @@ task :test do
}
end
+task :test do
+ test_run
+end
+
+task :test_gc_tracer do
+ require 'gc_tracer'
+ require 'pp'
+ pp GC.stat
+ file = "log.#{Process.pid}"
+ GC::Tracer.start_logging(file, events: %i(enter exit), gc_stat: false) do
+ test_run
+ end
+ pp GC.stat
+ puts "GC tracer log: #{file}"
+end
+
task :once do
app = Ko1TestApp::Application.instance
app.app
运行 bundle exec rake test_gc_tracer KO1TEST_CNT=30000。我们通过数值“30000”指定模拟30,000个请求。我们可以在文件“log.xxxx”里得到结果（xxxx是程序的进程ID）。文件如下
type tick major_by gc_by have_finalizer immediate_sweep state
enter 1419489706840147 0 newobj 0 0 sweeping
exit 1419489706840157 0 newobj 0 0 sweeping
enter 1419489706840184 0 newobj 0 0 sweeping
exit 1419489706840195 0 newobj 0 0 sweeping
enter 1419489706840306 0 newobj 0 0 sweeping
exit 1419489706840313 0 newobj 0 0 sweeping
enter 1419489706840612 0 newobj 0 0 sweeping
...
在我的环境下，这里有 1,142,907 行。
“type”列是事件类型，tick 是当前时间（gettimeofday（）的输出结果，epoc总时间，单位是毫秒）。通过这些信息我们可以获取垃圾收集器的中断时间。通过前两行我们可以计算出中断时间为10 微秒 （1419489706840157 - 1419489706840147）。
以下小脚本显示每次中断时间。
enter_tick = 0
open(ARGV.shift){|f|
f.each_line{|line|
e, tick, * = line.split(/\s/)
case e
when 'enter'
enter_tick = tick.to_i
when 'exit'
st = tick.to_i - enter_tick
puts st if st > 100 # over 100 us
else
# puts line
end
}
}
这里有很多行，这个脚本打印了 100 微秒内的中断次数。
下图显示了统计结果
在分代垃圾收集器中产生了7个较大的中断时间，他们应该是由“major GC”产生的。最大中断时间大概15毫秒（15Kus），不管怎样，增量垃圾收集器减少了最大中断时间（差不多2ms(2Kus))，太好了。
总结Ruby 2.2 通过引入增量垃圾收集算法缩短了垃圾收集的中断时间。