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"
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".
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).
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).
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).
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.
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.
*** Bug 48694 has been marked as a duplicate of this bug. ***
The issue was fixed in 5.5.x in r935947 and will be in 5.5.30 onwards.
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)
Created attachment 25409 [details] thread dump - hudson
Fixed in TC 6.0.x by r941868. Will be part of 6.0.27.
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.
Created attachment 27920 [details] Thread dump of tomcat showing blocked threads
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