Performance of rspec on the mastodon test suite is very slow compared to MRI

[matthewford]

Hello,

I'm trying to get mastodon to run in truffleruby, however one thing I have noticed is the specs run orders of magnitude slower thanunder MRI.

I'm using this branch: https://github.com/matthewford/mastodon/tree/truffle-ruby Diff: https://github.com/mastodon/mastodon/compare/main...matthewford:mastodon:truffle-ruby

[matthewford]

Retrying with graalvm, I can't install head (but that's a ruby-build issue https://github.com/rbenv/ruby-build/issues/2092), and using the JVM flag

update: I cant get specs to run with ruby truffleruby+graalvm-22.3.0, seeing this error:

# A fatal error has been detected by the Java Runtime Environment:
#
#  SIGSEGV (0xb) at pc=0x0000000120146745, pid=78523, tid=4867
#
# JRE version: OpenJDK Runtime Environment GraalVM CE 22.3.0 (11.0.17+8) (build 11.0.17+8-jvmci-22.3-b08)
# Java VM: OpenJDK 64-Bit Server VM GraalVM CE 22.3.0 (11.0.17+8-jvmci-22.3-b08, mixed mode, sharing, tiered, jvmci, jvmci compiler, compressed oops, g1 gc, bsd-amd64)
# Problematic frame:
# J 20153 jvmci com.oracle.truffle.llvm.nativemode.runtime.memory.LLVMNativeMemory.putI32(Lcom/oracle/truffle/api/nodes/Node;JI)V (31 bytes) @ 0x0000000120146745 [0x0000000120146700+0x0000000000000045]
#
# Core dump will be written. Default location: /cores/core.78523
#
# An error report file with more information is saved as:
# /Users/matthewford/Documents/GitHub/mastodon/hs_err_pid78523.log
Compiled method (c1)  101905 17979       3       com.oracle.truffle.llvm.runtime.nodes.memory.store.LLVMI32StoreNode::doOp (14 bytes)
 total in heap  [0x0000000118153210,0x0000000118153fd8] = 3528
 relocation     [0x0000000118153378,0x0000000118153400] = 136
 main code      [0x0000000118153400,0x0000000118153d80] = 2432
 stub code      [0x0000000118153d80,0x0000000118153de0] = 96
 oops           [0x0000000118153de0,0x0000000118153de8] = 8
 metadata       [0x0000000118153de8,0x0000000118153e18] = 48
 scopes data    [0x0000000118153e18,0x0000000118153ed0] = 184
 scopes pcs     [0x0000000118153ed0,0x0000000118153fb0] = 224
 dependencies   [0x0000000118153fb0,0x0000000118153fb8] = 8
 nul chk table  [0x0000000118153fb8,0x0000000118153fd8] = 32
Compiled method (c1)  101906 30781       3       com.oracle.truffle.llvm.runtime.nodes.memory.LLVMGetElementPtrNodeGen::executeGeneric_generic2 (274 bytes)
 total in heap  [0x0000000118705f90,0x000000011870d9c8] = 31288
 relocation     [0x00000001187060f8,0x00000001187064f0] = 1016
 main code      [0x0000000118706500,0x000000011870ca20] = 25888
 stub code      [0x000000011870ca20,0x000000011870cac0] = 160
 oops           [0x000000011870cac0,0x000000011870cae0] = 32
 metadata       [0x000000011870cae0,0x000000011870cbe8] = 264
 scopes data    [0x000000011870cbe8,0x000000011870d2b8] = 1744
 scopes pcs     [0x000000011870d2b8,0x000000011870d938] = 1664
 dependencies   [0x000000011870d938,0x000000011870d940] = 8
 nul chk table  [0x000000011870d940,0x000000011870d9c8] = 136
Could not load hsdis-amd64.dylib; library not loadable; PrintAssembly is disabled
#
# If you would like to submit a bug report, please visit:
#   https://github.com/oracle/graal/issues
#
[1]    78523 abort      DISABLE_SIMPLECOV=true ./bin/rspec ./spec/controllers

[eregon]

Thank you for the report.

truffleruby-head/truffleruby+graalvm-head is needed at least for the https://github.com/oracle/truffleruby/commit/3877eeb6d9016d796f1fbc385c908c781e870517 fix and it should also avoid that segfault you see on 22.3.0 (see https://github.com/oracle/truffleruby/issues/2801). I fixed https://github.com/rbenv/ruby-build/issues/2092.

It's expected for an optimizing JIT to run tests slower than in interpreter without JIT like CRuby due to profiling overheads, etc. However it shouldn't be orders of magnitude.

Do you have numbers for maybe a subset of the test suite? Something that can be quite expensive is explicit GC.start calls (that's quite a hack), but it seems you removed those in your branch. Another thing could be suprocesses, as each subprocess needs to warmup.

[eregon]

See https://github.com/mastodon/mastodon/commit/4e4b72a1ffa18de8280a0625e322f9c55df114d1#r90590935 regarding the GC.start calls.

[matthewford]

@eregon yeah in my brach I removed all the GC calls.

I'll try again with truffleruby-head/truffleruby+graalvm-head

[eregon]

The segfault on 22.3 is very likely the same as https://github.com/oracle/truffleruby/issues/2801 so yeah fixed on -dev.

I've run the tests with:

RAILS_ENV=test bundle exec rake db:migrate
RAILS_ENV=test bundle exec rake webpacker:compile
RAILS_ENV=test bundle exec rake

and then I tried (modified from the printed command line)

bundle exec ruby --cpusampler -I/home/eregon/code/mastodon/vendor/bundle/truffleruby/3.1.2.4/gems/rspec-core-3.11.0/lib:/home/eregon/code/mastodon/vendor/bundle/truffleruby/3.1.2.4/gems/rspec-support-3.11.1/lib /home/eregon/code/mastodon/vendor/bundle/truffleruby/3.1.2.4/gems/rspec-core-3.11.0/exe/rspec --pattern spec/\*\*\{,/\*/\*\*\}/\*_spec.rb

The profile shows:

------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Thread[main,5,main]
 Name                                                                                                                                                         ||             Total Time    ||              Self Time    || Location             
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Kernel#sleep                                                                                                                                                 ||            60780ms   2.8% ||            60780ms   2.8% || (core)~1:0
 Truffle::RegexpOperations.match_in_region                                                                                                                    ||            11350ms   0.5% ||            10880ms   0.5% || resource:/truffleruby/core/truffle/regexp_operations.rb~76-84:2346-2811
 Hash#[]                                                                                                                                                      ||            19250ms   0.9% ||             9810ms   0.5% || (core)~1:0
 Kernel#gem_original_require                                                                                                                                  ||            50410ms   2.4% ||             8840ms   0.4% || resource:/truffleruby/core/kernel.rb~226-238:7136-7516
 Array#<<                                                                                                                                                     ||             8730ms   0.4% ||             8730ms   0.4% || (core)~1:0
 Kernel#class                                                                                                                                                 ||             8440ms   0.4% ||             8440ms   0.4% || (core)~1:0
 ripper_yyparse                                                                                                                                               ||            13710ms   0.6% ||             8130ms   0.4% || ripper.c~6256:0
 Truffle::Interop.execute                                                                                                                                     ||            10630ms   0.5% ||             8040ms   0.4% || (core)~1:0
 Hash#[]=                                                                                                                                                     ||             8850ms   0.4% ||             6190ms   0.3% || (core)~1:0
 BasicObject#==                                                                                                                                               ||             5970ms   0.3% ||             5970ms   0.3% || (core)~1:0
 rb_funcallv_public                                                                                                                                           ||             7050ms   0.3% ||             5250ms   0.2% || call.c~44:0
 Hash#default                                                                                                                                                 ||             6210ms   0.3% ||             5200ms   0.2% || resource:/truffleruby/core/hash.rb~184-190:5675-5851

So a lot of time spent sleeping, which seems weird.