Mashalling in Ruby 2.2.0 slower than 2.1.5

Question

I have a complex object, my_object, which I marshal with

Marshal.dump(my_object)

I have benchmarked the performance of calling that line 100 times in both 2.1.5p273 and 2.2.0, and below are the results:

2.1.5  
                  user     system      total        real
Marshal Dump  7.310000   0.120000   7.430000 (  8.988470)
Marshal Dump  7.520000   0.050000   7.570000 (  8.210356)
Marshal Dump  7.610000   0.050000   7.660000 (  8.432685)

2.2.0
                  user     system      total        real
Marshal Dump 26.480000   0.150000  26.630000 ( 29.591742)
Marshal Dump 24.100000   0.300000  24.400000 ( 28.520397)
Marshal Dump 26.210000   0.210000  26.420000 ( 29.993412)

(I ran the benchmark 3 times for each version, to be thorough.)

As you can see, it's taking in excess of 3 times as long in 2.2.0 vs 2.1.5. I zeroed in on Marshal.dump because, using the ruby-prof gem, it showed me that that was the line that was performing poorly; but I can't find a way to get the methods that Marshal.dump itself calls in the profiler.

Edit: see my answer with a minimal repro, found after much experimentation

Answer 1

The source location is nil.

Marshal.method(:dump).source_location
#=> nil

This means that it is a C implemented method, and there is no more Ruby code that you can trace. In other words, it is an atomic/elementary method.

If you believe your result is valid, then I suggest you to post that as a bug in Ruby trunk. Several performance issues have indeed been found for the newest versions of Ruby, so your case does not seem unusual.

Answer 2

It's marshalling floats that causes the slowdown.

require 'benchmark'

class ToBeMarshaled

  def initialize n
    @a = []
    n.times do |i|
      @a << i.to_f
    end
  end

end

tbm = ToBeMarshaled.new(10000)

n = 100

Benchmark.bm do |x|
  x.report("Marshal Dump") {for i in 1..n; Marshal.dump(tbm); end}
end

results (ran benchmark 3 times for each Ruby version):

2.1.5
                  user     system      total        real
Marshal Dump  0.640000   0.010000   0.650000 (  0.744080)
Marshal Dump  0.670000   0.000000   0.670000 (  0.758597)
Marshal Dump  0.650000   0.020000   0.670000 (  0.747583)

2.2.0
                  user     system      total        real
Marshal Dump 25.070000   0.220000  25.290000 ( 27.980023)
Marshal Dump 24.100000   0.160000  24.260000 ( 26.633049)
Marshal Dump 24.440000   0.230000  24.670000 ( 27.540826)

~35 times slower.

If you take the ".to_f" off of that code, you get:

2.1.5
                  user     system      total        real
Marshal Dump  0.160000   0.000000   0.160000 (  0.180247)
Marshal Dump  0.180000   0.000000   0.180000 (  0.189485)
Marshal Dump  0.160000   0.010000   0.170000 (  0.191304)

2.2.0
                  user     system      total        real
Marshal Dump  0.120000   0.010000   0.130000 (  0.146710)
Marshal Dump  0.130000   0.010000   0.140000 (  0.159851)
Marshal Dump  0.130000   0.000000   0.130000 (  0.143917)

2.2.0 slightly edges out 2.1.5.