Marshal.load of Hashes slow, especially glacial when vm cold

[LillianZ]

Loading the Hash of Hash of Hash below takes
0.075s on MRI,
0.14s at Truffleruby peak,
... and 3s the first time it is run (21x slower than warm).

This is very unfortunate because in most applications we would only expect to to use Marshal load once at the beginning.

require 'benchmark'
alphabet = "A, B, C, D, E, F, G, H, I, J, K, L, M, N, O, P, Q, R, S, T, U, V, W, X, Y, Z".split(", ")
symalphabet = [:AA, :AB, :AC, :AD, :AE, :AF, :AG, :AH, :AI, :AJ, 
 :BA, :BB, :BC, :BD, :BE, :BF, :BG, :BH, :BI, :BJ, 
 :CA, :CB, :CC, :CD, :CE, :CF, :CG, :CH, :CI, :CJ, 
 :DA, :DB, :DC, :DD, :DE, :DF, :DG, :DH, :DI, :DJ, 
 :EA, :EB, :EC, :ED, :EE, :EF, :EG, :EH, :EI, :EJ, 
 :FA, :FB, :FC, :FD, :FE, :FF, :FG, :FH, :FI, :FJ, 
 :GA, :GB, :GC, :GD, :GE, :GF, :GG, :GH, :GI, :GJ, 
 :HA, :HB, :HC, :HD, :HE, :HF, :HG, :HH, :HI, :HJ, 
 :IA, :IB, :IC, :ID, :IE, :IF, :IG, :IH, :II, :IJ, 
 :JA, :JB, :JC, :JD, :JE, :JF, :JG, :JH, :JI, :JJ, 
]
bigh = Hash.new
alphabet.each do |letter1|
  alphabet.each do |letter2|
    h = Hash.new
    symalphabet.each do |symbol|
      h[symbol] = {:a => "String One", :b => "String Two", :c => nil}
    end
    bigh[letter1+letter2] = h
  end
end
str = Marshal.dump(bigh)
puts Benchmark.measure {Marshal.load(str)}

[chrisseaton]

I added Benchmark.ips to the end of this so we can see cold and warmup (maybe bips should print first-iteration...)

require 'benchmark'
require 'benchmark/ips'
alphabet = "A, B, C, D, E, F, G, H, I, J, K, L, M, N, O, P, Q, R, S, T, U, V, W, X, Y, Z".split(", ")
symalphabet = [:AA, :AB, :AC, :AD, :AE, :AF, :AG, :AH, :AI, :AJ, 
 :BA, :BB, :BC, :BD, :BE, :BF, :BG, :BH, :BI, :BJ, 
 :CA, :CB, :CC, :CD, :CE, :CF, :CG, :CH, :CI, :CJ, 
 :DA, :DB, :DC, :DD, :DE, :DF, :DG, :DH, :DI, :DJ, 
 :EA, :EB, :EC, :ED, :EE, :EF, :EG, :EH, :EI, :EJ, 
 :FA, :FB, :FC, :FD, :FE, :FF, :FG, :FH, :FI, :FJ, 
 :GA, :GB, :GC, :GD, :GE, :GF, :GG, :GH, :GI, :GJ, 
 :HA, :HB, :HC, :HD, :HE, :HF, :HG, :HH, :HI, :HJ, 
 :IA, :IB, :IC, :ID, :IE, :IF, :IG, :IH, :II, :IJ, 
 :JA, :JB, :JC, :JD, :JE, :JF, :JG, :JH, :JI, :JJ, 
]
bigh = Hash.new
alphabet.each do |letter1|
  alphabet.each do |letter2|
    h = Hash.new
    symalphabet.each do |symbol|
      h[symbol] = {:a => "String One", :b => "String Two", :c => nil}
    end
    bigh[letter1+letter2] = h
  end
end
str = Marshal.dump(bigh)
puts Benchmark.measure {Marshal.load(str)}

Benchmark.ips do |x|
  x.warmup = 5
  x.report('Marshal.load') { Marshal.load(str) }
end

ruby 2.7.1p83 (2020-03-31 revision a0c7c23c9c) [x86_64-darwin19]
  0.069405   0.008819   0.078224 (  0.078383)
Warming up --------------------------------------
        Marshal.load     1.000  i/100ms
Calculating -------------------------------------
        Marshal.load     17.458  (±11.5%) i/s -     87.000  in   5.033390s

truffleruby (Shopify) 20.3.0-dev-e574e0f3, like ruby 2.6.6, GraalVM CE Native [x86_64-darwin]
 10.043862   1.585444  11.629306 (  5.489669)
Warming up --------------------------------------
        Marshal.load     1.000  i/100ms
Calculating -------------------------------------
        Marshal.load      0.945  (± 0.0%) i/s -      5.000  in   5.452409s

	Cold	Hot
MRI	0.078383s	17.458 ips
TruffleRuby	5.489669	0.945 ips

So this is bad on both cold performance and also hot performance. Thermometer confirms hot during measurement. What we really care about at the moment is the cold performance though - we load a Marshal blob on startup and it's painfully slow.

[LillianZ]

The example Marshalled string has ~3M characters; the Marshalled string we load on startup has ~17M characters. It is indeed slow.

[eregon]

I made a variant of the script where the result of Marshal.dump is saved to a file.
That way, we don't call Marshal.dump during the benchmark, which I guess is also the case for the application's startup?
https://gist.github.com/eregon/e523df1b607bd152a9eef980fd936b8c

I see first iteration times of around 2 seconds, which is slow but probably not that noticeable during startup. It would be nice to have something about the size of the real data, so we can get a feeling of how long it takes and how much we gain on it when optimizing.

Profiling (see the gist) reveals most of the time is spent in Marshal::State#construct which is a somewhat large method dispatching via a big case expression, and 2nd place is Integer#=== , most likely for that big case expression.

One obvious thing here is we could AST-inline Integer#=== to avoid extra boxing, call overhead in interpreter, etc.

Then there are probably better ways to optimize that big case expression since all values are Integer.
Yet the values are not contiguous.
IIRC There is an optimization in graal for turning if e == SOME_INT1 else if e == SOME_INT2 else if ... to a Java switch, we should check if it triggers here.
Maybe a Ruby Array of Proc's would be better for dispatch. That way we'd likely wouldn't inline anything over that call, but then we'd have a clear place where to stop and start inlining. We might want to treat special case like true/false/nil specially.

[chrisseaton]

That way, we don't call Marshal.dump during the benchmark, which I guess is also the case for the application's startup?

Yes it comes from a file. There's some other steps involved - we'll open separate issues for those too.

[petenorth]

A lot of time is spent in Marshal::State#construct for the rails rspec tests of an app I've been testing with TruffleRuby.

[gogainda]

Sorry for my ignorance but doens't Marshal::State#construct has O(n) pef here? Would it be better to have some map-like implementation?

[eregon]

Yes, case in general is O(n) in Ruby because it's just if when1 === expr elsif when2 === expr elsif ... semantically. But I think CRuby optimizes when it's all when SOME_INTEGER to use a Hash internally or so. A Hash has its own costs though.

It would be cool to see if we can get that Graal optimization to kick in and transform it essentially to a Java switch which uses various strategies depending on the when values. Yet most of the time in construct in the profiles is in interpreter, so whatever we do needs to be efficient in interpreter too.

[chrisseaton]

It would be cool to see if we can get that Graal optimization to kick in

But remember it's cold for quite a bit of this run.

[petenorth]

Could the JRuby implementation be used?

https://github.com/jruby/jruby/blob/de19365b3f95fbaacd3f45267bde14c09f469554/core/src/main/java/org/jruby/runtime/marshal/UnmarshalStream.java#L73

Java code like this would be AOT compiled into the TruffleRuby native image executable, no?

Or is this against an over arching design ethos?

[eregon]

Potentially we could rewrite Marshal in Java, that's a possibility. We cannot just "reuse" JRuby's implementation because JRuby's uses different representations than TruffleRuby for basically every Ruby object/value.
We could also only have construct as a Java @CoreMethod if the goal is to use Java's switch. Java code is typically much harder/higher effort to maintain than Ruby code, so it would need to be worth it. Java code is generally beneficial for startup/warmup performance, but is a high cost to maintain and is often extremely verbose.

So yes, one possibility, but I think we should explore a few other things first (notably AST-inline Integer#===). If we end up optimizing Ruby's case it will apply not only to Marshal but to many other case in Ruby code.

[eregon]

As a side note, for this use case, if the marshalled objects are rather simple, it might be feasible to store them as part of pre-initialization when building the TruffleRuby Native Image. Then as soon as TruffleRuby starts up, the objects would already be in the heap, and there would be no deserialization at all.
Speeding up Marshal.load is worth on its own, but that sounds an interesting optimization to optimize application startup.

[eregon]

It seems quite a bit faster after AST-inlining Integer#===: 6860647
Before (06662f0):

$ precise-time 10 `which ruby` bench_marshal_load.rb
2146 [1956-2356] ms

After (929d527)

$ precise-time 10 `which ruby` bench_marshal_load.rb
1735 [1556-1901] ms

The format is average [min-max]

[eregon]

If we use --engine.MultiTier we get down to 1 second (1066 [1058-1076] ms).
Sampling without MultiTier:

$ ruby --experimental-options --cpusampler --cpusampler.SampleInternal bench_marshal_load.rb
 Name                                                         |      Total Time     |  Opt % ||       Self Time     |  Opt % | Location             
----------------------------------------------------------------------------------------------------------------------------------------------------
 Marshal::State#construct                                     |       1073ms  96.2% |   0.0% ||        337ms  30.2% |   0.9% | resource:/truffleruby/core/marshal.rb~561-654:14615-17159 
 Marshal::State#add_object                                    |        207ms  18.6% |   0.0% ||        119ms  10.7% |   0.0% | resource:/truffleruby/core/marshal.rb~549-553:14384-14494 
 block in Marshal::State#construct_hash                       |       1073ms  96.2% |   0.0% ||         98ms   8.8% |  24.5% | resource:/truffleruby/core/marshal.rb~760:19325-19356 
 Integer#times                                                |       1073ms  96.2% |   0.0% ||         73ms   6.5% |  35.6% | resource:/truffleruby/core/integer.rb~135-144:4106-4252 
 Marshal::State#construct_string                              |        193ms  17.3% |  18.7% ||         67ms   6.0% |  53.7% | resource:/truffleruby/core/marshal.rb~229-252:7053-7724 

Sampling with MultiTier:

$ ruby --experimental-options --engine.MultiTier --cpusampler --cpusampler.SampleInternal bench_marshal_load.rb
 Name                                                         |      Total Time     |  Opt % ||       Self Time     |  Opt % | Location             
----------------------------------------------------------------------------------------------------------------------------------------------------
 Marshal::State#construct                                     |        669ms  94.2% |   0.0% ||        194ms  27.3% |  16.5% | resource:/truffleruby/core/marshal.rb~561-654:14615-17159 
 Marshal::StringState#consume_byte                            |         65ms   9.2% |  58.5% ||         53ms   7.5% |  54.7% | resource:/truffleruby/core/marshal.rb~1262-1267:31843-32023 
 block in Marshal::State#construct_hash                       |        668ms  94.1% |  35.2% ||         49ms   6.9% |  38.8% | resource:/truffleruby/core/marshal.rb~760:19325-19356 
 Integer#times                                                |        668ms  94.1% |   0.0% ||         40ms   5.6% |  50.0% | resource:/truffleruby/core/integer.rb~135-144:4106-4252 
 Marshal::State#get_byte_sequence                             |         83ms  11.7% |  77.1% ||         35ms   4.9% |  82.9% | resource:/truffleruby/core/marshal.rb~945-948:23887-23969 

[norswap]

I'm going to take a stab at this.
Is the symalphabet example from above representative of the actual 17M workload, or does that have a more varied structure?