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

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.

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

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.

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.

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.

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.

Charles,

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

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

~/projects/jruby ➔ 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.

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.

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

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

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

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

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.

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.

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!

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.

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.