Details

    • Type: Bug Bug
    • Status: Resolved Resolved
    • Priority: Blocker Blocker
    • Resolution: Fixed
    • Affects Version/s: JRuby 1.6.6, JRuby 1.6.7
    • Fix Version/s: JRuby 1.6.8
    • Labels:
      None
    • Environment:
      not OS related. We reproduced this on a Mac OSX Snow Leopard
    • Testcase included:
      yes
    • Number of attachments :
      2

      Description

      With the d9426515f8497c635d3aeebdc8d12c6105bf6ab8 changeset we see about 20-25% drop in performance for a specific case where objects extend a module via active_support/core_ext/object/metaclass.

      We have a ruby test script is attached to allow you to reproduce the problem. We ran our test script against 1.6.7 and 1.6.7 with the d94265 changeset removed and saw 20% performance improvement.

      Attached files:

      • autoload_bug.zip: a test script to reproduce performance issue, run test.rb
      • debug.patch: there are some debug output patched to 1.6.7 branch, and if you built a complete jar with this patch, and run the test, you should see that class C is never mark as autoloaded.

        Activity

        Hide
        Babar added a comment - - edited

        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
        
        Show
        Babar added a comment - - edited 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
        Hide
        Charles Oliver Nutter added a comment -

        I see some slowdown comparing JRuby 1.6.6 and JRuby 1.6.7, but not as severe as you both describe. I also see a massive improvement in performance on master:

        system ~/projects/jruby/autoload_bug $ rvm jruby-1.6.6 do ruby test.rb 
              user     system      total        real
         85.124000   0.000000  85.124000 ( 85.101000)
        
        system ~/projects/jruby/autoload_bug $ rvm jruby-1.6.7 do ruby test.rb 
              user     system      total        real
         89.137000   0.000000  89.137000 ( 89.113000)
        
        # This is master
        system ~/projects/jruby/autoload_bug $ jruby test.rb 
               user     system      total        real
          35.209000   0.000000  35.209000 ( 35.209000)
        

        There may be some improvements possible in the threadsafe autoload logic, but it seems like master has already made substantial gains in performance. We do not plan to release a 1.6.8 release.

        I'll have a quick look at the autoload logic to see if there's improvements possible, but I may just resolve this one as fixed.

        Show
        Charles Oliver Nutter added a comment - I see some slowdown comparing JRuby 1.6.6 and JRuby 1.6.7, but not as severe as you both describe. I also see a massive improvement in performance on master: system ~/projects/jruby/autoload_bug $ rvm jruby-1.6.6 do ruby test.rb user system total real 85.124000 0.000000 85.124000 ( 85.101000) system ~/projects/jruby/autoload_bug $ rvm jruby-1.6.7 do ruby test.rb user system total real 89.137000 0.000000 89.137000 ( 89.113000) # This is master system ~/projects/jruby/autoload_bug $ jruby test.rb user system total real 35.209000 0.000000 35.209000 ( 35.209000) There may be some improvements possible in the threadsafe autoload logic, but it seems like master has already made substantial gains in performance. We do not plan to release a 1.6.8 release. I'll have a quick look at the autoload logic to see if there's improvements possible, but I may just resolve this one as fixed.
        Hide
        Charles Oliver Nutter added a comment -

        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...

        Show
        Charles Oliver Nutter added a comment - 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...
        Hide
        Babar added a comment - - edited

        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.

        Show
        Babar added a comment - - edited 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.
        Hide
        Charles Oliver Nutter added a comment -

        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.

        Show
        Charles Oliver Nutter added a comment - 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.
        Hide
        Charles Oliver Nutter added a comment -

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

        Show
        Charles Oliver Nutter added a comment - Marking as fixed, since master appears to revert back to pre-1.6.6 performance for the given benchmark.
        Hide
        Li Xiao added a comment - - edited

        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()))

        { // Do not finish autoloading by cyclic autoload module.finishAutoload(baseName); }

        }

        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)

        Show
        Li Xiao added a comment - - edited 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())) { // Do not finish autoloading by cyclic autoload module.finishAutoload(baseName); } } 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)
        Hide
        Babar added a comment -

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

        Show
        Babar added a comment - FYI, I can confirm that master branch (1.7.0.dev) performance is OK with my thread safe Rails 3.2 application.
        Hide
        Charles Oliver Nutter added a comment -

        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.

        Show
        Charles Oliver Nutter added a comment - 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.
        Hide
        Charles Oliver Nutter added a comment -

        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.

        Show
        Charles Oliver Nutter added a comment - 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.
        Hide
        Li Xiao added a comment -

        Cool, thanks for looking into this.

        Show
        Li Xiao added a comment - Cool, thanks for looking into this.
        Hide
        Hiroshi Nakamura added a comment -

        Let me give it a try.

        Show
        Hiroshi Nakamura added a comment - Let me give it a try.
        Hide
        Hiroshi Nakamura added a comment -
        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?

        Show
        Hiroshi Nakamura added a comment - 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?
        Hide
        Babar added a comment - - edited

        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 ?

        Show
        Babar added a comment - - edited 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 ?
        Hide
        Hiroshi Nakamura added a comment -

        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.

        Show
        Hiroshi Nakamura added a comment - 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.

          People

          • Assignee:
            Hiroshi Nakamura
            Reporter:
            Li Xiao
          • Votes:
            1 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: