Increased memory usage (leaking?) with each hotdeploy

[Chack]

Hello,

I did some localhost performance testing with trinidad and I am seeing
great results (about 30% faster then passenger under heavy load). Also
the memory footprint is really small which is great. However to be
usable in production we really need hotdeploy since we will be running
multiple applications in the same trinidad instance. Hotdeploy is
working fine with the config we are using, the correct application
gets reloaded after touching tmp/restart. But I noticed something
strange, the java process trinidad runs in starts off with about
200MB, but with each hotdeploy this increases by about 40mb. I tested
this for a bit, hotdeploying the same application multiple times and
managed to bloat that particular java process to 1000MB memory usage,
staying that way untill i killed the process.

The only issue I could find in the log files was multiple repeats of
this:

INFO: Illegal access: this web application instance has been stopped
already. Could not load java.lang.Runnable. The eventual following
stack trace is caused by an error thrown for debugging purposes as
well as to attempt to terminate the thread which caused the illegal
access, and has no functional impact.
java.lang.IllegalStateException
at
org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:
1562)
at java.lang.ClassLoader.loadClass(ClassLoader.java:296)
at java.lang.ClassLoader.loadClass(ClassLoader.java:248)
at java.lang.ClassLoader.defineClass1(Native Method)
at java.lang.ClassLoader.defineClassCond(ClassLoader.java:632)
at java.lang.ClassLoader.defineClass(ClassLoader.java:616)
at
org.jruby.util.JRubyClassLoader.defineClass(JRubyClassLoader.java:76)
at
org.jruby.util.JRubyClassLoader.getJDBCDriverUnloader(JRubyClassLoader.java:
66)
at
org.jruby.util.JRubyClassLoader.tearDown(JRubyClassLoader.java:47)
at org.jruby.Ruby.tearDown(Ruby.java:2764)
at
org.jruby.embed.ScriptingContainer.terminate(ScriptingContainer.java:
1719)
at
org.jruby.embed.ScriptingContainer.finalize(ScriptingContainer.java:
1733)
at java.lang.ref.Finalizer.invokeFinalizeMethod(Native Method)
at java.lang.ref.Finalizer.runFinalizer(Finalizer.java:83)
at java.lang.ref.Finalizer.access$100(Finalizer.java:14)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:
160)
17.04.2011 20:49:59 org.apache.catalina.loader.WebappClassLoader
loadClass

So is this default behavior and the GC maybe just felt no reason yet
to start collecting? Or is something fishy going on? Maybe you have
some hints for me how I can investigate further.

This is the trinidad.yml I am using:

address: localhost
port: 28080
environment: production
jruby_min_runtimes: 1
jruby_max_runtimes: 1
extensions:
daemon:
pid_file: tmp/pids/trinidad.pid
jvm_args: "-server -XX:NewRatio=2 -XX:SurvivorRatio=2"

web_apps:
default:
context_path: /someapp
extensions:
hotdeploy:
delay: 10000
subapp:
context_path: /someapp/subapp
web_app_dir: ../subapp
extensions:
hotdeploy:
delay: 10000

Thanks for your help.

[David Calavera]

Hi Chack,

the latest versions of Trinidad don't need the extension to perform the hotdeploy, tomcat does it by itself, but the delay time is fixed, I don't know yet how tomcat configures it.

https://github.com/trinidad/trinidad/blob/master/History.txt#L7

Could you try again removing the extension? my first thought is that we are creating a classloader eachtime the application starts again and perhaps that's keeping more memory each time.

Thank you!!

org.jruby.embed.ScriptingContainer.terminate(ScriptingContainer.jjava:

--
Has recibido este mensaje porque estás suscrito al grupo "Rails Trinidad" de Grupos de Google.
Para publicar una entrada en este grupo, envía un correo electrónico a rails-t...@googlegroups.com.
Para anular tu suscripción a este grupo, envía un correo electrónico a rails-trinida...@googlegroups.com
Para tener acceso a más opciones, visita el grupo en http://groups.google.com/group/rails-trinidad?hl=es.

[Chack]

Hello,

Thanks for the quick reply. Hotdeploying does indeed work without the
extension, delay time seems to be 30sec. However the same issue still
exists, memory footprint rising by 35-40mb with each hotdeploy. I am
also still getting the same error message in the log files.

I am a bit confused now tho since i capped the JVM as 250m via -
Xmx250m in the JVM options, and OSX Activity Monitor reports it
exceeding that after a few redeploys (380mb currently). However if i
connect with jconsole to that specific process it shows a heap size of
only 80mb after a manual GC. I guess i need to do some more digging
into what the ActivityMonitor is actually showing.

Cheers!

[David Calavera]

I was wondering why you got that error message, I haven't seen it before. It seems something changed in JRuby-Rack and it's the cause of the error message, but I don't know yet if it's also the cause of the leak.

Could you downgrade your JRuby-Rack version to 1.0.7, that seems to work as expected.

Thank you!!

[David Calavera]

I'm experienced the same problems that you have. JRuby-Rack seems to be the responsible but I don't know the reason yet :S

[kares]

I've tried this really fast on a simple app with a custom JRuby-Rack built that changed the following :

in DefaultRackApplicationFactory I've updated the destroy method to release the instance state :

    public void destroy() {
        this.rackupScript = null;
        this.rackupLocation = null;
        this.rackContext = null;
        this.defaultConfig = null;
        this.getRequiredLibraries = null;
        errorApplication.destroy();
        errorApplication = null;
    }

the original error goes away, however a different comes around :

INFO: Illegal access: this web application instance has been stopped already.  Could not load rubygems.defaults.OperatingSystemService.  The eventual following stack trace is caused by an error thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access, and has no functional impact.

but the app seems to be doing OK and memory seems to be stable after re-deploys ... I will re-test later with a slightly more "robust" app and see if it is doing good as well with my JRuby-Rack patch ...

[kares]

sorry for the false alarm - it's leaking the same way on the (big) "robust" app despite the fact that it did behave slightly differently on the "small" app ...

[David Calavera]

I've also added the main application to the destroy method and it seems it behaves a little bit better but I still think jruby-rack loads too much things each time.

On Monday, April 18, 2011 at 9:35 AM, kares wrote:

sorry for the false alarm - it's leaking the same way on the (big) "robust" app despite the fact that it did behave slightly differently on the "small" app ...

--

[Chack]

I am not really sure if this is a leak at all, and not just the OS
being too lazy to take the memory from java away again. I have to
admit that I don't really have in-depth knowledge about how (in my
case) OSX allocates memory to processes, but Activity Monitor might
only show how much memory OSX allows a process to have, and not how
much it is actually using.

Anyway a good testing method is the watch command line tool (you can
get it via brew if your on OSX).

just hit 'watch -n30 touch tmp/restart.txt' and watch the java process
growing by 60mb per minute about.

The good news is that it seem to cap at arround 440MB for me now,
which might be fixed memory heap size of 250mb i allowed it to have
from the start plus some non heap memory that can only grow up to a
certain cap untill it is GCed. And after GCing the OS just leaves Java
with the memory because it doesn't need it for anything else. There
is probably some JVM options where you can fix this behavior.

[Chack]

I also found this quote in another mailing list:

---
This is a know issue with Tomcat (and most other Java App Servers)
that they don't correctly clear the permanent generation after
undeploy. The only solutions are to increase the permgen settings or
to restart the app server every few deploys. It's not an issue with
your app or warbler.
---

I guess its save to assume that you are supposed to restart tomcat
every couple of redeploys :(

[kares]

 Hey Chacke,

You're right Java re-deploys is a pain in the ass but JRuby does include a few hooks such as JDBC Driver deregistration that should fix the issues.

I think it's definitely a leak. There are org.jruby.RubyInstanceConfig instances left - not being GCed after each "redeploy" ... and this relates to some changed behavior in JRuby-Rack 1.0.7 -> 1.0.8

[Nick Sieger]

So you definitely don't see the leak with 1.0.7? Any chance of using a heap analyzer to see what's holding onto the RubyInstanceConfig instances? Can you try with an app that doesn't use a database connection? Even though JRuby 1.6 has the JDBC unloader code, the stack trace above looks like it might not be working, and database connections have been the most common culprit of memory leaks.

/Nick

[kares]

Nick's right, at least in my case, it is not related to the changes in 1.0.8 - I am seeing above the same mem increase after redeploys with 1.0.7 as well.

The `ScriptingContainer` does terminate correctly in 1.0.8 - the errors where seeing come from attempting to `terminate` it again during `finalize`.
If I make sure the container only terminates once - no errors happen (and I'm sure the container got terminated as expected) :

    private static class TerminatorContainer extends ScriptingContainer {

        TerminatorContainer() {
            super(LocalContextScope.SINGLETHREAD);
        }

        private boolean terminated = false;

        @Override
        public void terminate() {
            if ( ! terminated ) {
                super.terminate();
                terminated = true;
            }
        }

    }

However it still leaks, thus we were going the wrong direction here ...

[Topping Bowers]

So this was a long time ago :).  Sorry to resurrect if it's been talked about later (but I didn't see it).  We're seeing the same thing in production and (at least once) saw an OutOfMemoryError in production after deploying maybe 6 or 7 times (relatively large app).  I tried to replicate this locally and I just couldn't - using jvisualvm multiple deploys would increase size but then level off after GC.  In production this doesn't seem to be the case.

We're using trinidad 1.3.5 with no extensions

jruby-rack 1.1.5

Development machine (the one that doesn't see increase) is OSX Lion. I was locally running in production mode, but not all Db connections would have been made.

Production is 11.10 Ubuntu.

I now (finally) have a sandbox app that I'm going to keep trying to get to error with a hot-deploy but are there any tools on a remote 11.10 Ubuntu box (with relatively closed ports) I should be looking into to get the most out of this experiment?

Thanks for your help,

Topper

[Topping Bowers]

Oh and we're using mongoid - I noticed "trinidad cleans up your jdbc connections."  Do I have to manually clean up my mongo connections?

Topper

[Keith Gaputis]

Chack was right in an earlier post. More than likely this is an issue with JVM footprint dilation, and has nothing to do with JDBC.  Basically when running older versions of the JVM in server mode, it cannot release classloader resources from the previous deployment after performing a hot deployment.  All of the classes loaded into the permgen area of the heap take up the additional ~40mb of RAM you are seeing after each hotdeploy.

The problem has been around for many years, and was not fixed until recent versions of the JVM:

http://bugs.sun.com/view_bug.do?bug_id=4957990 

Perhaps try upgrading to a newer version of Java. I know it is fixed in JDK 7, not sure about anything else.

[Topping Bowers]

Thanks! I tried Java 7 and it seems to fix the memory leak, but now I'm still having trouble with hot deploy... even in a minimal Rails App.  I should probably make a new topic though... which I will do and call "Problems with hot deploy"