Bug 48903 - ClassLoader deadlock when compiling JSP pages in 6.0.26
ClassLoader deadlock when compiling JSP pages in 6.0.26
Status: RESOLVED FIXED
Product: Tomcat 6
Classification: Unclassified
Component: Catalina
6.0.33
PC Linux
: P2 critical (vote)
: default
Assigned To: Tomcat Developers Mailing List
:
: 48694 (view as bug list)
Depends on:
Blocks:
  Show dependency tree
 
Reported: 2010-03-12 22:21 UTC by Konstantin Kolinko
Modified: 2014-02-17 13:53 UTC (History)
5 users (show)



Attachments
threads_20100313_0109.txt - thread dump (58.84 KB, text/plain)
2010-03-12 22:21 UTC, Konstantin Kolinko
Details
MyClassLoader.java - sample of reflectively calling JDK7 API (1.74 KB, text/plain)
2010-03-14 00:31 UTC, Konstantin Kolinko
Details
2010-03-15_tc6_bug48903_v2.patch (13.20 KB, patch)
2010-03-25 19:57 UTC, Konstantin Kolinko
Details | Diff
thread dump - hudson (155.03 KB, text/plain)
2010-05-06 14:39 UTC, aullrich
Details
Thread dump of tomcat showing blocked threads (391.11 KB, text/plain)
2011-11-10 18:56 UTC, Greg Walters
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Konstantin Kolinko 2010-03-12 22:21:19 UTC
Created attachment 25123 [details]
threads_20100313_0109.txt - thread dump

Steps to reproduce:

1. Install TC 6.0.26
I am using Sun JRE 6u18

2. Download tomahawk-examples-1.1.8-bin.zip from
http://myfaces.apache.org/tomahawk/download.html
and copy myfaces-example-simple-1.1.8.war from the archive to the webapps folder of Tomcat

3. Start Tomcat and browse http://localhost:8080/myfaces-example-simple-1.1.8/

4. Try to open several links (Sample 1, .. Filtered Stylesheet) at the same time.
I am using Snap Links plugin for Firefox, http://snaplinks.mozdev.org/

5. Several Tabs are opened in the browser to load the pages, but pages never load.

6. Using jvisualvm tool I can see that there is a deadlock in Tomcat. The thread dump is attached.

Citing from the dump:

Found one Java-level deadlock:
=============================
"http-8080-6":
  waiting to lock monitor 0x1731bafc (object 0x08189dd0, a org.apache.catalina.loader.WebappClassLoader),
  which is held by "http-8080-1"
"http-8080-1":
  waiting to lock monitor 0x1731b88c (object 0x13bdb118, a java.lang.String),
  which is held by "http-8080-5"
"http-8080-5":
  waiting to lock monitor 0x1731bafc (object 0x08189dd0, a org.apache.catalina.loader.WebappClassLoader),
  which is held by "http-8080-1"
Comment 1 Konstantin Kolinko 2010-03-12 22:33:19 UTC
What is strange is that I cannot confirm that org.apache.catalina.loader.WebappClassLoader is held by "http-8080-1" -- that is not shown in the stacktrace of thread "http-8080-1".
Comment 2 Konstantin Kolinko 2010-03-13 03:07:26 UTC
Digging further I should say that
1. There is, indeed, lock on the ClassLoader in the native code.

2. There is "experimental" option to turn off that locking. E.g., described here:
http://underlap.blogspot.com/2006/11/experimental-fix-for-sunbug-4670071.html
and thus Tomcat is not the first one to run into such an issue.

3. Evaluation part of http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=4670071
mentions API change to allow parallel classloading, and API change actually means that it will be no sooner than JDK7. See

http://java.sun.com/javase/7/docs/api/java/lang/ClassLoader.html
methods registerAsParallelCapable() and getClassLoadingLock(String)


While I was evaluating this, several comments were added to bug 48694, especially attachment 25124 [details], which is another sample of a deadlock (in that case JRE is 1.6.0_13).
Comment 3 Konstantin Kolinko 2010-03-14 00:31:00 UTC
Created attachment 25125 [details]
MyClassLoader.java - sample of reflectively calling JDK7 API

I just tested that the JDK7 ClassLoader methods that I mentioned in comment 2 can be reflectively called by a class compiled with JDK 6. I was afraid that registerAsParallelCapable() will not work when called through reflection.

I am attaching a sample ClassLoader implementation that calls those methods.
On success it prints something like this:

Result: true
Lock: java.lang.Object@1befab0

where the lock is not the classloader, but some other object.
I tested that it runs successfully with JDK7 early access milestone 5 (jre-7-ea-bin-b76-windows-i586-12_nov_2009).
Comment 4 Konstantin Kolinko 2010-03-25 18:44:47 UTC
For reference: synchronized(name.intern()) was introduced by patches to bug 44041 and bug 48694. (r881748 and r915592 - Tomcat 6.0.21 and 6.0.25 respectively).

I tested Tomcat 6.0.24 with myfaces-example-simple-1.1.8.war as described in comment 0 and I do not observe this issue with JRE 6u18, but do observe it with JRE 7 beta milestone 5 (1.7.0-ea-b76).
Comment 5 Mark Thomas 2010-03-25 19:56:28 UTC
The simple solution of synchronized(this) has been applied to trunk and proposed for 6.0.x. Alternatives will be explored in 7.0.x and back-ported once proven stable.
Comment 6 Konstantin Kolinko 2010-03-25 19:57:49 UTC
Created attachment 25185 [details]
2010-03-15_tc6_bug48903_v2.patch

Patch for the current tc6.0.x (as of rev.922264) that fixes this issue *and* introduces a new system property and helper class to make use of the new JRE 7 feature of parallel classloading.


Known issues with this patch, found during review
(should be fixed before applying it):
-----------------------------------------------------
1. "JasperLoader extends LockAwareURLClassLoader":
It creates a dependency between Jasper and Catalina. Jasper should be independent.

Maybe move the class into o.a.tomcat.util.<something>.*

May consider to rename the package part of the "CLASSLOADER_LOCK_POLICY" system property as well.


2. Use the StringManager for i18n.

Though as far as I see all those are debug messages, so i18n may be not necessary there.

3. o.a.catalina.loader.StandardClassLoader should also inherit from LockAwareURLClassLoader and call "registerAsParallelCapable", like JasperLoader does.

It means that LockAwareURLClassLoader class should be included into bootstrap.jar and removed from other Tomcat jars.

Thus, some changes to the build.xml file are also necessary.


4. I have doubt that support for the "name" as value of CLASSLOADER_LOCK_POLICY is needed. Even if it works with recent JRE 6 with some (undocumented) options, I will not recommend it for production. Is anybody there who needs that feature?

5. JRE 7 is not released yet, so something can still be changing there.
Comment 7 Konstantin Kolinko 2010-04-20 11:26:18 UTC
*** Bug 48694 has been marked as a duplicate of this bug. ***
Comment 8 Konstantin Kolinko 2010-04-20 11:27:55 UTC
The issue was fixed in 5.5.x in r935947 and will be in 5.5.30 onwards.
Comment 9 aullrich 2010-05-06 14:37:06 UTC
We are running hudson 1.356, java.exe from jdk1.6.0_14 and tomcat 6.0.26 and get deadlocks
Excerpts below - going to attach full log.

Found one Java-level deadlock:
=============================
"Handling GET /job/Project1Trunk/ : http-8080-40":
  waiting to lock monitor 0x000000005b013e50 (object 0x00002aaac2cc9b58, a java.net.URLClassLoader),
  which is held by "Handling GET /job/Project2Trunk/disk-usage/graph : http-8080-22"
"Handling GET /job/Project2Trunk/disk-usage/graph : http-8080-22":
  waiting to lock monitor 0x000000005b986958 (object 0x00002aaab4465798, a java.lang.String),
  which is held by "Handling GET /job/Project2Trunk/emma/graph : http-8080-14"
"Handling GET /job/Project2Trunk/emma/graph : http-8080-14":
  waiting to lock monitor 0x000000005b0169a0 (object 0x00002aaac266fc30, a org.apache.catalina.loader.WebappClassLoader),
  which is held by "Handling GET /job/Project2Trunk/test/trend : http-8080-15"
"Handling GET /job/Project2Trunk/test/trend : http-8080-15":
  waiting to lock monitor 0x000000005b986958 (object 0x00002aaab4465798, a java.lang.String),
  which is held by "Handling GET /job/Project2Trunk/emma/graph : http-8080-14"
        
Java stack information for the threads listed above:
===================================================
"Handling GET /job/Project1Trunk/ : http-8080-40":
        at sun.misc.Unsafe.defineClass(Native Method)
        at sun.reflect.ClassDefiner.defineClass(ClassDefiner.java:45)
        at sun.reflect.MethodAccessorGenerator$1.run(MethodAccessorGenerator.java:381)
...

"Handling GET /job/Project2Trunk/disk-usage/graph : http-8080-22":
        at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1394)
        - waiting to lock <0x00002aaab4465798> (a java.lang.String)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:300)
        - locked <0x00002aaac2c3ed48> (a hudson.ClassicPluginStrategy$DependencyClassLoader)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:300)
        - locked <0x00002aaac2cc9b58> (a java.net.URLClassLoader)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:252)
        at java.lang.ClassLoader.loadClassInternal(ClassLoader.java:320)
        - locked <0x00002aaac2cc9b58> (a java.net.URLClassLoader)
        at hudson.plugins.disk_usage.ProjectDiskUsageAction.doGraph(ProjectDiskUsageAction.java:106)
...

"Handling GET /job/Project2Trunk/emma/graph : http-8080-14":
        at java.lang.ClassLoader.checkCerts(ClassLoader.java:752)
        - waiting to lock <0x00002aaac266fc30> (a org.apache.catalina.loader.WebappClassLoader)
        at java.lang.ClassLoader.preDefineClass(ClassLoader.java:488)
        at java.lang.ClassLoader.defineClass(ClassLoader.java:615)
        at java.security.SecureClassLoader.defineClass(SecureClassLoader.java:124)
        at org.apache.catalina.loader.WebappClassLoader.findClassInternal(WebappClassLoader.java:2527)
        - locked <0x00002aaab4465798> (a java.lang.String)
        at org.apache.catalina.loader.WebappClassLoader.findClass(WebappClassLoader.java:1010)
        at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1483)
        - locked <0x00002aaab4465798> (a java.lang.String)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:300)
        - locked <0x00002aaac2ce9f90> (a hudson.ClassicPluginStrategy$DependencyClassLoader)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:300)
        - locked <0x00002aaac2ce9f08> (a java.net.URLClassLoader)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:252)
        at java.lang.ClassLoader.loadClassInternal(ClassLoader.java:320)
        - locked <0x00002aaac2ce9f08> (a java.net.URLClassLoader)
        at hudson.plugins.emma.CoverageObject.doGraph(CoverageObject.java:156)
        at hudson.plugins.emma.EmmaProjectAction.doGraph(EmmaProjectAction.java:52)
....

"Handling GET /job/Project2Trunk/test/trend : http-8080-15":
        at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1394)
        - waiting to lock <0x00002aaab4465798> (a java.lang.String)
        at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1361)
        at java.lang.ClassLoader.loadClassInternal(ClassLoader.java:320)
        - locked <0x00002aaac266fc30> (a org.apache.catalina.loader.WebappClassLoader)
        at hudson.tasks.test.AbstractTestResultAction.buildDataSet(AbstractTestResultAction.java:244)
        at hudson.tasks.test.AbstractTestResultAction.doGraph(AbstractTestResultAction.java:208)
        at hudson.tasks.test.TestResultProjectAction.doTrend(TestResultProjectAction.java:97)
Comment 10 aullrich 2010-05-06 14:39:15 UTC
Created attachment 25409 [details]
thread dump - hudson
Comment 11 Rainer Jung 2010-05-06 15:20:20 UTC
Fixed in TC 6.0.x by r941868. Will be part of 6.0.27.
Comment 12 Greg Walters 2011-11-10 18:19:00 UTC
I've been able to confirm that this bug has not been fixed in 6.0.28 and 6.0.33. Possible regression? I'll attach a full log as soon as I get permission to release the logs but in the meantime here's the stack-trace I get:

**
@400000004ebc0ed6372bb204 "http-scrubbed%2F172.18.12.12-8083-144" daemon prio=10 tid=0x00002aaae40c9800 nid=0x4d09 waiting for moni
tor entry [0x000000004b0dd000]
@400000004ebc0ed6372bb9d4    java.lang.Thread.State: BLOCKED (on object monitor)
@400000004ebc0ed6372bbdbc       at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1559)
@400000004ebc0ed6372c07f4       - waiting to lock <0x00002aaab41214a0> (a org.apache.catalina.loader.WebappClassLoader)
@400000004ebc0ed6372c0fc4       at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1526)
@400000004ebc0ed6372c13ac       at org.apache.cxf.common.classloader.ClassLoaderUtils.loadClass(ClassLoaderUtils.java:217)
@400000004ebc0ed6372c1b7c       at org.apache.cxf.jaxws.support.JaxWsServiceConfiguration.getRequestWrapper(JaxWsServiceConfiguration.java:629)
@400000004ebc0ed6372c36d4       at org.apache.cxf.service.factory.ReflectionServiceFactoryBean.getRequestWrapper(ReflectionServiceFactoryBean.java:2053)
@400000004ebc0ed6372c428c       at org.apache.cxf.jaxws.support.JaxWsServiceFactoryBean.initializeWrapping(JaxWsServiceFactoryBean.java:311)
@400000004ebc0ed6372c4a5c       at org.apache.cxf.jaxws.support.JaxWsServiceFactoryBean.initializeWSDLOperation(JaxWsServiceFactoryBean.java:211)
@400000004ebc0ed6372c7554       at org.apache.cxf.service.factory.ReflectionServiceFactoryBean.initializeWSDLOperations(ReflectionServiceFactoryBean.java:551)
@400000004ebc0ed6372c7d24       at org.apache.cxf.jaxws.support.JaxWsServiceFactoryBean.initializeWSDLOperations(JaxWsServiceFactoryBean.java:253)
@400000004ebc0ed6372c84f4       at org.apache.cxf.service.factory.ReflectionServiceFactoryBean.buildServiceFromWSDL(ReflectionServiceFactoryBean.java:335)
@400000004ebc0ed6372ca04c       at org.apache.cxf.service.factory.ReflectionServiceFactoryBean.initializeServiceModel(ReflectionServiceFactoryBean.java:435)
@400000004ebc0ed6372cac04       at org.apache.cxf.service.factory.ReflectionServiceFactoryBean.create(ReflectionServiceFactoryBean.java:192)
@400000004ebc0ed6372cafec       at org.apache.cxf.jaxws.support.JaxWsServiceFactoryBean.create(JaxWsServiceFactoryBean.java:164)
@400000004ebc0ed6372cc75c       at org.apache.cxf.jaxws.ServiceImpl.createPort(ServiceImpl.java:408)
@400000004ebc0ed6372ccb44       at org.apache.cxf.jaxws.ServiceImpl.getPort(ServiceImpl.java:292)
@400000004ebc0ed6372ccf2c       at org.apache.cxf.jaxws.ServiceImpl.getPort(ServiceImpl.java:287)
@400000004ebc0ed6372cd6fc       at javax.xml.ws.Service.getPort(Service.java:161)
@400000004ebc0ed6372cfa24       at org.jivesoftware.webservices.ServiceProvider.getUserService(ServiceProvider.java:108)
@400000004ebc0ed6372d01f4       at org.apache.jsp.index_jsp._jspService(index_jsp.java:642)
@400000004ebc0ed6372d05dc       at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:70)
@400000004ebc0ed6372d09c4       at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
@400000004ebc0ed6372d0dac       at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:388)
@400000004ebc0ed6372d2904       at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:313)
@400000004ebc0ed6372d2cec       at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:260)
@400000004ebc0ed6372d30d4       at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
@400000004ebc0ed6372d38a4       at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
@400000004ebc0ed6372d4c2c       at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
@400000004ebc0ed6372d53fc       at com.opensymphony.module.sitemesh.filter.PageFilter.parsePage(PageFilter.java:118)
@400000004ebc0ed6372d57e4       at com.opensymphony.module.sitemesh.filter.PageFilter.doFilter(PageFilter.java:52)
@400000004ebc0ed6372d5bcc       at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
@400000004ebc0ed6372d8aac       at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
@400000004ebc0ed6372d8e94       at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
@400000004ebc0ed6372d9664       at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
@400000004ebc0ed6372d9a4c       at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
@400000004ebc0ed6372e07ac       at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
@400000004ebc0ed6372e0b94       at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
@400000004ebc0ed6372e1364       at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:291)
@400000004ebc0ed6372e4244       at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:859)
@400000004ebc0ed6372e4a14       at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:602)
@400000004ebc0ed6372e4dfc       at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489)
@400000004ebc0ed6372e55cc       at java.lang.Thread.run(Thread.java:619)
**

To reproduce the issue I need only start multiple http requests to tomcat within a short time.
Comment 13 Greg Walters 2011-11-10 18:56:49 UTC
Created attachment 27920 [details]
Thread dump of tomcat showing blocked threads
Comment 14 Rainer Jung 2011-11-10 19:39:49 UTC
There's no deadlock in your thread dump. There's just one thread holding a lock and many other threads queing up behind. The thread that holds the lock is

@400000004ebc1d9333afcdcc "http-j2ee.www.igniterealtime.org%2F172.18.12.12-8083-145" daemon prio=10 tid=0x00002aaae437f000 nid=0x6162 runnable [0x0000000040e39000]
@400000004ebc1d9333aff0f4    java.lang.Thread.State: RUNNABLE
@400000004ebc1d9333b02b8c 	at java.lang.Throwable.fillInStackTrace(Native Method)
@400000004ebc1d9333b02f74 	- locked <0x00002aaad7afb280> (a java.security.PrivilegedActionException)
@400000004ebc1d9333b04acc 	at java.lang.Throwable.<init>(Throwable.java:241)
@400000004ebc1d9333b0623c 	at java.lang.Exception.<init>(Exception.java:77)
@400000004ebc1d9333b079ac 	at java.security.PrivilegedActionException.<init>(PrivilegedActionException.java:48)
@400000004ebc1d9333b0911c 	at java.security.AccessController.doPrivileged(Native Method)
@400000004ebc1d9333b0ac74 	at java.net.URLClassLoader.findClass(URLClassLoader.java:190)
@400000004ebc1d9333b10a34 	at java.lang.ClassLoader.loadClass(ClassLoader.java:307)
@400000004ebc1d9333b10e1c 	- locked <0x00002aaab360cb98> (a sun.misc.Launcher$AppClassLoader)
@400000004ebc1d9333b12d5c 	at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:301)
@400000004ebc1d9333b13144 	- locked <0x00002aaab360cb98> (a sun.misc.Launcher$AppClassLoader)
@400000004ebc1d9333b16024 	at java.lang.ClassLoader.loadClass(ClassLoader.java:248)
@400000004ebc1d9333b17794 	at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1595)
@400000004ebc1d9333b17b7c 	- locked <0x00002aaab4024170> (a org.apache.catalina.loader.WebappClassLoader)

As you can see the thread handles an exception. Stack creation for an exception can be quite slow, especially if it happens very often. Bugzilla is not a support forum. Please followup with your problem on the Tomcat users list.

Regards,

Rainer