Bug 48694 - WebappClassLoader deadlock if web application uses it's own classloader
Summary: WebappClassLoader deadlock if web application uses it's own classloader
Status: RESOLVED DUPLICATE of bug 48903
Alias: None
Product: Tomcat 6
Classification: Unclassified
Component: Catalina (show other bugs)
Version: 6.0.24
Hardware: PC Windows Vista
: P2 normal (vote)
Target Milestone: default
Assignee: Tomcat Developers Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2010-02-07 23:52 UTC by Eugene Petrenko
Modified: 2014-02-17 13:53 UTC (History)
1 user (show)



Attachments
Thread Dump (33.77 KB, application/octet-stream)
2010-03-13 01:56 UTC, pmonestie
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Eugene Petrenko 2010-02-07 23:52:07 UTC
OS: Windows 7 x64, JRE: 1.5.0_19-b02 (x86)


Please see the stacktrace:
TOMCAT 6.0.24 DEADLOCK

Thread1:
20:32:24 Loading VCS changes for perforce: localhost:1666: UNIT-235 {id=5}; Changes loader 5 {id=5}@6432, prio=5, in group 'main', status: 'waiting for monitor entry'
  java.lang.Thread.State: BLOCKED
	 blocks 20:32:24 Loading VCS changes for tfs: https://team-unit.labs.intellij.net:8080 $/Asd {id=3}; Changes loader 4 {id=3}@6406
	 blocks 20:32:24 Loading VCS changes for svn: http://89.163.21.152:1777/espresso/svn/dsis/trunk {id=2}; Changes loader 1 {id=2}@6412
	 waiting for 20:32:24 Loading VCS changes for tfs: https://team-unit.labs.intellij.net:8080 $/Asd {id=3}; Changes loader 4 {id=3}@6406
	  at org.apache.catalina.loader.WebappClassLoader.findClassInternal(WebappClassLoader.java:2276)
	  at org.apache.catalina.loader.WebappClassLoader.findClass(WebappClassLoader.java:976)
	  at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1451)
	  at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1329)
	  at jetbrains.buildServer.plugins.classLoaders.TeamCityClassLoader.callParentLoadClass(TeamCityClassLoader.java:45)
	  at jetbrains.buildServer.plugins.classLoaders.TeamCityClassLoader.doLoadClass(TeamCityClassLoader.java:60)
	  at jetbrains.buildServer.plugins.classLoaders.TeamCityClassLoader.loadClass(TeamCityClassLoader.java:35)
	  at java.lang.ClassLoader.loadClass(ClassLoader.java:251)
	  at java.lang.ClassLoader.loadClassInternal(ClassLoader.java:319)
	  at jetbrains.buildServer.buildTriggers.vcs.perforce.P4CommandLineConnection.runP4Command(P4CommandLineConnection.java:47)
	  at jetbrains.buildServer.buildTriggers.vcs.perforce.PerforceConnection.runCommand(PerforceConnection.java:161)
	  at jetbrains.buildServer.buildTriggers.vcs.perforce.PerforceConnection.runCommand(PerforceConnection.java:211)
	  at jetbrains.buildServer.buildTriggers.vcs.perforce.PerforceConnection.getCurrentVersion(PerforceConnection.java:264)
	  at jetbrains.buildServer.buildTriggers.vcs.perforce.PerforceSupport.getCurrentVersion(PerforceSupport.java:377)
	  at jetbrains.buildServer.buildTriggers.vcs.VcsChangesLoader.getCurrentVersion(VcsChangesLoader.java:444)
	  at jetbrains.buildServer.vcs.impl.VcsManagerImpl.getVersionsForAllRoots(VcsManagerImpl.java:1145)
	  at jetbrains.buildServer.vcs.impl.VcsManagerImpl.loadChanges(VcsManagerImpl.java:1099)
	  at jetbrains.buildServer.serverSide.impl.auth.SecuredVcsManager.loadChanges(SecuredVcsManager.java:50)
	  at jetbrains.buildServer.serverSide.impl.VcsModificationChecker$1.run(VcsModificationChecker.java:168)
	  at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:417)
	  at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:269)
	  at java.util.concurrent.FutureTask.run(FutureTask.java:123)
	  at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:651)
	  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:676)
	  at java.lang.Thread.run(Thread.java:595)



Thread2:
20:32:24 Loading VCS changes for tfs: https://team-unit.labs.intellij.net:8080 $/Asd {id=3}; Changes loader 4 {id=3}@6406, prio=5, in group 'main', status: 'waiting for monitor entry'
  java.lang.Thread.State: BLOCKED
	 blocks 20:32:24 Loading VCS changes for perforce: localhost:1666: UNIT-235 {id=5}; Changes loader 5 {id=5}@6432
	 blocks Vcs Monitor@6389
	 blocks Alarm (NotificationThread-HangedBuilds)@6498
	 blocks TeamCity Initialization@1382
	 waiting for 20:32:24 Loading VCS changes for perforce: localhost:1666: UNIT-235 {id=5}; Changes loader 5 {id=5}@6432
	  at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1363)
	  at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1329)
	  at java.lang.ClassLoader.loadClassInternal(ClassLoader.java:319)
	  at jetbrains.buildServer.SimpleCommandLineProcessRunner.runCommandSecure(SimpleCommandLineProcessRunner.java:119)
	  at jetbrains.buildServer.buildTriggers.vcs.tfs.TfsNativeExeRunner.start(TfsNativeExeRunner.java:48)
	  at jetbrains.buildServer.buildTriggers.vcs.tfs.TfsServerNativeExeRunner.start(TfsServerNativeExeRunner.java:96)
	  at jetbrains.buildServer.buildTriggers.vcs.tfs.TfsSupport$1.apply(TfsSupport.java:134)
	  at jetbrains.buildServer.buildTriggers.vcs.tfs.TfsSupport$1.apply(TfsSupport.java:131)
	  at jetbrains.buildServer.buildTriggers.vcs.tfs.TfsLock.doCommand(TfsLock.java:48)
	  at jetbrains.buildServer.buildTriggers.vcs.tfs.TfsSupport.getCurrentVersion(TfsSupport.java:130)
	  at jetbrains.buildServer.buildTriggers.vcs.VcsChangesLoader.getCurrentVersion(VcsChangesLoader.java:444)
	  at jetbrains.buildServer.vcs.impl.VcsManagerImpl.getVersionsForAllRoots(VcsManagerImpl.java:1145)
	  at jetbrains.buildServer.vcs.impl.VcsManagerImpl.loadChanges(VcsManagerImpl.java:1099)
	  at jetbrains.buildServer.serverSide.impl.auth.SecuredVcsManager.loadChanges(SecuredVcsManager.java:50)
	  at jetbrains.buildServer.serverSide.impl.VcsModificationChecker$1.run(VcsModificationChecker.java:168)
	  at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:417)
	  at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:269)
	  at java.util.concurrent.FutureTask.run(FutureTask.java:123)
	  at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:651)
	  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:676)
	  at java.lang.Thread.run(Thread.java:595)


As you may notice,

Method java.lang.ClassLoader.loadClassInternal(ClassLoader.java:319) is synchronized on this,
Method org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1451) synchonizes on class name
but 
org.apache.catalina.loader.WebappClassLoader.findClassInternal(WebappClassLoader.java:2276) synchronizes in this again!


TeamCityClassLoader class delegates to WebappClassLoader as parent classloader in the same way as ClassLoader class does.
As workaround I added synchronization on parent classloader in my code.


The fix is to make WebappClassLoader#loadClass synchronized
Comment 1 Mark Thomas 2010-02-08 10:28:29 UTC
I'd like to avoid making WebappClassLoader#loadClass synchronized if at all possible. Could you try this patch instead?

Index: java/org/apache/catalina/loader/WebappClassLoader.java
===================================================================
--- java/org/apache/catalina/loader/WebappClassLoader.java	(revision 907621)
+++ java/org/apache/catalina/loader/WebappClassLoader.java	(working copy)
@@ -989,9 +989,7 @@
             }
             if ((clazz == null) && hasExternalRepositories) {
                 try {
-                    synchronized (this) {
-                        clazz = super.findClass(name);
-                    }
+                    clazz = super.findClass(name);
                 } catch(AccessControlException ace) {
                     log.warn("WebappClassLoader.findClassInternal(" + name
                             + ") security exception: " + ace.getMessage(), ace);
@@ -2273,7 +2271,7 @@
         if (clazz != null)
             return clazz;
 
-        synchronized (this) {
+        synchronized (name.intern()) {
             clazz = entry.loadedClass;
             if (clazz != null)
                 return clazz;

Thanks,

Mark
Comment 2 aullrich 2010-02-08 14:27:08 UTC
This fix works for us here. It's not checked into trunk yet, though?


In our case a well known 3rd party library calls 
first WebappClassLoader.load(...), catches and eats any Throwable including CNFException and then delegates to Class.forName(..).

Therefore two threads trying to literally load a class with the name "x" end up being deadlocked on the name of the class and the class loader instance.

	at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1362)
	- waiting to lock <0x00002aaab67f1090> (a java.lang.String)
	at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1329)
	at java.lang.ClassLoader.loadClassInternal(ClassLoader.java:320)
	- locked <0x00002aaab9f0b4d8> (a org.apache.catalina.loader.WebappClassLoader)
	at java.lang.Class.forName0(Native Method)
	at java.lang.Class.forName(Class.java:169)

---

at org.apache.catalina.loader.WebappClassLoader.findClass(WebappClassLoader.java:993)
	- waiting to lock <0x00002aaab9f0b4d8> (a org.apache.catalina.loader.WebappClassLoader)
	at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1451)
	- locked <0x00002aaab67f1090> (a java.lang.String)
	at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1329)
Comment 3 Mark Thomas 2010-02-10 22:43:35 UTC
I've updated trunk to align with the proposed patch (it already had part of it) and proposed the patch for 6.0.x
Comment 4 Mark Thomas 2010-02-23 23:44:27 UTC
This has been fixed in 6.0.x and will be included in 6.0.25 onwards.
Comment 5 pmonestie 2010-03-13 01:29:56 UTC
In fact the deadlock still exists in 6.0.26.
Under certain conditions (well using jrebel) I get:

Name: Thread-8
State: BLOCKED on java.lang.String@1d6ebede owned by: Thread-10
Total blocked: 44  Total waited: 2

Stack trace: 
org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1395)
org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1361)

Name: Thread-10
State: BLOCKED on org.apache.catalina.loader.WebappClassLoader@646f72d4 owned by: Thread-8
Total blocked: 33  Total waited: 2

Stack trace: 
org.apache.catalina.loader.WebappClassLoader.findClass(WebappClassLoader.java)
org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1483)
org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1361)


At line 1395 replacing synchronized (name.intern()) { 
with
  synchronized (this) fixes the problem.

The issue with doing synchronized (name.intern()) { in public Class loadClass(String name, boolean resolve)  is that it turn this method calls (at least from what I could see) at line 1485 findClass(String name)

AND
public Class findClass(String name) at line 977 calls protected Class findClassInternal(String name) which syncs on name.intern()
Comment 6 Konstantin Kolinko 2010-03-13 01:33:47 UTC
Do you have full stack traces for those threads (from a thread dump)?
You can add them as an attachment.
Comment 7 Konstantin Kolinko 2010-03-13 01:37:47 UTC
And what is your configuration (JVM vendor and version), and do you use custom class loader, as *this* bug does, 
or you do not, and it is another bug (e.g. bug 48903)?
Comment 8 pmonestie 2010-03-13 01:56:00 UTC
Created attachment 25124 [details]
Thread Dump
Comment 9 pmonestie 2010-03-13 01:57:28 UTC
java version "1.6.0_13"
Java(TM) SE Runtime Environment (build 1.6.0_13-b03-211)
Java HotSpot(TM) 64-Bit Server VM (build 11.3-b02-83, mixed mode)

This is on a mac.

No no custom classloader but this happens when I run Tomcat with JRebel (2 or 3). The relevant traces (from another run is as follow)

Find also attached the ThreadDump

Name: Thread-10
State: BLOCKED on java.lang.String@9edcacb owned by: Thread-9
Total blocked: 28  Total waited: 1

Stack trace: 
org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1395)
org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1361)
org.hibernate.util.ReflectHelper.classForName(ReflectHelper.java:95)
org.hibernate.util.ReflectHelper.getConstantValue(ReflectHelper.java:122)
org.hibernate.hql.ast.QueryTranslatorImpl$JavaConstantConverter.handleDotStructure(QueryTranslatorImpl.java:569)
org.hibernate.hql.ast.QueryTranslatorImpl$JavaConstantConverter.visit(QueryTranslatorImpl.java:564)
org.hibernate.hql.ast.util.NodeTraverser.visitDepthFirst(NodeTraverser.java:40)
org.hibernate.hql.ast.util.NodeTraverser.visitDepthFirst(NodeTraverser.java:41)
org.hibernate.hql.ast.util.NodeTraverser.visitDepthFirst(NodeTraverser.java:41)
org.hibernate.hql.ast.util.NodeTraverser.visitDepthFirst(NodeTraverser.java:41)
org.hibernate.hql.ast.util.NodeTraverser.traverseDepthFirst(NodeTraverser.java:33)
org.hibernate.hql.ast.QueryTranslatorImpl.parse(QueryTranslatorImpl.java:254)
org.hibernate.hql.ast.QueryTranslatorImpl.doCompile(QueryTranslatorImpl.java:157)
org.hibernate.hql.ast.QueryTranslatorImpl.compile(QueryTranslatorImpl.java:111)
org.hibernate.engine.query.HQLQueryPlan.<init>(HQLQueryPlan.java:77)
org.hibernate.engine.query.HQLQueryPlan.<init>(HQLQueryPlan.java:56)
org.hibernate.engine.query.QueryPlanCache.getHQLQueryPlan(QueryPlanCache.java:72)
org.hibernate.impl.AbstractSessionImpl.getHQLQueryPlan(AbstractSessionImpl.java:133)
org.hibernate.impl.SessionImpl.list(SessionImpl.java:1113)
org.hibernate.impl.QueryImpl.list(QueryImpl.java:79)


AND



Name: Thread-9
State: BLOCKED on org.apache.catalina.loader.WebappClassLoader@1f302997 owned by: Thread-11
Total blocked: 34  Total waited: 2

Stack trace: 
org.apache.catalina.loader.WebappClassLoader.findClass(WebappClassLoader.java)
org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1483)
org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1361)
org.hibernate.util.ReflectHelper.classForName(ReflectHelper.java:95)
org.hibernate.util.ReflectHelper.getConstantValue(ReflectHelper.java:122)
org.hibernate.hql.ast.QueryTranslatorImpl$JavaConstantConverter.handleDotStructure(QueryTranslatorImpl.java:569)
org.hibernate.hql.ast.QueryTranslatorImpl$JavaConstantConverter.visit(QueryTranslatorImpl.java:564)
org.hibernate.hql.ast.util.NodeTraverser.visitDepthFirst(NodeTraverser.java:40)
org.hibernate.hql.ast.util.NodeTraverser.visitDepthFirst(NodeTraverser.java:41)
org.hibernate.hql.ast.util.NodeTraverser.visitDepthFirst(NodeTraverser.java:41)
org.hibernate.hql.ast.util.NodeTraverser.visitDepthFirst(NodeTraverser.java:41)
org.hibernate.hql.ast.util.NodeTraverser.traverseDepthFirst(NodeTraverser.java:33)
org.hibernate.hql.ast.QueryTranslatorImpl.parse(QueryTranslatorImpl.java:254)
org.hibernate.hql.ast.QueryTranslatorImpl.doCompile(QueryTranslatorImpl.java:157)
org.hibernate.hql.ast.QueryTranslatorImpl.compile(QueryTranslatorImpl.java:111)
org.hibernate.engine.query.HQLQueryPlan.<init>(HQLQueryPlan.java:77)
org.hibernate.engine.query.HQLQueryPlan.<init>(HQLQueryPlan.java:56)
org.hibernate.engine.query.QueryPlanCache.getHQLQueryPlan(QueryPlanCache.java:72)
org.hibernate.impl.AbstractSessionImpl.getHQLQueryPlan(AbstractSessionImpl.java:133)
org.hibernate.impl.SessionImpl.list(SessionImpl.java:1113)
org.hibernate.impl.QueryImpl.list(QueryImpl.java:79)

(In reply to comment #8)
> Created an attachment (id=25124) [details]
> Thread Dump

(In reply to comment #8)
> Created an attachment (id=25124) [details]
> Thread Dump
Comment 10 pmonestie 2010-03-13 05:45:36 UTC
So looking at all this I think the problem is as follow:

Thread1

If you call Class.forName in turn You call ClassLoader.loadClassInternal and this is synchronized on this. Following that you enter WebappClassLoader and get a lock on string.intern()

Thread2
On another thread you call WebAppClassLoader.loadClass which gets a lock on string.intern() but also calls defineClass which is synchronized on this .

It seems possible to get a deadlock from the sequence of event.

I'm not sure why I seem to hit this bug more when using JRebel.
Comment 11 aullrich 2010-03-13 15:44:31 UTC
Can't see how you'd get into this situation with the current source code.
The stack traces indicate that findClass on the WebappClassLoader would have to be a synchronized method? Is JRebel changing the byte code of the loader by any chance?
But maybe I'm just blind ;-)
Comment 12 pmonestie 2010-03-14 20:58:10 UTC
yea I guess you are right. The stacktrace is suspicious in the sense that there is no line number here:
at org.apache.catalina.loader.WebappClassLoader.findClass(WebappClassLoader.java)
	- waiting to lock

Hmm I'll try to see with the JRebel guys what could be wrong. One quick fix, for the poeple that have the same issue than me is to synchronize on 'this' in loadClass.

Thanks again for all your help.
Comment 13 Konstantin Kolinko 2010-03-25 19:12:05 UTC
(In reply to comment #8)
> Created an attachment (id=25124) [details]
> Thread Dump

The issue that you are observing in Comment 5 and below is caused by combination of synchronized(name.intern()) in Tomcat and synchronized(classLoader) in JRE classes. See bug 48903 for an explanation, and
http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=4670071


Bugs 44041 and this bug 48694 are still to be fixed in Tomcat 5.5.
Comment 14 Konstantin Kolinko 2010-04-20 11:26:18 UTC
The issue (both the original one, and the one in Comment 5 and below) was fixed in 5.5.x in r935947 and will be in 5.5.30 onwards.

The issue in Comment 5 and below has not been fixed in 6.0.x yet, but the patch is already proposed. It is tracked as bug 48903. Thus, I am closing this one.

*** This bug has been marked as a duplicate of bug 48903 ***