performance drop with threadsafe autoloading for JRuby 1.6.6.

I've exactly the same problem with my Rails 3.2.3 application, but with more than 50% of performance drop on Windows, ouch !
For advanced users, here a workaround if you use RVM:

cd $HOME/.rvm/repos/
git clone -b jruby-1_6 https://github.com/jruby/jruby.git
cd jruby
git revert d9426515f8497c635d3aeebdc8d12c6105bf6ab8
ant
ant dist
rvm reinstall jruby-head --branch jruby-1_6
rvm jruby-head do gem install $HOME/.rvm/repos/jruby/gem/pkg/jruby-jars-1.6.8.dev.gem --no-ri --no-rdoc

I certainly hope this benchmark is written this way solely to test the performance of evaluating these constants, and that you are not doing extend inside initialize as part of regular code...

I see some slowdown comparing JRuby 1.6.6 and JRuby 1.6.7, but not as severe as you both describe.

Notice that JRuby 1.6.6 and JRuby 1.6.7 have both this performance issue.
With JRuby 1.6.6.dev prior to commit d9426515f8497c635d3aeebdc8d12c6105bf6ab8 the performances were good.
I'll check tomorrow if JRuby master branch is OK with my Rails application.

Ahh, I understand now; both 1.6.6 and 1.6.7 have the problem. JRuby 1.6.5 does indeed run the attached benchmark much faster:

system ~/projects/jruby/autoload_bug $ rvm jruby-1.6.5 do ruby test.rb 
      user     system      total        real
 32.177000   0.000000  32.177000 ( 32.153000)

This is in the neighborhood of master's performance. The variability between 1.6.5 and master and between 1.6.6 and 1.6.7 are probably due to the large object churn in the benchmark.

Marking as fixed, since master appears to revert back to pre-1.6.6 performance for the given benchmark.

It's autoload thread safe patch problem, because there is a thread lock inside RubyModule#Autoload#getConstant.

Because Autoload never mark class C (in the test) as autoloaded, so it always go through autoload process which involves RubyModule#Autoload#getConstant.

The reason it never got marked as autoloaded is because IAutoloadMethod only marks a constant is loaded when lockAndRequire the constant file is required successfully inside RubyKernel#autoload method.

public void load(Ruby runtime) {
if (runtime.getLoadService().lockAndRequire(file()))

}

The tricky here is, class B and class C defined in module A autoload with same file name:

module A
autoload :B, 'a/b'
autoload :C, 'a/b'
end

(this is a very common pattern inside activerecord)

So, if you patched the debug.patch to 1.6.7, and run the test again, you should see the process, class C never got marked as autoload and then when any code reference to A::C inside an object method that is defined by object.class_eval (came from active_support/core_ext/object/metaclass), it will need go through RubyModule#Autoload#getConstant which has a thread lock causing performance issue.

(I replied in email, seems not in comment, so put this here)

FYI, I can confirm that master branch (1.7.0.dev) performance is OK with my thread safe Rails 3.2 application.

Li: Thanks for the additional details. I'll have a look at the logic on master and see if the autoload lock remains in place. The perf numbers seem to indicate it's not, but they could reflect some huge improvement in something else too.

Li: Thanks again for the extra info.

I traced the logic you describe to this code in RubyKernel:

    // inside the IAutoload impl:
    public void load(Ruby runtime) {
        if (runtime.getLoadService().lockAndRequire(file())) {
            // Do not finish autoloading by cyclic autoload 
            module.finishAutoload(baseName);
        }
    }

lockAndRequire, as you point out, returns false if the file has already been loaded, which causes autoloads of the same file to continue going through the slow locking process. However, on master the code has changed:

    public void load(Ruby runtime) {
        if (runtime.getLoadService().autoloadRequire(file())) {
            // Do not finish autoloading by cyclic autoload 
            module.finishAutoload(baseName);
        }
    }

This version calls autoloadRequire, which returns true for all cases except circular/cyclic requires (which are uncommon and trigger warnings as well). So even if the file has been required before, the autoload gets "finished" and the autoload-triggering object is removed.

I feel better about marking this fixed now.

This is definitely of concern for anyone running Rails on JRuby 1.6.6 or 1.6.7, since all these autoloads will have this locking behavior regardless of whether they get preloaded (since preloading just tries to access them). I'll see if I can come up with a workaround that doesn't involve reverting the patch, since there won't be a 1.6.8.

Cool, thanks for looking into this.

Let me give it a try.

diff --git a/src/org/jruby/RubyKernel.java b/src/org/jruby/RubyKernel.java
index 241aded..a4c3708 100644
--- a/src/org/jruby/RubyKernel.java
+++ b/src/org/jruby/RubyKernel.java
@@ -195,10 +195,13 @@ public class RubyKernel {
             }
 
             public void load(Ruby runtime) {
-                if (runtime.getLoadService().lockAndRequire(file())) {
-                    // Do not finish autoloading by cyclic autoload 
-                    module.finishAutoload(baseName);
-                }
+                runtime.getLoadService().lockAndRequire(file());
+                // From jruby 1.7 it calls finishAutoload if the above require
+                // was NOT a cyclic autoload. But since there's no cyclic
+                // detection in jruby-1_6, when lockAndRequire returns from
+                // LoadService it means that autoload is finished. So it's safe
+                // to call finishAutoload here.
+                module.finishAutoload(baseName);
             }
         });
         return runtime.getNil();

Can someone try this patch?

Hi Hiroshi,

Your performance patch is OK with my thread safe Rails 3.2 application.
Thanks you !

Does this mean that JRuby 1.6.8 will be released ?

I've just committed to jruby-1_6 branch.

commit 465bc21af418ba7b874c3c7f6444ea4a3ca58a91
Author: Hiroshi Nakamura <nahi@ruby-lang.org>
Date:   Mon Apr 16 22:01:56 2012 +0900

    JRUBY-6580: Fix performance drop with threadsafe autoload
    
    In jruby-1_6 branch, end of autoload require was not detected correctly.
    It caused unnecesarry locking for constant access even after autoload
    finished.

Babar, thanks for the confirmation. I think Tom will push 1.6.8 at some point but I'm not sure about the date. For a while, please use 1.6.8.dev at http://ci.jruby.org/snapshots/release/ after the commit reach there.