JRuby (please use github issues at http://bugs.jruby.org)
  1. JRuby (please use github issues at http://bugs.jruby.org)
  2. JRUBY-5498

important JRuby 1.6 startup time regression launching JRuby script from JSR223 (12 sec -> 45 sec)

    Details

    • Type: Bug Bug
    • Status: Closed Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: JRuby 1.6
    • Fix Version/s: JRuby 1.6RC3
    • Component/s: Embedding
    • Labels:
      None
    • Environment:
      OS: Ubuntu Maverick 64 bits; Java: Java HotSpot(TM) 64-Bit Server VM (build 20.0-b06, mixed mode)
    • Testcase included:
      yes
    • Number of attachments :
      0

      Description

      This a serious performance regression. startup time to launch the exact same small JRuby program (see how to donwload it below)

      • along with jruby-complete 1.5.6: 12 seconds
      • along with jruby-complete trunk: 45 seconds!
        (trunk is from today, GIT id 254d3d0cde5b27eba920ff26b08b5adf68f9ab5e )

      The part of the program I'm testing here does something very simple in that test: basically, it's just the standard jruby-complete.jar executable with the following modifications:

      There is absolutely no code logic involved here from the 'ooor' bundled gem so just don't bother about what it does.

      testing it:
      here is the exectable jar in both configurations:

      just test the startup time by doing:
      java -jar jruby-ooor-xxx.jar

      I'm pretty sure this regression occurs those last 3/4 weeks as I remembered I tested it and it wasn't that slow.
      If that is of any help here is how the jar is assembled: https://github.com/rvalyi/terminatooor (build.xml and 'ant' task)

      Hope this helps. Don't hesitate if you have question, I'm aslo rvalyi on twitter for fast feedback.

        Activity

        Hide
        Raphael Valyi added a comment -

        Guys,

        I did some further testing:
        the slowness really all comes from the require "ooor" statement line 17 of https://github.com/rvalyi/terminatooor/blob/master/src/com/akretion/kettle/steps/terminatooor/ui/jirb_swing.rb

        I changed a bit that part of the code of that file into:

        puts Time.now()
        require 'rubygems'
        puts Time.now()
        require 'active_resource'
        puts Time.now()
        require 'ooor'
        puts Time.now()

        This gives me:

        rvalyi@rvalyi-laptop:~/DEV/terminatooor/terminatooor$ java -jar jruby-ooor.jar
        Sat Feb 12 16:57:36 -0200 2011
        Sat Feb 12 16:57:37 -0200 2011
        Sat Feb 12 16:57:38 -0200 2011
        Sat Feb 12 16:58:17 -0200 2011 (require 'ooor' was the slow part)

        I also tried to change a bit the ooor.gemspec to see if I was doing something wrong, but nothing improved the performance.
        One reason require "activeresource" is fast might be because activeresource uses autoload while ooor doesn't. Well may be.

        Still, I can tell you that if you take that same ooor gem and but it in your JRuby gems, if you try to require 'ooor' in jirb directly instead, well, it's just normally fast.

        So the differences I see here is that our gems are in a jar and may be the fact that we passed through the JSR223 though I doubt it the reason of the slowness.

        Show
        Raphael Valyi added a comment - Guys, I did some further testing: the slowness really all comes from the require "ooor" statement line 17 of https://github.com/rvalyi/terminatooor/blob/master/src/com/akretion/kettle/steps/terminatooor/ui/jirb_swing.rb I changed a bit that part of the code of that file into: puts Time.now() require 'rubygems' puts Time.now() require 'active_resource' puts Time.now() require 'ooor' puts Time.now() This gives me: rvalyi@rvalyi-laptop:~/DEV/terminatooor/terminatooor$ java -jar jruby-ooor.jar Sat Feb 12 16:57:36 -0200 2011 Sat Feb 12 16:57:37 -0200 2011 Sat Feb 12 16:57:38 -0200 2011 Sat Feb 12 16:58:17 -0200 2011 (require 'ooor' was the slow part) I also tried to change a bit the ooor.gemspec to see if I was doing something wrong, but nothing improved the performance. One reason require "activeresource" is fast might be because activeresource uses autoload while ooor doesn't. Well may be. Still, I can tell you that if you take that same ooor gem and but it in your JRuby gems, if you try to require 'ooor' in jirb directly instead, well, it's just normally fast. So the differences I see here is that our gems are in a jar and may be the fact that we passed through the JSR223 though I doubt it the reason of the slowness.
        Hide
        Yoko Harada added a comment -

        I don't have any idea at this moment. Sorry. This, http://www.ruby-forum.com/topic/217850 might come from the same root.

        Show
        Yoko Harada added a comment - I don't have any idea at this moment. Sorry. This, http://www.ruby-forum.com/topic/217850 might come from the same root.
        Hide
        Raphael Valyi added a comment - - edited

        Hello Yoko and all,

        As I told, I believe this is finally not JSR223 related (we do not have the slow loading using Jirb, so if Jirb is JSR223, this is probably not related, if jirb uses Redbrige, well then I don't know).

        To help you narrow the regression, I can tell that I have a build of JRuby trunk from January the 30th that doesn't have this bug and load just as fast as JRuby 1.5.6. I believe it's not necessary I upload it, however if you want it too please tell me.

        Yoko, the link you gave is interesting indeed. However, it's from "2010-10-01". By that time, I can guarantee you that things has been just like with JRuby 1.5.6, meaning fast enough for us (even if it might have not been optimal yet, may be what that post tells us).
        On the contrary, I here really talking about a performance regression that occured on Trunk between RC1 and RC2 and I hope you can avoid in the 1.6 release.

        Best regards.

        Show
        Raphael Valyi added a comment - - edited Hello Yoko and all, As I told, I believe this is finally not JSR223 related (we do not have the slow loading using Jirb, so if Jirb is JSR223, this is probably not related, if jirb uses Redbrige, well then I don't know). To help you narrow the regression, I can tell that I have a build of JRuby trunk from January the 30th that doesn't have this bug and load just as fast as JRuby 1.5.6. I believe it's not necessary I upload it, however if you want it too please tell me. Yoko, the link you gave is interesting indeed. However, it's from "2010-10-01". By that time, I can guarantee you that things has been just like with JRuby 1.5.6, meaning fast enough for us (even if it might have not been optimal yet, may be what that post tells us). On the contrary, I here really talking about a performance regression that occured on Trunk between RC1 and RC2 and I hope you can avoid in the 1.6 release. Best regards.
        Hide
        Charles Oliver Nutter added a comment -

        I ran the JVM with -Xprof and the largest items in the resulting (sampled) profile were:

         41.0%     0  +  1910    java.util.zip.Inflater.inflateBytes
         12.9%     0  +   599    java.util.zip.CRC32.updateBytes
        

        I'm wondering if perhaps this is falling into the jars-in-jars search logic, which can be quite a bit slower.

        Show
        Charles Oliver Nutter added a comment - I ran the JVM with -Xprof and the largest items in the resulting (sampled) profile were: 41.0% 0 + 1910 java.util.zip.Inflater.inflateBytes 12.9% 0 + 599 java.util.zip.CRC32.updateBytes I'm wondering if perhaps this is falling into the jars-in-jars search logic, which can be quite a bit slower.
        Hide
        Charles Oliver Nutter added a comment -

        Ok, this time I added -Djruby.debug.loadService.timing=true and saw this surprising result in the middle of the output:

                              -> bouncy-castle-java
                                -> bcmail-jdk15-145.jar
                                <- bcmail-jdk15-145.jar - 175ms
                                -> bcprov-jdk15-145.jar
                                <- bcprov-jdk15-145.jar - 597ms
                              <- bouncy-castle-java - 820ms
                              -> jopenssl
                                -> digest
                                <- digest - 1ms
                                -> jopenssl/version
                                <- jopenssl/version - 1ms
                              <- jopenssl - 25280ms
        

        So it seems something jossl is doing has slowed down tremendously in this scenario. It's very likely it's the jars-in-jars logic, since immediately before this it loads the BC jars from within the same archive.

        Show
        Charles Oliver Nutter added a comment - Ok, this time I added -Djruby.debug.loadService.timing=true and saw this surprising result in the middle of the output: -> bouncy-castle-java -> bcmail-jdk15-145.jar <- bcmail-jdk15-145.jar - 175ms -> bcprov-jdk15-145.jar <- bcprov-jdk15-145.jar - 597ms <- bouncy-castle-java - 820ms -> jopenssl -> digest <- digest - 1ms -> jopenssl/version <- jopenssl/version - 1ms <- jopenssl - 25280ms So it seems something jossl is doing has slowed down tremendously in this scenario. It's very likely it's the jars-in-jars logic, since immediately before this it loads the BC jars from within the same archive.
        Hide
        Charles Oliver Nutter added a comment -

        Raphael: Perhaps you can try to bisect down to a specific commit? I think you're better equipped to do that at the moment than I am. Basically just build your full jar, and if you see the slowness you've got a bad commit.

        I can try to do that later but I'm helping iwth a production issue right now.

        Show
        Charles Oliver Nutter added a comment - Raphael: Perhaps you can try to bisect down to a specific commit? I think you're better equipped to do that at the moment than I am. Basically just build your full jar, and if you see the slowness you've got a bad commit. I can try to do that later but I'm helping iwth a production issue right now.
        Hide
        Raphael Valyi added a comment -

        Charles,

        I'll make my best to find some time to do that.

        Show
        Raphael Valyi added a comment - Charles, I'll make my best to find some time to do that.
        Hide
        Charles Oliver Nutter added a comment -

        A simple reproduction without using all of your OOOR stuff (but using your jar):

        ~/projects/jruby &#10132; time java -cp jruby-ooor-trunk.jar org.jruby.Main -e "require 'openssl'"
        
        real	0m33.292s
        user	0m32.313s
        sys	0m1.449s
        

        Looking into it.

        Show
        Charles Oliver Nutter added a comment - A simple reproduction without using all of your OOOR stuff (but using your jar): ~/projects/jruby &#10132; time java -cp jruby-ooor-trunk.jar org.jruby.Main -e "require 'openssl'" real 0m33.292s user 0m32.313s sys 0m1.449s Looking into it.
        Hide
        Charles Oliver Nutter added a comment -

        Ok, the problem here is that when we have jars in jars, we end up re-scanning those contained jars repeatedly for every classloader resource we try to load from then on. This causes a very large amount of overhead.

        I'm trying to determine what happened to cause this to happen now when it did not happen before.

        Show
        Charles Oliver Nutter added a comment - Ok, the problem here is that when we have jars in jars, we end up re-scanning those contained jars repeatedly for every classloader resource we try to load from then on. This causes a very large amount of overhead. I'm trying to determine what happened to cause this to happen now when it did not happen before.
        Hide
        Charles Oliver Nutter added a comment -

        I have figured out a good way to bisect, so I should have answers shortly.

        Show
        Charles Oliver Nutter added a comment - I have figured out a good way to bisect, so I should have answers shortly.
        Hide
        Charles Oliver Nutter added a comment -

        Ok, looks like the commit that slowed it down was this one:

        commit 149d315afbb812b3df0309080c5d317326b1ff3b
        Author: David Calavera <david.calavera@gmail.com>
        Date:   Sat Oct 23 11:23:27 2010 +0200
        
            fix JRUBY-5155: Dir.[] error with wildcards in the basename of the path into jar files
        

        This bug fixes issues using Dir.[] against a URL to a jar-contained filespec with wildcards in it. I'm not sure why this is affecting jar-in-jar loading just yet...

        Show
        Charles Oliver Nutter added a comment - Ok, looks like the commit that slowed it down was this one: commit 149d315afbb812b3df0309080c5d317326b1ff3b Author: David Calavera <david.calavera@gmail.com> Date: Sat Oct 23 11:23:27 2010 +0200 fix JRUBY-5155: Dir.[] error with wildcards in the basename of the path into jar files This bug fixes issues using Dir.[] against a URL to a jar-contained filespec with wildcards in it. I'm not sure why this is affecting jar-in-jar loading just yet...
        Hide
        Charles Oliver Nutter added a comment -

        Ok, it's as I suspected...

        David's fix doesn't actually break anything; rather, it makes something work that didn't work before.

        If you start up openssl with the OOOR stuff and JRuby 1.5.6, you get a message like this:

        ~/projects/jruby &#10132; time java -cp ../jruby-1.5.6/lib/jruby.jar:jruby-ooor-trunk.jar org.jruby.Main -e "require 'openssl'"
        OpenSSL ASN1/PKey/X509/Netscape/PKCS7 implementation unavailable
        gem install bouncy-castle-java for full support.
        
        real	0m8.416s
        user	0m9.177s
        sys	0m0.496s
        

        What's happening here is that this file in the bouncycastle jar (lib/bouncy-castle-java.rb):

        Dir[File.expand_path('bc*.jar', File.dirname(__FILE__))].each do |file|
          require File.basename(file)
        end
        

        ...does not successfully find those jars, ultimately producing this warning in jruby-openssl when it tries to load the PKCS subsystem. Since the jars are not loaded, they do not trigger jar-in-jar searching logic, and you don't see the perf hit you see normally.

        At this point there's a workaround: don't include the bouncycastle jars in your aggregate jar. That will prevent them being loaded and they won't muck up performance.

        However, this shows the terribly slow performance of searching classloader resources when there are jars-in-jars at play. We need to build in a better caching mechanism in the CompoundJarUrlStreamHandler class (in JRuby) so it doesn't constantly re-scan jars in memory.

        Show
        Charles Oliver Nutter added a comment - Ok, it's as I suspected... David's fix doesn't actually break anything; rather, it makes something work that didn't work before. If you start up openssl with the OOOR stuff and JRuby 1.5.6, you get a message like this: ~/projects/jruby &#10132; time java -cp ../jruby-1.5.6/lib/jruby.jar:jruby-ooor-trunk.jar org.jruby.Main -e "require 'openssl'" OpenSSL ASN1/PKey/X509/Netscape/PKCS7 implementation unavailable gem install bouncy-castle-java for full support. real 0m8.416s user 0m9.177s sys 0m0.496s What's happening here is that this file in the bouncycastle jar (lib/bouncy-castle-java.rb): Dir[File.expand_path('bc*.jar', File.dirname(__FILE__))].each do |file| require File.basename(file) end ...does not successfully find those jars, ultimately producing this warning in jruby-openssl when it tries to load the PKCS subsystem. Since the jars are not loaded, they do not trigger jar-in-jar searching logic, and you don't see the perf hit you see normally. At this point there's a workaround: don't include the bouncycastle jars in your aggregate jar. That will prevent them being loaded and they won't muck up performance. However, this shows the terribly slow performance of searching classloader resources when there are jars-in-jars at play. We need to build in a better caching mechanism in the CompoundJarUrlStreamHandler class (in JRuby) so it doesn't constantly re-scan jars in memory.
        Hide
        Charles Oliver Nutter added a comment -

        I have pushed a fix to CompoundJarUrlStreamHandler that, when a property is set, will cache all jar contents in memory for faster access. With this change, the require time for "openssl" goes back to normal:

        ~/projects/jruby &#10132; time java -cp lib/jruby.jar:jruby-ooor-trunk.jar -Djruby.cache.jars=true org.jruby.Main -e "require 'openssl'"
        
        real	0m6.459s
        user	0m7.688s
        sys	0m0.496s
        
        ~/projects/jruby &#10132; time java -cp lib/jruby.jar:jruby-ooor-trunk.jar org.jruby.Main -e "require 'openssl'"
        
        real	0m32.637s
        user	0m32.328s
        sys	0m1.360s
        

        A side effect of the cache, however, is that it consumes a large additional chunk of memory; in this case, around 50MB. It may be possible to reduce this, but the ultimate truth is that in order to cache jar contents, we need to consume at least as much space as those contents would take up uncompressed.

        As a result, this jruby.cache.jars property defaults to off, rather than being on all the time. I'm going to ask Nick to review this and see if he can make any improvements, since he added the original code (adapted from someone else's).

        Raphael: This has landed on master now, so you can feel free to try it out. If the memory hit is not a problem for you, perhaps you'll be all set. I'm not sure whether we can safely turn it on by default, though, due to the large memory use. If you'd like to help improve the caching logic, you can look at the logic I added in the following commit:

        commit 96aee91ec17d9339958e31e5f1a3c328c0198736
        Author: Charles Oliver Nutter <headius@headius.com>
        Date: Thu Mar 3 00:32:41 2011 -0600

        Add caching logic to jar-in-jar handling.

        • Uses more memory (loads all jar contents into byte[]s in memory) but performs significantly better.
        • -Xcache.jars=true or -Djruby.cache.jars=true
        Show
        Charles Oliver Nutter added a comment - I have pushed a fix to CompoundJarUrlStreamHandler that, when a property is set, will cache all jar contents in memory for faster access. With this change, the require time for "openssl" goes back to normal: ~/projects/jruby &#10132; time java -cp lib/jruby.jar:jruby-ooor-trunk.jar -Djruby.cache.jars=true org.jruby.Main -e "require 'openssl'" real 0m6.459s user 0m7.688s sys 0m0.496s ~/projects/jruby &#10132; time java -cp lib/jruby.jar:jruby-ooor-trunk.jar org.jruby.Main -e "require 'openssl'" real 0m32.637s user 0m32.328s sys 0m1.360s A side effect of the cache, however, is that it consumes a large additional chunk of memory; in this case, around 50MB. It may be possible to reduce this, but the ultimate truth is that in order to cache jar contents, we need to consume at least as much space as those contents would take up uncompressed. As a result, this jruby.cache.jars property defaults to off, rather than being on all the time. I'm going to ask Nick to review this and see if he can make any improvements, since he added the original code (adapted from someone else's). Raphael: This has landed on master now, so you can feel free to try it out. If the memory hit is not a problem for you, perhaps you'll be all set. I'm not sure whether we can safely turn it on by default, though, due to the large memory use. If you'd like to help improve the caching logic, you can look at the logic I added in the following commit: commit 96aee91ec17d9339958e31e5f1a3c328c0198736 Author: Charles Oliver Nutter <headius@headius.com> Date: Thu Mar 3 00:32:41 2011 -0600 Add caching logic to jar-in-jar handling. Uses more memory (loads all jar contents into byte[]s in memory) but performs significantly better. -Xcache.jars=true or -Djruby.cache.jars=true
        Hide
        Charles Oliver Nutter added a comment -

        Ok, Tom gave me the idea to use JarFile for the top-level jars, which reduces the cache memory load immensely. I've pushed that change, and the "require 'openssl'" example now loads slightly faster, but uses only a couple MB more than the scanning version. I find that totally acceptable.

        I'm also going to look into ways to make JarFile work against in-memory resources (it normally only works against files), which would allow us to only cache JarFile.

        commit 2f624eeb4249507cab453cbd61b3665f935be78a
        Author: Charles Oliver Nutter <headius@headius.com>
        Date: Thu Mar 3 11:15:58 2011 -0600

        Improve jar-in-jar cache memory use by not caching contents of jars directly on the filesystem.

        Show
        Charles Oliver Nutter added a comment - Ok, Tom gave me the idea to use JarFile for the top-level jars, which reduces the cache memory load immensely. I've pushed that change, and the "require 'openssl'" example now loads slightly faster, but uses only a couple MB more than the scanning version. I find that totally acceptable. I'm also going to look into ways to make JarFile work against in-memory resources (it normally only works against files), which would allow us to only cache JarFile. commit 2f624eeb4249507cab453cbd61b3665f935be78a Author: Charles Oliver Nutter <headius@headius.com> Date: Thu Mar 3 11:15:58 2011 -0600 Improve jar-in-jar cache memory use by not caching contents of jars directly on the filesystem.
        Hide
        Nick Sieger added a comment -

        Unfortunate that making something work better exposes a performance issue, but nice that we can fix it as well. Patches look good so far, and looking forward to seeing this in action.

        Show
        Nick Sieger added a comment - Unfortunate that making something work better exposes a performance issue, but nice that we can fix it as well. Patches look good so far, and looking forward to seeing this in action.
        Hide
        Raphael Valyi added a comment -

        Charles,

        Regarding our use case, the only advantage of packaging my gems in jruby-complete is to provide a single click experience to the user. We only need SSL connections eventually from within the ETL so I just moved those SSL gems outside the jar and it works perfect, at least for us. Once again thanks a ton for your support!

        Show
        Raphael Valyi added a comment - Charles, Regarding our use case, the only advantage of packaging my gems in jruby-complete is to provide a single click experience to the user. We only need SSL connections eventually from within the ETL so I just moved those SSL gems outside the jar and it works perfect, at least for us. Once again thanks a ton for your support!
        Hide
        Charles Oliver Nutter added a comment -

        Ok, I think I'm going to call this one fixed.

        There's no way to use JarFile or ZipFile against in-memory resources, since they depend on zlib which only works against files. There are some other options that could perhaps be modified to work against in-memory resources (like Apache Harmony's java.util.zip stuff), but that's a much larger job than I want to take on.

        The modified jar-in-jar logic works like this:

        • For top-level file: jar files, open them directly and use JarFile to get entries. Nothing from top-level jar files is cached in memory.
        • For nested jar files, open once and cache all contents directly in memory. There's a memory impact from this, the uncompressed contents are held in memory forever. However, nested jars are generally not too large, and the memory tradeoff comes with a very solid improvement in lookup performance.

        With the new logic, only nested jars will have a memory impact equal to their uncompressed size, but the load time for resources when jars-in-jars are present is as fast as loading from filesystem jars.

        Show
        Charles Oliver Nutter added a comment - Ok, I think I'm going to call this one fixed. There's no way to use JarFile or ZipFile against in-memory resources, since they depend on zlib which only works against files. There are some other options that could perhaps be modified to work against in-memory resources (like Apache Harmony's java.util.zip stuff), but that's a much larger job than I want to take on. The modified jar-in-jar logic works like this: For top-level file: jar files, open them directly and use JarFile to get entries. Nothing from top-level jar files is cached in memory. For nested jar files, open once and cache all contents directly in memory. There's a memory impact from this, the uncompressed contents are held in memory forever. However, nested jars are generally not too large, and the memory tradeoff comes with a very solid improvement in lookup performance. With the new logic, only nested jars will have a memory impact equal to their uncompressed size, but the load time for resources when jars-in-jars are present is as fast as loading from filesystem jars.
        Hide
        Charles Oliver Nutter added a comment -

        Raphael: I think we were commenting at exactly the same time

        That sounds like a fine workaround, and if you want to move them back into the jar after RC3 that will work too. Because the main part of the memory hit was from the top-level jruby-complete jar itself, I've just switched over to using the caching logic only.

        Show
        Charles Oliver Nutter added a comment - Raphael: I think we were commenting at exactly the same time That sounds like a fine workaround, and if you want to move them back into the jar after RC3 that will work too. Because the main part of the memory hit was from the top-level jruby-complete jar itself, I've just switched over to using the caching logic only.

          People

          • Assignee:
            Charles Oliver Nutter
            Reporter:
            Raphael Valyi
          • Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: