Track down PermGen problem with JRuby on Rails in Tomcat

We're running a small web application written JRuby on Rails running under Tomcat. We're using a Spring back-end that's shared with another production web application. Unfortunately, we keep running into PermGen problems.

OS: Ubuntu Linux 2.6.24-24-server #1 SMP x86_64 GNU/Linux Java: 1.6.0_21 Tomcat: 6.0.28 JRuby: 1.5.0 Rails: 2.3.7

We're currently getting crawled by Google, Yahoo and Baidu, so site usage is up. I've been monitoring Tomcat with JConsole and we're definitely seeing a problem with an excessive number of classes. When tomcat launches, we have about 12,000 classes loaded. After 8 hours, we have almost 75,000 classes loaded. PermGen goes from 100MB to 460MB in the same time.

Class unloading is working, but it only unloaded ~500 classes over that same 8 hour period. PermGen never seems to get collected.

We're running with the following VM options for Tomcat:

-Xms2048m -Xmx2048m -XX:MaxPermSize=512m -XX:PermSize=128m \
-XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:ParallelGCThreads=4 \
-XX:+CMSClassUnloadingEnabled -XX:+CMSPermGenSweepingEnabled

Obviously there's some kind of leak. The question is how where? Any advice on how to track down who and what is responsible for this? I'm hoping it's some really silly mistake on our part, but I'm not sure where to begin.

Any advice would be greatly appreciated.

EDIT

It looks like we're seeing one new class created for every single incoming request.

EDIT 2

It's definitely related to JRuby. Using JConsole, I enabled Verbose mode for the class loader. Here's a sample from catalina.out:

[Loaded anon_class1275113147_895127379 from file:/opt/apache-tomcat-6.0.28/webapps/notes/WEB-INF/lib/jruby-core-1.5.0.jar]
[Loaded anon_class1354333392_895127376 from file:/opt/apache-tomcat-6.0.28/webapps/notes/WEB-INF/lib/jruby-core-1.5.0.jar]
[Loaded anon_class1402528430_895127373 from file:/opt/apache-tomcat-6.0.28/webapps/notes/WEB-INF/lib/jruby-core-1.5.0.jar]

So the question becomes how do I track down the party responsible for creating those extra classes?

EDIT 3

Not sure if this the problem, but somehow we're ending up with an insane number of class loaders. Ran jmap -permstat PID and got:

class_loader  classes bytes       parent_loader   alive?              type
total = 1320  135748  947431296   N/A             alive=1, dead=1319  N/A

That seems a little excessive. The majority are one of three kinds of classloaders: sun.reflect.DelegatingClassLoader, org.jruby.util.JRubyClassLoader or org.jruby.util.ClassCache$OneShotClassLoader. Again, sample output from jmap -permstat:

class_loader            classes bytes      parent_loader           alive?  type
0x00007f71f4e93d58      1       3128       0x00007f71f4d54680      dead    sun/reflect/DelegatingClassLoader@0x00007f72ef9a6dc0
0x00007f721e51e2a0      57103   316038936  0x00007f720431c958      dead    org/jruby/util/JRubyClassLoad开发者_如何学Cer@0x00007f72f2fd1158
0x00007f72182f2b10      4       12944      0x00007f721d7f3030      dead    org/jruby/util/JRubyClassLoader@0x00007f72f2fd1158
0x00007f721d7d50d8      9       457520     0x00007f720431c958      dead    org/jruby/util/ClassCache$OneShotClassLoader@0x00007f72f3ce2368

PermGen is definitely a problem with JRuby-based applications. I'm not surprised that the CMS is not collecting much. Typically there isn't a true memory leak, but rather the application is just heavy and hard on permgen and hasn't leveled off yet.

I can offer a few options:

1. Bump up permgen even further to see if you can find the leveling-off point.
2. See if you can get away with running your application in pure-interpreted mode (-Djruby.compile.mode=OFF). That should get rid of a big chunk of the classes filling up your permgen.
3. Try to run with Rails 2.2 and greater threadsafe! mode. Running your application in a single runtime is another way to gain big memory savings, and that applies to permgen as well.

EDIT: FYI, this question turned out to be a JRuby bug. The 1.5.2 and 1.6 releases should fix this particular issue. My comments above still stand in general.

There are profiling tools, and people who know how to use them. I'm not one of them, I'm afraid.

Brute force advice:

Restart your Tomcat every 8 hours. Total downtime as seen by your users will be very acceptable. Problem solved ;)

EDIT

Oh, all right! The boring solution.

We had similar problem with a Sinatra web application using JRuby 1.5.1: JVM TraceClassLoading option prints out anon_class* loaded along with every request.

After spending sometime to narrow down where that anonymous class got loaded, which is done by printing out trace statements to console, we finally figured out it was caused by calling a missing method on a Java object.

That call triggered JRuby to add that missing method to the Java object. That process created a new singleton JRuby class, which was named "anon_class" followed by some hash values. Since it is a class type, it stays in PermGen and never gets collected by GC.

The workaround is to avoid calling that missing method or provide a implementation. In our case, we were trying to call sort method with a block on a Java ArrayList object. If we call the "to_a" method first to convert Java ArrayList to JRuby array, then, sort with a block will not create an anon_class.

So, I would suggest to review code for places accessing Java object from JRudy.

Just to provide a simple example to show this problem and workaround:

require 'java'
include_class java.util.ArrayList

list = ArrayList.new
list << 3
list << 2
list << 1

3.times do
  new_list = list.sort { |a, b| a <=> b}
  #new_list = list.to_a.sort { |a, b| a <=> b}
  puts new_list
end

Assume the file name is test_classload.rb, the following are outputs: $ jruby -J-XX:+TraceClassLoading test_classload.rb | grep anon_class
[Loaded anon_class819349464_307995535 from JVM_DefineClass]
[Loaded anon_class729155693_307995574 from JVM_DefineClass]
[Loaded anon_class1690464956_307995577 from JVM_DefineClass]

If switch to the commented line, the output is empty: no anon_class loaded.