Bug #10761: Marshal.dump 100% slower in 2.2.0 vs 2.1.5

• Status: Closed
• Assignee: -
• Target version: -
• ruby -v: 2.2.0
• Backport: 2.0.0: DONTNEED, 2.1: DONTNEED, 2.2: DONE

[jenkoruby (David Jenkins)]

Calling Marshal.dump on a complex (nested) object 100 times shows the following:

2.1.5
user system total real
Marshal Dump 24.350000 0.250000 24.600000 ( 29.330294)

2.2.0
user system total real
Marshal Dump 50.450000 0.140000 50.590000 ( 52.268773)

To reproduce, put marshal_slow.rb and nested_ds.txt in same directory and run marshal_slow.rb.

I found that Marshal.dump only shows this kind of discrepancy on deeply nested objects. The nested_ds.txt file is a dump of an object that contained a collection of sub objects of the same type.

[jenkoruby (David Jenkins)]

• File dataset_dump.txt dataset_dump.txt added
• File better_slow_marshal.rb better_slow_marshal.rb added

I have an even better repro (attached) which yielded the following results:

2.1.5
user system total real
Marshal Dump 4.250000 0.080000 4.330000 ( 4.682933)
Marshal Dump 4.440000 0.040000 4.480000 ( 4.613776)
Marshal Dump 4.500000 0.050000 4.550000 ( 4.717084)

2.2.0
user system total real
Marshal Dump 13.390000 0.070000 13.460000 ( 13.742177)
Marshal Dump 14.540000 0.090000 14.630000 ( 14.884479)
Marshal Dump 13.580000 0.060000 13.640000 ( 13.968422)

roughly 3 times slower in 2.2.0 than in 2.1.5

[jenkoruby (David Jenkins)]

Final repro, no data files, all code:

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

[normalperson (Eric Wong)]

[e-mail] wrote:

Final repro, no data files, all code:

Thanks, looks like my fault in r45384 [Feature #9425]
Looking for a fix which doesn't involve reverting...

[normalperson (Eric Wong)]

• File [e-mail] [e-mail] added
• Backport changed from 2.0.0: UNKNOWN, 2.1: UNKNOWN, 2.2: UNKNOWN to 2.0.0: UNKNOWN, 2.1: UNKNOWN, 2.2: REQUIRED

Using Marshal.load on untrusted data is too risky for me,
so I only tested your last test case:

$ ./patched/ruby --disable=gems /tmp/marshal.rb
real 0m0.311s
user 0m0.308s
sys 0m0.002s

$ ~/ruby-2.1/bin/ruby --disable=gems /tmp/marshal.rb
real 0m0.354s
user 0m0.351s
sys 0m0.002s

patch (also attached):
http://80x24.org/spew/m/[e-mail]

benchmark suite results (with new benchmarks for flonum keys):
http://80x24.org/spew/m/8d1ad66566f9e76b07e000e8dd335b9ebcb06b01.txt

I'll commit soon unless there's problems.

[normalperson (Eric Wong)]

[e-mail] wrote:

patch (also attached):
http://80x24.org/spew/m/[e-mail]

NAK. "gem install " seems to infinite loop with this.

[normalperson (Eric Wong)]

Eric Wong [e-mail] wrote:

[e-mail] wrote:

patch (also attached):
http://80x24.org/spew/m/[e-mail]

NAK. "gem install " seems to infinite loop with this.

Testing this now on top of the previous commit:
http://80x24.org/spew/m/be1385d4f7cea47dae5aebc7577f3d9c94c18d21.txt

• Status changed from Open to Closed
• % Done changed from 0 to 100

Applied in changeset r49376.

---

fix flonum hashing regression from r45384

• st.c (st_numhash): mix float value for flonum
• hash.c (rb_any_hash): ditto
• benchmark/bm_hash_aref_flo.rb: new benchmark
• benchmark/bm_hash_ident_flo.rb: ditto
  [Bug #10761]

[normalperson (Eric Wong)]

Committed as r49376. Scary regression, sorry for the breakage :x

[naruse (Yui NARUSE)]

• Backport changed from 2.0.0: UNKNOWN, 2.1: UNKNOWN, 2.2: REQUIRED to 2.0.0: UNKNOWN, 2.1: UNKNOWN, 2.2: DONE

ruby_2_2 r49513 merged revision(s) 49376,49387,49389.

[nobu (Nobuyoshi Nakada)]

• Status changed from Closed to Open
• Backport changed from 2.0.0: UNKNOWN, 2.1: UNKNOWN, 2.2: DONE to 2.0.0: UNKNOWN, 2.1: UNKNOWN, 2.2: REQUIRED

r49386 is missing.

[usa (Usaku NAKAMURA)]

• Backport changed from 2.0.0: UNKNOWN, 2.1: UNKNOWN, 2.2: REQUIRED to 2.0.0: DONTNEED, 2.1: DONTNEED, 2.2: REQUIRED

[naruse (Yui NARUSE)]

• Backport changed from 2.0.0: DONTNEED, 2.1: DONTNEED, 2.2: REQUIRED to 2.0.0: DONTNEED, 2.1: DONTNEED, 2.2: DONE

ruby_2_2 r49513 merged revision(s) 49376,49387,49389.

[usa (Usaku NAKAMURA)]

• Status changed from Open to Closed

[wanabe (_ wanabe)]

• Backport changed from 2.0.0: DONTNEED, 2.1: DONTNEED, 2.2: DONE to 2.0.0: DONTNEED, 2.1: DONTNEED, 2.2: REQUIRED

r49386 is not backported yet in ruby_2_2.
In ruby_2_2@49627, there is '#ifdef USE_FLONUM' in st_numhash() of st.c.
But in trunk, the '#ifdef' has been deleted at r49386.

[naruse (Yui NARUSE)]

• Backport changed from 2.0.0: DONTNEED, 2.1: DONTNEED, 2.2: REQUIRED to 2.0.0: DONTNEED, 2.1: DONTNEED, 2.2: DONE

ruby_2_2 r49513 merged revision(s) 49376,49387,49389.
49668