Project

General

Profile

Actions

Bug #10761

closed

Marshal.dump 100% slower in 2.2.0 vs 2.1.5

Added by jenkoruby (David Jenkins) about 9 years ago. Updated about 9 years ago.

Status:
Closed
Assignee:
-
Target version:
-
[ruby-core:<unknown>]

Description

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.


Files

nested_ds.txt (2.1 MB) nested_ds.txt Large file to populate object which in turn will be Marshal.dump'd jenkoruby (David Jenkins), 01/21/2015 05:08 AM
marshal_slow.rb (212 Bytes) marshal_slow.rb Code that runs benchmark on Marshal.dump jenkoruby (David Jenkins), 01/21/2015 05:12 AM
dataset_dump.txt (362 KB) dataset_dump.txt jenkoruby (David Jenkins), 01/21/2015 02:47 PM
better_slow_marshal.rb (239 Bytes) better_slow_marshal.rb jenkoruby (David Jenkins), 01/21/2015 02:48 PM
flonum-hash-fixup-r45384-v1@r49365.patch (2.21 KB) flonum-hash-fixup-r45384-v1@r49365.patch normalperson (Eric Wong), 01/21/2015 10:20 PM

Updated by jenkoruby (David Jenkins) about 9 years ago

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

Updated by jenkoruby (David Jenkins) about 9 years ago

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

Updated by normalperson (Eric Wong) about 9 years ago

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...

Updated by normalperson (Eric Wong) about 9 years ago

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/flonum-hash-fixup-r45384-v1@r49365.txt

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

I'll commit soon unless there's problems.

Updated by normalperson (Eric Wong) about 9 years ago

wrote:

patch (also attached):
http://80x24.org/spew/m/flonum-hash-fixup-r45384-v1@r49365.txt

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

Updated by normalperson (Eric Wong) about 9 years ago

Eric Wong wrote:

wrote:

patch (also attached):
http://80x24.org/spew/m/flonum-hash-fixup-r45384-v1@r49365.txt

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

Actions #7

Updated by Anonymous about 9 years ago

  • 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]

Updated by normalperson (Eric Wong) about 9 years ago

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

Updated by naruse (Yui NARUSE) about 9 years ago

  • 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.

Updated by nobu (Nobuyoshi Nakada) about 9 years ago

  • 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.

Updated by usa (Usaku NAKAMURA) about 9 years ago

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

Updated by naruse (Yui NARUSE) about 9 years ago

  • 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.

Updated by usa (Usaku NAKAMURA) about 9 years ago

  • Status changed from Open to Closed

Updated by wanabe (_ wanabe) about 9 years ago

  • 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.

Updated by naruse (Yui NARUSE) about 9 years ago

  • 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

Actions

Also available in: Atom PDF

Like0
Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0