Assets rendering is very slow since ruby 2.1.3

[Olivier4murs]

In my Rails 4.1.7 app, rendering a page with assets is about 5 times slower with ruby 2.1.3 (or 2.1.4) than with 2.1.2
I'm using Rubymine to debug (which use debase 0.1.0 and ruby-debug-ide 0.4.23.beta10)
When running with debugging off, I don't have this slowdown.

• With ruby 2.1.2 :

/Users/ob/.rvm/rubies/ruby-2.1.2/bin/ruby -e at_exit{sleep(1)};$stdout.sync=true;$stderr.sync=true;load($0=ARGV.shift) /Users/ob/.rvm/gems/ruby-2.1.2/gems/ruby-debug-ide-0.4.23.beta10/bin/rdebug-ide --disable-int-handler --evaluation-timeout 10 --port 53456 --dispatcher-port 53457 -- /Users/ob/Developpement/git/preparation_stable/test/dummy/bin/rails server -b 0.0.0.0 -p 3001 -e development
Fast Debugger (ruby-debug-ide 0.4.23.beta10, debase 0.1.0) listens on 127.0.0.1:53456
Fast Debugger (ruby-debug-ide 0.4.23.beta10, debase 0.1.0) listens on 127.0.0.1:53464
=> Booting Puma
=> Rails 4.1.7 application starting in development on http://0.0.0.0:3001
=> Run rails server -h for more startup options
=> Notice: server is listening on all interfaces (0.0.0.0). Consider using 127.0.0.1 (--binding option)
=> Ctrl-C to shutdown server
Puma 2.9.2 starting...

• Min threads: 0, max threads: 16
• Environment: development
• Listening on tcp://0.0.0.0:3001
  Started GET "/preparation/" for 127.0.0.1 at 2014-11-10 10:15:27 +0100
  Processing by AppPreparation::AccueilsController#show as HTML
  Rendered /Users/ob/Developpement/git/preparation_stable/app/views/app_preparation/accueils/show.html.erb within layouts/app_preparation/application (34.4ms)
  Rendered /Users/ob/Developpement/git/preparation_stable/app/views/app_preparation/utilisateurs/_utilisateur.html.erb (51.4ms)
  Completed 200 OK in 2329ms (Views: 2210.1ms | ActiveRecord: 54.2ms)

• With ruby 2.1.4 :

/Users/ob/.rvm/rubies/ruby-2.1.4/bin/ruby -e at_exit{sleep(1)};$stdout.sync=true;$stderr.sync=true;load($0=ARGV.shift) /Users/ob/.rvm/gems/ruby-2.1.4/gems/ruby-debug-ide-0.4.23.beta1/bin/rdebug-ide --disable-int-handler --port 54394 --dispatcher-port 54395 -- /Users/ob/Developpement/git/preparation_stable/test/dummy/bin/rails server -b 0.0.0.0 -p 3001 -e development
Fast Debugger (ruby-debug-ide 0.4.23.beta1, debase 0.1.0) listens on 127.0.0.1:54394
Fast Debugger (ruby-debug-ide 0.4.23.beta1, debase 0.1.0) listens on 127.0.0.1:54404
=> Booting Puma
=> Rails 4.1.7 application starting in development on http://0.0.0.0:3001
=> Run rails server -h for more startup options
=> Notice: server is listening on all interfaces (0.0.0.0). Consider using 127.0.0.1 (--binding option)
=> Ctrl-C to shutdown server
Puma 2.9.2 starting...

• Min threads: 0, max threads: 16
• Environment: development
• Listening on tcp://0.0.0.0:3001
  Started GET "/preparation/" for 127.0.0.1 at 2014-11-10 10:26:25 +0100
  Processing by AppPreparation::AccueilsController#show as HTML
  Rendered /Users/ob/Developpement/git/preparation_stable/app/views/app_preparation/accueils/show.html.erb within layouts/app_preparation/application (142.2ms)
  Rendered /Users/ob/Developpement/git/preparation_stable/app/views/app_preparation/utilisateurs/_utilisateur.html.erb (222.2ms)
  Completed 200 OK in 8557ms (Views: 8293.7ms | ActiveRecord: 55.7ms)

Is this problem already known? Do you need more details?
Thanks

[os97673]

No, it is not a known problem. Could you please compare assets rendering w/o debugger?
Is there any difference? Also could you please use the same version of ruby-debug-ide for both cases.

[mbasset]

I am also having this issue. Massive slowdown when using debugger in ruby 2.1.3/2.1.4 It takes over 20 seconds just to start my test suite where as without debugger it takes less than 5. The code base for the test suite is very large with many rails plugins and mountable engines.

[anatolyspektor]

+1 experience the slowdown with ruby 2.1.4

[os97673]

It would be nice to have some project to reproduce the problem (my simple projects don't demonstrate it :(
I have identified one suspicious change in ruby code but I can not verify if this is the cause until I reproduce the problem.

[mbasset]

Unfortunately the project I work on is under close source. :( What change do you think may have caused the issue. If you point to the change in ruby I can investigate and see if anything obvious stands out that might relate specifically to our code base.

[os97673]

Here are changes in vm_trace.c in ruby which look suspicious.
To verify that you need to remove these two lines, rebuild ruby from sources and try you project with patched version.

--- ./ruby-2.1.2/vm_trace.c 2013-12-17 11:19:25.000000000 +0400
+++ ./ruby-2.1.3/vm_trace.c 2014-07-30 19:52:15.000000000 +0400
@@ -335,6 +335,7 @@
trace_arg->self != rb_mRubyVMFrozenCore /* skip special methods. TODO: remove it. */) {
const VALUE errinfo = th->errinfo;
const int outer_state = th->state;

•   const VALUE old_recursive = rb_threadptr_reset_recursive_data(th);
  int state = 0;
  th->state = 0;
  th->errinfo = Qnil;
  

  @@ -355,6 +356,7 @@
  terminate:
  th->trace_arg = 0;
  th->vm->trace_running--;

•   rb_threadptr_restore_recursive_data(th, old_recursive);
  
  if (state) {
  if (pop_p) {
  

[mbasset]

Humm. The formatting seems to have gone a bit wonky. I don't have time to try recompiling right now. Do you think this is something that debase can work around or will all future versions need to be recompiled without these recursive functions?

[os97673]

I think if this is the problematic case we will need to discuss with ruby developers about possible ways to either improve ruby implementation or debase code

[mbasset]

I can confirm issue still exists with ruby 2.1.5. Also I tried using 2.1.2 and its still painfully slow. I'm now not convinced the issue is due to the ruby version.

[os97673]

Need a test project to work with :(

[Olivier4murs]

I've created a test app on github :
https://github.com/Olivier4murs/debase-slow-assets

• Ruby 2.1.2
  Fast Debugger (ruby-debug-ide 0.4.23.beta11, debase 0.1.0) listens on 127.0.0.1:56270
  Started GET "/" for 127.0.0.1 at 2014-11-14 13:01:33 +0100
  Processing by PagesController#index as HTML
  Page Load (0.3ms) SELECT "pages".* FROM "pages"
  Rendered pages/index.html.erb within layouts/application (1.8ms)
  Completed 200 OK in 560ms (Views: 557.5ms | ActiveRecord: 0.3ms)
• Ruby 2.1.4
  Fast Debugger (ruby-debug-ide 0.4.23.beta11, debase 0.1.0) listens on 127.0.0.1:56443
  Started GET "/" for 127.0.0.1 at 2014-11-14 13:04:00 +0100
  Processing by PagesController#index as HTML
  Page Load (0.7ms) SELECT "pages".* FROM "pages"
  Rendered pages/index.html.erb within layouts/application (4.8ms)
  Completed 200 OK in 2082ms (Views: 2076.9ms | ActiveRecord: 0.7ms)

[os97673]

I was able to reproduce the problem with https://github.com/railstutorial/sample_app_rails_4 and have confirmed my theory that this is a fix for ruby bug https://bugs.ruby-lang.org/issues/9940 who causes this performance regression. Will contact ruby developers to see what we can do here.

[os97673]

I've created https://bugs.ruby-lang.org/issues/10511

[os97673]

The problem has been fixed in 2.2.0-dev (see https://bugs.ruby-lang.org/issues/10511)
Unfortunately I'm unable to test it with sample_app_rails_4 because sqlite can not be built with it :( at least on my system)
Could you please try your tests with the version.

[Olivier4murs]

It works better but still far slower than 2.1.2
On my test app :
ruby 2.0.0 : 350ms
ruby 2.1.2 : 540ms
ruby 2.1.4 : 2165ms
ruby 2.2-head : 1376ms

[os97673]

I have tried https://github.com/Olivier4murs/debase-slow-assets and see similar results :(2.2-head is 1.5-2 times slower than 2.1.2) Well investigate what may cause the problem.

[os97673]

I've found one more cause of the performance degradation: https://bugs.ruby-lang.org/issues/10511#note-11

[os97673]

I've found one more cause of the performance degradation: https://bugs.ruby-lang.org/issues/10511#note-11

The problem is fixed now (https://bugs.ruby-lang.org/issues/10511#note-23)
I've tried both simple benchmark I've created and debase-slow-assets and it works ok for me.
Please test and report if you still see the problem

[Olivier4murs]

Thanks, it's resolved !
On my test app :
ruby 2.0.0 : 350ms
ruby 2.1.2 : 540ms
ruby 2.1.4 : 2165ms
ruby-2.2-head (2014-12-11) : 400ms

[os97673]

wonderful!!! So, I'm closing the ticket.
If anyone will find other situations where debugging is slower please file a new ticket with test to reproduce the problem.