[JAVA-130] Memory Leaks with ThreadLocals in Tomcat Created: 09/Jul/10  Updated: 09/Nov/10  Resolved: 30/Sep/10

Status: Closed
Project: Java Driver
Component/s: None
Affects Version/s: 2.0
Fix Version/s: 2.2

Type: Bug Priority: Major - P3
Reporter: Klaus Lehner Assignee: Eliot Horowitz (Inactive)
Resolution: Done Votes: 4
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Fedora, Tomcat


Attachments: Text File threadlocal1.patch    

 Description   

When running mongo 2.0 in a tomcat environment I can see the following logs in the catalina.out, and the tomcat web server can't be stopped any more without killing it, it seems that there's a non-deamon thread still hanging.

SEVERE: A web application created a ThreadLocal with key of type [null] (value [com.mongodb.DBTCPConnector$1@d5ba1ef]) and a value of type [com.mongodb.DBTCPConnector.MyPort] (value [com.mongodb.DBTCPConnector$MyPort@7ae458c2]) but failed to remove it when the web application was stopped. To prevent a memory leak, the ThreadLocal has been forcibly removed.
Jul 8, 2010 7:28:23 AM org.apache.catalina.loader.WebappClassLoader clearThreadLocalMap
SEVERE: A web application created a ThreadLocal with key of type [null] (value [com.mongodb.OutMessage$1@257f6796]) and a value of type [com.mongodb.OutMessage] (value [com.mongodb.OutMessage@4f69bc15]) but failed to remove it when the web application was stopped. To prevent a memory leak, the ThreadLocal has been forcibly removed.
Jul 8, 2010 7:28:23 AM org.apache.catalina.loader.WebappClassLoader clearThreadLocalMap
SEVERE: A web application created a ThreadLocal with key of type [null] (value [com.mongodb.Response$1@26bb2f6e]) and a value of type [org.bson.BSONDecoder] (value [org.bson.BSONDecoder@4b26f29f]) but failed to remove it when the web application was stopped. To prevent a memory leak, the ThreadLocal has been forcibly removed.



 Comments   
Comment by Klaus Lehner [ 09/Nov/10 ]

ah sorry - forgot to call close() as mentioned by eliot; will give that a try

Comment by Eliot Horowitz (Inactive) [ 09/Nov/10 ]

Can you create a new case with the full log and steps to reproduce exactly?

Comment by Klaus Lehner [ 09/Nov/10 ]

This is still the case, even with 2.3.

I still have errors like that in my catalina.out and tomcat can't be stopped without killing it. Please reopen that task.

SEVERE: A web application created a ThreadLocal with key of type [null] (value [com.mongodb.DBTCPConnector$1@4b6eb12]) and a value of type [com.mongodb.DBTCPConnector.MyPort] (value [com.mongodb.DBTCPConnector$MyPort@6fe23ecd]) but failed to remove it when the web application was stopped. To prevent a memory leak, the ThreadLocal has been forcibly removed.

Comment by Eliot Horowitz (Inactive) [ 11/Oct/10 ]

The 2 in org.bson should never be using by normal operations, and accoring to tomcat docs, it seems the other should be.
If you see issues in an app - please open a new ticket with the exact errors

Comment by Daniel Spilker [ 11/Oct/10 ]

I tried the 2.2 driver today. Unfortunately this issue seems not to be fixed. I still count 3 thread locals (2 in org.bson.BSON and 1 in com.mongodb.DBTCPConnector). I do not see why these should get GC'ed when Mongo.close() is called, since the contents of the thread locals will still be referenced from each thread which used these classes. It will get GC'ed when the threads die, but in a shared environment like servlet containers where threads are pooled and reused this is not going to happen.

Comment by Robert Stewart [ 09/Oct/10 ]

At first, I was still seeing one message being logged at SEVERE level. Tomcat, at least in version 6.0.24, seemed to be taking things into its own hands, though.

Oct 8, 2010 11:08:19 PM org.apache.catalina.loader.WebappClassLoader clearThreadLocalMap
SEVERE: A web application created a ThreadLocal with key of type [null] (value [com.mongodb.DBTCPConnector$1@2f4f069b]) and a value of type [com.mongodb.DBTCPConnector.MyPort] (value [com.mongodb.DBTCPConnector$MyPort@6d3ac260]) but failed to remove it when the web application was stopped. To prevent a memory leak, the ThreadLocal has been forcibly removed.

This happens when I undeploy a webapp on Tomcat 6.0.24. The last sentence in the message is different than in previous comments posted on this issue. I think this is due to changes in more recent versions of Tomcat 6.0.x.

In my webapp, I'm using my log4mongo-java appender for Log4J to log events to MongoDB. I've registered a ServletContextListener in my webapp that is called when the context is destroyed (e.g., when undeploying a webapp or shutting down Tomcat). In the callback, I Log4J's LogManager.close(), which eventually calls the close method on my appender, which finally calls Mongo.close().

After I patched mongo-java-driver with the fix I identified in http://jira.mongodb.org/browse/JAVA-180 (an NPE was preventing final clean up from occurring), the ThreadLocal was cleaned up and no messages were logged at SEVERE level.

So, the 2.2 driver fixes the problems I was seeing with 2.1.

Comment by Eliot Horowitz (Inactive) [ 30/Sep/10 ]

If you call Mongo.close() on application quit, everything should be cleaned up now.
Removed 2 main ThreadLocal
The last one should be cleaned with Mongo.close() when Mongo is gc'ed

Comment by auto [ 30/Sep/10 ]

Author:

{'login': 'erh', 'name': 'Eliot Horowitz', 'email': 'eliot@10gen.com'}

Message: don't put OutMessage in ThreadLocal.
store buffers in Mongo not ThreadLocal
JAVA-130
http://github.com/mongodb/mongo-java-driver/commit/396cd5796cb1e627787e62f53e460465a95ac0b0

Comment by auto [ 30/Sep/10 ]

Author:

{'login': 'erh', 'name': 'Eliot Horowitz', 'email': 'eliot@10gen.com'}

Message: doing our own UTF-8 Encoding so we can avoid extra buffers. this makes BSONEncoder lightweight
prep for JAVA-130
http://github.com/mongodb/mongo-java-driver/commit/cde408cac4abc0322d1c67f9f57e5e4e19413cf9

Comment by auto [ 30/Sep/10 ]

Author:

{'login': 'erh', 'name': 'Eliot Horowitz', 'email': 'eliot@10gen.com'}

Message: remove 1 ThreadLocal by putting BSONDecoder in DBPort JAVA-130
From hans
http://github.com/mongodb/mongo-java-driver/commit/0cc187f55680856929925b3b43c68b1cb4042d0f

Comment by Hans Meiser [ 22/Sep/10 ]

Patch to move BSONDecoder into DBPort and remove threadlocal in Response. BSONDecoder is now per connection.
DBPort is pooled and so BSONDecoder is also pooled.

Comment by Eliot Horowitz (Inactive) [ 31/Aug/10 ]

Still trying to figure out exactly what the bug or standard fix is.

Comment by Klaus Lehner [ 30/Aug/10 ]

any forecast when this will be fixed?

Comment by Mike DeLaurentis [ 23/Aug/10 ]

I'm seeing this issue also, using the 2.0 version of the driver, with tomcat 6.0.29. I get these messages:

SEVERE: The web application [/vbz2-0.1] appears to have started a thread named [ObjectId-TimeFixer] but has failed to stop it. This is very likely to create a memory leak.
SEVERE: The web application [/vbz2-0.1] created a ThreadLocal with key of type [null] (value [com.mongodb.OutMessage$1@a12487]) and a value of type [com.mongodb.OutMessage] (value [com.mongodb.OutMessage@165381c]) but failed to remove it when the web application was stopped. This is very likely to create a memory leak.
SEVERE: The web application [/vbz2-0.1] created a ThreadLocal with key of type [null] (value [com.mongodb.DBTCPConnector$1@46e524]) and a value of type [com.mongodb.DBTCPConnector.MyPort] (value [com.mongodb.DBTCPConnector$MyPort@6dc8af]) but failed to remove it when the web application was stopped. This is very likely to create a memory leak.
SEVERE: The web application [/vbz2-0.1] created a ThreadLocal with key of type [null] (value [com.mongodb.Response$1@f3a7d5]) and a value of type [org.bson.BSONDecoder] (value [org.bson.BSONDecoder@8fc7ce]) but failed to remove it when the web application was stopped. This is very likely to create a memory leak.

Comment by Daniel Spilker [ 04/Aug/10 ]

This is not a Tomcat specific problem. It applies to all JEE application servers and OSGI environments.

I found this link which describes memory leaks in JEE environments: http://www.java-community.de/archives/140-Memory-leaks-et-alii.html

Comment by Eliot Horowitz (Inactive) [ 31/Jul/10 ]

Removing the thread locals is not an option.
In my simple testing its 20% slower - and when gc becomes heavy in apps, it'll be even worse.

Can anyone point to tomcat documentation on what they're thinking/expecting?

Comment by Daniel Spilker [ 30/Jul/10 ]

I created two more patches to get rid of two of the ThreadLocals: http://github.com/daspilker/mongo-java-driver/commit/c72945ca0518265b2db6dad92e1c63a09331cdcf and http://github.com/daspilker/mongo-java-driver/commit/bf47166013d03e5d798318eb9744b8c6586e70ff

As I understand the code these ThreadLocals avoid object creation for OutMessage and BSONDecoder objects. But these objects are cheap to create. So it should not decrease throughput when not caching instances of these objects.

Comment by Daniel Spilker [ 30/Jul/10 ]

Cool, I'm currently trying the same. I also noted a decrease in throughput, but I can live with that.

Comment by Eliot Horowitz (Inactive) [ 30/Jul/10 ]

I got rid of the ObejctId Thread.
its only a little slower to just call currentTimeMillis() every time
i can generate 20M object ids per second on by box, down from 30M or so

Comment by Eliot Horowitz (Inactive) [ 23/Jul/10 ]

I don't these are serious.
At most its a slight memory leak.

I still don't understand what tomcat is thinking - really doesn't make much sense to me at this point...

Comment by Matt Wright [ 23/Jul/10 ]

Would just like to say that this happens on Windows as well. Its quite disconcerting to see these "severe" messages from Tomcat when reloading or stopping the webapp. Do we need to be concerned about them? It sounds like there is some significant differences in understanding amongst the comments on this issue.

In addition to the ThreadLocal messages I also get this message just before them:

SEVERE: The web application [/compositor] appears to have started a thread named [ObjectId-TimeFixer] but has failed to stop it. This is very likely to create a memory leak.
Jul 23, 2010 10:43:48 AM org.apache.catalina.loader.WebappClassLoader clearThreadLocalMap

Comment by Eliot Horowitz (Inactive) [ 23/Jul/10 ]

That change is bad because if you have multiple Mongo instances closing one will stop the thread which is very bad.
I'll see if I can do something next week.

Comment by Daniel Spilker [ 23/Jul/10 ]

There are shutdown hooks defined by the Servlet API, but I think it is not a good practice for a database driver to register any hooks with a Servlet engine. The driver shut provide some methods to dispose all resources used by the driver. The web application is responsible for calling such methods when it is been undeployed. E.g. the web app needs to class mongo.close() for all mongo objects which have been created by the web application. When there are further resources, like threads which are shared by several mongo objects, the driver can expose more methods which the application must call to dispose these resources.

I forked the Java driver on GitHub and added a method to stop the thread which is used by ObjectId. Please have a look at http://github.com/daspilker/mongo-java-driver/commit/664383806941ad148f25fd19b428139248f2f200. My application calls mongo.close() and ObjectId.stopTimer() when it is being undeployed. This resolves the problem that the ObjectId thread keeps on running when the application is undeployed.

Comment by Eliot Horowitz (Inactive) [ 22/Jul/10 ]

Do you know if a shutdown hook will be executed for each container?
If so I can easily add a shutdown hook

Comment by Daniel Spilker [ 22/Jul/10 ]

Every webapp is loaded with it's own class loader. So when you have two webapps running in one Tomcat instance all classes are loaded and initialized twice. This means that the thread started in the static initializer in ObjectId is started twice, once for each webapp.

I think this behavior is mandated by the Servlet specification and is true for every Servlet container, not only for Tomcat.

Disposing everything on Mongo.close() may not be a good idea, when you have multiple mongo connections in one webapp. But there should be a way to clean things up after the last connection has been closed.

Comment by Eliot Horowitz (Inactive) [ 22/Jul/10 ]

Its a little weird though because in a normal open - you may have multiple Mongo objects, but a thread may use many.

So having Mongo.close() clear thread locals seems like a really bad idea...

Does tomcat guarantee that a single Thread only is used by a single app?

Comment by Daniel Spilker [ 22/Jul/10 ]

Tomcat executes the shutdown hooks for servlet etc. This is where we are calling Mongo.close(). I would expect Mongo.close() to dispose all resources used by the driver, including clearing ThreadLocals and stopping any threads.

Comment by Eliot Horowitz (Inactive) [ 22/Jul/10 ]

What is the hook tomcat expects to use to clean things up?

Comment by Daniel Spilker [ 22/Jul/10 ]

We are running the MongoDB Java driver 2.0 in a webapp in Tomcat 7.0.0 beta and we are seeing the same messages as Klaus did.

Additionally there is a thread which is marked as daemon, but not stopped when the webapp is undeloyed:

22.07.2010 18:47:25 org.apache.catalina.loader.WebappClassLoader clearReferencesThreads
SEVERE: The web application [] appears to have started a thread named [ObjectId-TimeFixer] but has failed to stop it. This is very likely to create a memory leak.

Comment by Eliot Horowitz (Inactive) [ 20/Jul/10 ]

Can you get a thread name for that?
There shouldn't be...

Comment by Klaus Lehner [ 20/Jul/10 ]

It also seems that there is a non-daemon thread that is not terminating when tomcat is stopped.

Generated at Thu Feb 08 08:51:34 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.