MJIT の super の速度確認

a.rb

max = ARGV[0].to_i

if ARGV[1]
  require "rbconfig"

  step = ARGV[1].to_i
  puts "%4s %13s %13s %13s" % ["n", "jit", "nojit", "rate"]
  ruby = RbConfig.ruby
  IO.popen("#{ruby} --disable-gems #{__FILE__} #{max}", mode: "r+") do |nojit|
    IO.popen("#{ruby} --disable-gems --jit --jit-verbose=1 #{__FILE__} #{max}", mode: "r+") do |jit|

      0.step(max, step) do |n|
        jit.puts n
        jit.flush
        jit_ips = jit.gets.to_f
        nojit.puts n
        nojit.flush
        nojit_ips = nojit.gets.to_f
      	puts "%4d %13.3f %13.3f %13.3f" % [n, jit_ips, nojit_ips, jit_ips.to_f / nojit_ips.to_f]
        STDOUT.flush
      end
    end
  end

  exit
end

class A0
  def foo
  end

  def foo0
  end
end

i = 0
while i < max
  i += 1
  eval <<~EOS
    class A#{i} < A#{i - 1}
      def foo
        super
      end
      def foo#{i}
        foo#{i - 1}
      end
    end
  EOS
end

if RubyVM::MJIT.enabled?
  a = eval("A#{max}").new
  10.times { a.foo }
  RubyVM::MJIT.pause
end

if ENV["PERF_STAT"]
  $pid = Process.spawn("perf stat -e #{ENV["PERF_STAT"]} -p #{$$}")
  at_exit { Process.kill :INT, $pid }
end

if ENV["PERF_RECORD"]
  Process.spawn("perf record -e #{ENV["PERF_RECORD"]} -p #{$$} -o perf.#{$$}.data")
end

GC.disable
while n = STDIN.gets
  GC.start
  a = eval("A#{n}").new
  c = 1_000_000

  t0 = Time.now
  i = c
  while i > 0
    i -= 1
  end

  t1 = Time.now
  i = c
  while i > 0
    i -= 1
    a.foo
  end

  t2 = Time.now
  sec = t2 - t1 - (t1 - t0)
  puts "%13.3f" % (c / sec)
  STDOUT.flush
end

output.docker.log

$ docker run -it -v `pwd`:/opt/work mtsmfm/ruby-trunk:20180902 sh -c 'cd /opt/work && ruby a.rb 50 5'
   n           jit         nojit          rate
JIT success (40.9ms): block in <main>@a.rb:54 -> /tmp/_ruby_mjit_p10u0.c
JIT success (825.4ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u1.c
JIT success (828.0ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u2.c
JIT success (838.7ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u3.c
JIT success (843.2ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u4.c
JIT success (835.8ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u5.c
JIT success (829.6ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u6.c
JIT success (830.2ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u7.c
JIT success (852.8ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u8.c
JIT success (828.7ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u9.c
JIT success (886.7ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u10.c
JIT success (883.1ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u11.c
JIT success (873.9ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u12.c
JIT success (881.6ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u13.c
JIT success (861.3ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u14.c
JIT success (851.9ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u15.c
JIT success (830.6ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u16.c
JIT success (828.3ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u17.c
JIT success (828.9ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u18.c
JIT success (828.7ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u19.c
JIT success (832.5ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u20.c
JIT success (872.3ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u21.c
JIT success (993.6ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u22.c
JIT success (901.4ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u23.c
JIT success (861.2ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u24.c
JIT success (954.2ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u25.c
JIT success (912.5ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u26.c
JIT success (881.2ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u27.c
JIT success (874.4ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u28.c
JIT success (878.9ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u29.c
JIT success (869.6ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u30.c
JIT success (948.5ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u31.c
JIT success (832.0ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u32.c
JIT success (897.9ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u33.c
JIT success (830.6ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u34.c
JIT success (843.6ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u35.c
JIT success (832.6ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u36.c
JIT success (831.3ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u37.c
JIT success (858.2ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u38.c
JIT success (843.9ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u39.c
JIT success (843.6ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u40.c
JIT success (832.8ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u41.c
JIT success (835.8ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u42.c
JIT success (834.4ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u43.c
JIT success (840.7ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u44.c
JIT success (839.8ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u45.c
JIT success (829.9ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u46.c
JIT success (829.2ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u47.c
JIT success (834.5ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u48.c
JIT success (836.1ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u49.c
JIT success (831.7ms): foo@(eval):2 -> /tmp/_ruby_mjit_p10u50.c
JIT success (22.0ms): foo@a.rb:30 -> /tmp/_ruby_mjit_p10u51.c
JIT compaction (20.6ms): Compacted 52 methods -> /tmp/_ruby_mjit_p10u52.so
   0  46553092.638  61411828.459         0.758
   5   4653578.669   4810737.366         0.967
  10   2247873.193   2226699.888         1.010
  15   1391147.012   1449608.291         0.960
  20    945563.755    998231.630         0.947
  25    643280.385    718253.316         0.896
  30    472338.065    545765.676         0.865
  35    369712.646    413473.449         0.894
  40    291569.314    324539.623         0.898
  45    225867.583    269685.704         0.838
  50    185342.295    225625.997         0.821
Successful MJIT finish

output.log

$ ruby a.rb 50 5
   n           jit         nojit          rate
JIT success (49.5ms): block in <main>@a.rb:54 -> /tmp/_ruby_mjit_p23149u0.c
JIT success (1015.8ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u1.c
JIT success (1078.2ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u2.c
JIT success (988.7ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u3.c
JIT success (991.9ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u4.c
JIT success (1000.6ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u5.c
JIT success (1011.4ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u6.c
JIT success (1001.7ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u7.c
JIT success (1025.9ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u8.c
JIT success (1006.3ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u9.c
JIT success (1011.4ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u10.c
JIT success (1035.9ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u11.c
JIT success (991.9ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u12.c
JIT success (992.2ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u13.c
JIT success (1011.2ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u14.c
JIT success (1028.6ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u15.c
JIT success (1039.2ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u16.c
JIT success (1012.3ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u17.c
JIT success (971.4ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u18.c
JIT success (994.1ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u19.c
JIT success (1026.7ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u20.c
JIT success (1006.0ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u21.c
JIT success (1017.5ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u22.c
JIT success (1009.9ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u23.c
JIT success (1020.0ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u24.c
JIT success (1029.8ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u25.c
JIT success (983.7ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u26.c
JIT success (1008.3ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u27.c
JIT success (1000.6ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u28.c
JIT success (1009.9ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u29.c
JIT success (1040.8ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u30.c
JIT success (1009.1ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u31.c
JIT success (1011.0ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u32.c
JIT success (978.0ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u33.c
JIT success (1014.9ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u34.c
JIT success (993.5ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u35.c
JIT success (1004.4ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u36.c
JIT success (1003.0ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u37.c
JIT success (1015.1ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u38.c
JIT success (1023.5ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u39.c
JIT success (1023.8ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u40.c
JIT success (1014.9ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u41.c
JIT success (1010.8ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u42.c
JIT success (1031.1ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u43.c
JIT success (999.1ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u44.c
JIT success (1006.9ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u45.c
JIT success (997.5ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u46.c
JIT success (1006.6ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u47.c
JIT success (1005.9ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u48.c
JIT success (1001.0ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u49.c
JIT success (998.3ms): foo@(eval):2 -> /tmp/_ruby_mjit_p23149u50.c
JIT success (26.2ms): foo@a.rb:30 -> /tmp/_ruby_mjit_p23149u51.c
JIT compaction (23.4ms): Compacted 52 methods -> /tmp/_ruby_mjit_p23149u52.so
   0  43823995.996  48432862.705         0.905
   5   3970578.726   3652718.984         1.087
  10   1891652.383   1889361.728         1.001
  15   1050286.878   1242719.887         0.845
  20    646879.350    860493.721         0.752
  25    449880.703    638558.198         0.705
  30    332877.787    448629.604         0.742
  35    270837.560    370958.229         0.730
  40    216998.985    300943.310         0.721
  45    182295.966    246560.005         0.739
  50    151163.186    206137.127         0.733
Successful MJIT finish

super.rb

require 'benchmark_driver'
max = 40

Benchmark.driver do |x|
  prelude = <<~RUBY
    class A0
      def foo
      end
    
      def foo0
      end
    end
  RUBY
    
  i = 0
  while i < max
    i += 1
    prelude << <<~RUBY
      class A#{i} < A#{i - 1}
        def foo
          super
        end
        def foo#{i}
          foo#{i - 1}
        end
	def bar
	  foo#{i}
	end
      end
    RUBY
  end

  prelude << <<~RUBY
    if RubyVM::MJIT.enabled?
      a = eval("A#{max}").new
      10.times { a.foo; a.bar }
      RubyVM::MJIT.pause
    end

    a = A#{max}.new
  RUBY

  if ENV["PERF_STAT"]
    prelude << <<~RUBY
      $pid = Process.spawn("perf stat -e #{ENV["PERF_STAT"]} -p \#{$$}")
      at_exit { Process.kill :INT, $pid }
    RUBY
  end

  x.rbenv 'trunk', 'trunk,--jit', 'ignore-big-func', 'ignore-big-func,--jit'
  x.prelude prelude

  x.report %{ a.foo }
  # x.report %{ a.bar }
end