gc_hook.rb

# gc_hook.rb
#   Usage: RUBYOPT=-r./gc_hook.rb ruby app.rb

=begin
GC::Profiler.enable
at_exit{ GC::Profiler.raw_data.map{ |d| p(d) } }
=end

require 'objspace'
ObjectSpace.gc_hook = proc { |before, after|
  STDERR.puts "*** mismatch: #{before[:count]} vs #{after[:count]}" if before[:count] != after[:count]

  reason = GC::Profiler.decode_flags(before[:last_collection_flags])
  type = reason.key?(:major_by) ? "MAJOR GC" : "minor gc"
  diff = after[:time] - before[:time]

  STDERR.printf "[%f:% 4d] %s (% 13s) took %1.3fs (%1.3fs cpu)  live: % 8d -> % 8d  free: % 8d -> % 8d %s\n",
    before[:time],
    before[:count],
    type,
    reason.values_at(:major_by, :gc_by).compact.join(","),
    after[:time] - before[:time],
    after[:cputime] - before[:cputime],
    before[:heap_live_slot],
    after[:heap_live_slot],
    before[:heap_free_slot],
    after[:heap_free_slot],
    reason[:immediate_sweep] ? "  +immediate_sweep" : ""
}

__END__

[1386114627.664106:   9] MAJOR GC ( shady,newobj) took 0.004s (0.004s cpu)  live:    50843 ->    50507  free:      514 ->      851
[1386114627.810446:  10] minor gc (       newobj) took 0.002s (0.002s cpu)  live:    50686 ->    50335  free:      671 ->     1022
[1386114627.936074:  11] minor gc (       newobj) took 0.002s (0.002s cpu)  live:    50746 ->    50672  free:      611 ->      685
[1386114628.022459:  12] minor gc (       newobj) took 0.003s (0.003s cpu)  live:    50655 ->    50608  free:      702 ->      749
[1386114628.085437:  13] minor gc (       newobj) took 0.003s (0.003s cpu)  live:    51092 ->    51081  free:      265 ->      276
[1386114628.120031:  14] MAJOR GC ( shady,newobj) took 0.008s (0.008s cpu)  live:    50411 ->    50062  free:      950 ->     1299
[1386114628.170878:  15] minor gc (       newobj) took 0.004s (0.004s cpu)  live:    50954 ->    50639  free:      403 ->      718
[1386114628.253836:  16] minor gc (       newobj) took 0.005s (0.005s cpu)  live:    91183 ->    90919  free:      936 ->     1201
[1386114628.352107:  17] minor gc (       newobj) took 0.004s (0.004s cpu)  live:    91295 ->    91080  free:      824 ->     1040
[1386114628.393363:  18] minor gc (       newobj) took 0.003s (0.003s cpu)  live:    89609 ->    89553  free:     2510 ->     2566
[1386114628.424048:  19] minor gc (       newobj) took 0.002s (0.002s cpu)  live:    89918 ->    89836  free:     2202 ->     2285
[1386114628.538721:  20] MAJOR GC (oldgen,newobj) took 0.017s (0.017s cpu)  live:   158552 ->   158407  free:     6934 ->     7079
[1386114628.984449:  21] minor gc (       malloc) took 0.010s (0.010s cpu)  live:   126813 ->    75608  free:    38673 ->    90007   +immediate_sweep
[1386114629.271977:  22] minor gc (       newobj) took 0.006s (0.006s cpu)  live:   164437 ->   164358  free:     1049 ->     1128
[1386114629.430584:  23] minor gc (       newobj) took 0.007s (0.007s cpu)  live:   164528 ->   164143  free:      959 ->     1344
[1386114629.633070:  24] minor gc (       newobj) took 0.006s (0.006s cpu)  live:   163951 ->   163736  free:     1535 ->     1751
[1386114629.936994:  25] minor gc (       newobj) took 0.010s (0.010s cpu)  live:   164485 ->   164431  free:     1001 ->     1055
[1386114630.264757:  26] MAJOR GC ( shady,newobj) took 0.024s (0.024s cpu)  live:   164520 ->   164301  free:      966 ->     1185
[1386114630.389236:  27] minor gc (       newobj) took 0.008s (0.008s cpu)  live:   164818 ->   164612  free:      668 ->      875
[1386114630.445923:  28] minor gc (       newobj) took 0.007s (0.007s cpu)  live:   165458 ->   165299  free:       28 ->      187
[1386114630.679625:  29] minor gc (       malloc) took 0.023s (0.022s cpu)  live:   287667 ->   145862  free:     1726 ->   143630   +immediate_sweep
[1386114631.011979:  30] minor gc (       newobj) took 0.011s (0.011s cpu)  live:   287909 ->   287548  free:     1484 ->     1845
[1386114631.264829:  31] minor gc (       newobj) took 0.012s (0.012s cpu)  live:   287248 ->   286913  free:     2145 ->     2480
[1386114631.462232:  32] minor gc (       newobj) took 0.011s (0.011s cpu)  live:   286184 ->   286173  free:     3209 ->     3220
[1386114631.689803:  33] minor gc (       newobj) took 0.012s (0.012s cpu)  live:   287489 ->   287482  free:     1904 ->     1911
[1386114631.891898:  34] minor gc (       newobj) took 0.011s (0.011s cpu)  live:   287265 ->   287258  free:     2128 ->     2135
[1386114632.111391:  35] minor gc (       newobj) took 0.015s (0.015s cpu)  live:   288582 ->   288576  free:      811 ->      817
[1386114632.688199:  36] MAJOR GC (oldgen,newobj) took 0.068s (0.068s cpu)  live:   520870 ->   520506  free:       42 ->      406
[1386114633.210290:  37] minor gc (       newobj) took 0.011s (0.011s cpu)  live:   520882 ->   520506  free:       30 ->      406
[1386114633.599533:  38] minor gc (       newobj) took 0.016s (0.014s cpu)  live:   520242 ->   519893  free:      670 ->     1019
[1386114634.092071:  39] minor gc (       malloc) took 0.023s (0.023s cpu)  live:   553437 ->   385813  free:     3341 ->   171082   +immediate_sweep
[1386114634.624861:  40] minor gc (       malloc) took 0.027s (0.027s cpu)  live:   633442 ->   407454  free:     2819 ->   228953   +immediate_sweep
[1386114635.226138:  41] minor gc (       malloc) took 0.030s (0.030s cpu)  live:   687679 ->   424126  free:     5239 ->   268948   +immediate_sweep
[1386114635.685916:  42] minor gc (       malloc) took 0.031s (0.031s cpu)  live:   689739 ->   440597  free:     3179 ->   252476   +immediate_sweep
[1386114636.207198:  43] minor gc (       malloc) took 0.040s (0.036s cpu)  live:   778669 ->   463937  free:     1475 ->   316338   +immediate_sweep
[1386114636.832351:  44] minor gc (       malloc) took 0.036s (0.035s cpu)  live:   784178 ->   494622  free:     4117 ->   293854   +immediate_sweep
[1386114637.127497:  45] minor gc (       malloc) took 0.039s (0.038s cpu)  live:   707171 ->   507625  free:    81124 ->   280671   +immediate_sweep
[1386114637.372650:  46] minor gc (       malloc) took 0.035s (0.035s cpu)  live:   696781 ->   515426  free:    91514 ->   272869   +immediate_sweep
[1386114637.704114:  47] minor gc (       malloc) took 0.041s (0.041s cpu)  live:   751174 ->   527551  free:    37121 ->   260745   +immediate_sweep
[1386114638.003907:  48] minor gc (       malloc) took 0.046s (0.046s cpu)  live:   742655 ->   538667  free:    45640 ->   249628   +immediate_sweep
[1386114638.303950:  49] minor gc (       malloc) took 0.040s (0.040s cpu)  live:   746222 ->   548757  free:    42073 ->   239538   +immediate_sweep
[1386114638.653671:  50] minor gc (       malloc) took 0.046s (0.046s cpu)  live:   792491 ->   562513  free:     3550 ->   233937   +immediate_sweep
[1386114639.031762:  51] minor gc (       newobj) took 0.030s (0.029s cpu)  live:   796994 ->   796589  free:     1900 ->     2305
[1386114640.630710:  52] MAJOR GC ( shady,method) took 0.205s (0.200s cpu)  live:  1178596 ->   387670  free:     4669 ->   795933   +immediate_sweep