Track down PermGen problem with JRuby on Rails in Tomcat

Question

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/JRubyClassLoader@0x00007f72f2fd1158
0x00007f72182f2b10      4       12944      0x00007f721d7f3030      dead    org/jruby/util/JRubyClassLoader@0x00007f72f2fd1158
0x00007f721d7d50d8      9       457520     0x00007f720431c958      dead    org/jruby/util/ClassCache$OneShotClassLoader@0x00007f72f3ce2368

Greek

Answer 1

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.

Weinreb

75,000 classes for 4 instances still seems like a lot to me... :) But I'll definitely do some more testing. Thanks! – Greek

The thing that concerns me is that it looks like every new request creates new classes that never get released. That just doesn't feel right to me. I understand why JRuby is creating new classes, but I can't understand why they don't get cleaned up... – Greek

How can I tell if jruby.compile.mode=OFF is working correctly? I added -Djruby.compile.mode=OFF to CATALINA_OPTS in catalina.sh, started tomcat and launched a webcrawler against the site. JConsole indicates that the total class count and total permgen is steadily rising. – Greek

Never mind. Found the JITCompiler mbean. Definitely showing 0 for everything. Yet still seeing rising class count and permgen. – Greek

Answer 2

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.

Accra

Thanks, but restarting Tomcat every 8 hours is not an acceptable solution. Especially since I'm the guy who will be doing that. :) The point here is to solve the underlying problem. – Greek

cron and friends were invented so you wouldn't need to do the restarting manually. You have a problem that's either in your Ruby code or the implementation of JRuby or an obscure combination of that and Tomcat, so it's not even just a "standard" Java memory problem. I'm guessing that you'll be restarting your server plenty of times before you get it fixed, so it would be wise to look at scripting regular restarts. – Accra

Absolutely. But I'm pretty comfortable with the process of stopping & starting tomcat and automating that. We've got that under control. But downtime every 8 hours, even if it's only 30-60 seconds, isn't considered acceptable to management. You know how it goes. :) So my question here is really looking for advice on how to track the source of the problem. – Greek

Once they hear my consulting rates, they'll be delighted with 3 minutes of downtime per day! ;) But seriously, your situation is difficult. Running a "plain" Ruby server might not be a bad alternative. Another desperate idea I can offer is to throw yourself sobbing at Charles Nutter's feet. Nobody knows more about JRuby than he does. But hey, you might first want to read the page I linked to :) – Accra

Re consulting rates - too bad I'm a salaried employee. Maybe I need to rethink my contract... :) Hadn't seen the article from Charles - I'll definitely peruse it. And I'll definitely spend more time before bothering Charles - I'm sure he has better things to do with his time. :) – Greek

Kidding aside, I think it directly addresses your problem, including a free yet powerful tool to use in solving it. Hopefully. – Accra

Found it. ClassLoaders aren't getting released due to a leak. Thanks. – Greek

Excellent. I'm very glad I was able to apply my half-knowledge to help you (help yourself). – Accra

Answer 3

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.

Frizzy

Answer 4

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.

Frizzy