rails: Extremely slow boot with thousands routes and probably hanging

[deepj]

Today's jodosha released his ruby web benchmark (see https://twitter.com/hanamirb/status/1233002378930065408).

So I wanted to try hanami-api and TruffleRuby. Unfortunately, hanami-api requires 2.7. OK. So let's run rails and 10000 routes. And I was badly surprised. MRI boots it in ~8 secs. TruffleRuby it wasn't able to do that either in 15 minutes (then I killed it).

What I noticed. The most time it probably spent in action_dispatch/journey/visitors.rb

from ~/.gem/truffleruby/2.6.5/gems/actionpack-6.0.2.1/lib/action_dispatch/journey/visitors.rb:104:in `visit_CAT'
from ~/.gem/truffleruby/2.6.5/gems/actionpack-6.0.2.1/lib/action_dispatch/journey/visitors.rb:104:in `visit'
from ~/.gem/truffleruby/2.6.5/gems/actionpack-6.0.2.1/lib/action_dispatch/journey/visitors.rb:163:in `visit'
from ~/.gem/truffleruby/2.6.5/gems/actionpack-6.0.2.1/lib/action_dispatch/journey/visitors.rb:108:in `binary'
from ~/.gem/truffleruby/2.6.5/gems/actionpack-6.0.2.1/lib/action_dispatch/journey/visitors.rb:110:in `visit_CAT'
from ~/.gem/truffleruby/2.6.5/gems/actionpack-6.0.2.1/lib/action_dispatch/journey/visitors.rb:104:in `visit'
from ~/.gem/truffleruby/2.6.5/gems/actionpack-6.0.2.1/lib/action_dispatch/journey/visitors.rb:163:in `visit'
from ~/.gem/truffleruby/2.6.5/gems/actionpack-6.0.2.1/lib/action_dispatch/journey/visitors.rb:108:in `binary'

To reproduce:

git clone https://github.com/jodosha/ruby-web-bench.git
cd ruby-web-bench
gem install rails puma
rackup apps/rails-10000.ru

[deepj]

BTW: Roda with 10000 routes was loaded quite fast over this. But a bit slower than in MRI

[bjfish]

I am able to run this after a few minutes on the latest master.

[deepj]

@bjfish can you compare it with MRI? Because in my case it takes only 8 secs but it's over 15 minutes on TruffleRuby. My MacBook Pro is pretty old

[ocher]

I'm having the same issue. We've got 763 routes in our app, and it takes quite a long time (with a very high CPU load) to start the app. Not sure if it is a number of routes, or the size of the app, but unfortunately at the moment it is a blocker and we cannot start using TruffleRuby.

[gogainda]

@eregon should we give this issue some attention?

[gogainda]

@ocher can you provide a sample application with reproducible issue?

[ocher]

@gogainda Unfortunately I'm not able to provide you a sample application, because it is our internal app which I cannot share. But I'm happy to test if you have anything new which you think should solve the problem. 👍

[eregon]

It would be interesting if you could share the results of "require profiling" as described in https://github.com/oracle/truffleruby/blob/master/doc/contributor/profiling.md#require-profiling

So something like:

TRUFFLERUBYOPT="--experimental-options --cpusampler --metrics-profile-require=summary" time bundle exec rake environment |& grep "metrics "

[ocher]

There you go:

metrics searching        |       5964ms   6.9% |   5.4% ||       5964ms   6.9% |   5.4% | (metrics)~1:0 
metrics require          |      84563ms  98.0% |   0.0% ||       3875ms   4.5% |   2.6% | (metrics)~1:0 
metrics parsing          |       2280ms   2.6% |   1.4% ||       2280ms   2.6% |   1.4% | (metrics)~1:0 
metrics execute          |      84503ms  98.0% |   0.0% ||        759ms   0.9% |   0.1% | (metrics)~1:0 
metrics translating      |        437ms   0.5% |   3.9% ||        437ms   0.5% |   3.9% | (metrics)~1:0 

123.33 real       311.74 user        17.80 sys

[gogainda]

@ocher could you double check this issue again? Locally I didn't notice that it's slow or hanging

[ocher]

Hi @gogainda

Yes, it is still slow for me. I've upgraded to:

truffleruby 21.0.0, like ruby 2.7.2, GraalVM CE Native [x86_64-darwin]

And here are the results:

metrics searching    |       6543ms   5.9% |   0.0% ||       6543ms   5.9% |   0.0% | (metrics)~1:0 
metrics require      |     108928ms  98.2% |   0.0% ||       5918ms   5.3% |   0.0% | (metrics)~1:0 
metrics parsing      |       2248ms   2.0% |   0.0% ||       2248ms   2.0% |   0.0% | (metrics)~1:0 
metrics translating  |        466ms   0.4% |   0.0% ||        466ms   0.4% |   0.0% | (metrics)~1:0 
metrics execute      |     108864ms  98.1% |   0.0% ||        132ms   0.1% |   0.0% | (metrics)~1:0

[gogainda]

@ocher is it truffleruby-dev or stable one? I was checking with latest dev

[ocher]

@gogainda I've used RVM to install it. I guess that it must be the stable release. I've pasted in my previous comment output of ruby -v. If you would like I could check the latest dev version, just please let me know how could I get it.

[eregon]

@ocher You can use rvm install truffleruby-head, see https://github.com/oracle/truffleruby#getting-started

[ocher]

@eregon Thank you.

So I have tested it again, now I have installed the following version:

truffleruby 21.1.0-dev-14fe7531, like ruby 2.7.2, GraalVM CE Native [x86_64-darwin]

Results are better, but still it seems slow compared to MRI:

 metrics searching     |       5756ms   9.9% |  44.1% ||       5667ms   9.7% |  44.0% | (metrics)~1:0 
 metrics require       |      56516ms  96.9% |  55.6% ||       3299ms   5.7% |  15.4% | (metrics)~1:0 
 metrics parsing       |       2487ms   4.3% |  66.8% ||       2487ms   4.3% |  66.8% | (metrics)~1:0 
 metrics translating   |        446ms   0.8% |  70.9% ||        446ms   0.8% |  70.9% | (metrics)~1:0 
 metrics execute       |      56447ms  96.7% |  55.6% ||        119ms   0.2% |  18.5% | (metrics)~1:0 
       91.95 real       217.07 user        16.24 sys

MRI:

real	0m10.775s
user	0m6.029s
sys	0m2.917s