Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
matthewford opened this issue Nov 20, 2022 · 5 comments

Comments

@matthewford
Copy link

matthewford commented Nov 20, 2022

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: mastodon/mastodon@main...matthewford:mastodon:truffle-ruby

@matthewford
Copy link
Author

matthewford commented Nov 20, 2022

Retrying with graalvm, I can't install head (but that's a ruby-build issue rbenv/ruby-build#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
Copy link
Member

eregon commented Nov 21, 2022

Thank you for the report.

truffleruby-head/truffleruby+graalvm-head is needed at least for the 3877eeb fix and it should also avoid that segfault you see on 22.3.0 (see #2801).
I fixed rbenv/ruby-build#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
Copy link
Member

eregon commented Nov 21, 2022

See mastodon/mastodon@4e4b72a#r90590935 regarding the GC.start calls.

@matthewford
Copy link
Author

matthewford commented Nov 21, 2022

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

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

@eregon
Copy link
Member

eregon commented Dec 9, 2022

The segfault on 22.3 is very likely the same as #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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

2 participants