Hi All,
I’ll likely raise a JIRA ticket for this, but I wanted to start with this
mailing list.
I’ll try to explain what we’re seeing…
We are running a fairly large Tapestry application with hundreds of concurrent
users.
When under load, we are occasionally seeing an instance go into deadlock,
whereby the Tomcat threads max out, but the CPU is virtually zero.
This can commonly occur when a new instance starts up under heavy load, but can
also happen on an instance that has been running for several days.
The log files give clues as to what’s happening, but nothing definitive. For
example:
2024-11-12T15:26:20.925Z {name=ip-10-242-182-176.ec2.internal} ERROR
[2024-11-12T15:26:13,611]
PQSL-STAT,start=2024-11-11.14:23:02,instance=i-01da4661bc7f47e18,host=ip-10-242-182-176,sub=main,version=2024.11.0.7644
31/10/2024
07:39:01,hours=25.05,threadBlktime=0,threads=408,run=57,block=38,wait=133,timed=180,locks=[org.apache.tapestry5.services.pageload.PageClassLoaderContextManagerImpl(2),java.util.jar.JarFile(10),java.lang.Object(25),java.io.ExpiringCache(1)],heapuse=16092,heapmax=24849,gc=1,
2024-11-12T15:26:20.925Z {name=ip-10-242-182-176.ec2.internal} ERROR
[2024-11-12T15:26:13,611]
[email protected]/java.util.zip.ZipFile.getEntry(ZipFile.java:347)
2024-11-12T15:26:20.925Z {name=ip-10-242-182-176.ec2.internal}
[email protected]/java.util.zip.ZipFile$1.getEntry(ZipFile.java:1143)
2024-11-12T15:26:20.925Z {name=ip-10-242-182-176.ec2.internal}
[email protected]/java.util.jar.JarFile.getEntry0(JarFile.java:586)
2024-11-12T15:26:20.925Z {name=ip-10-242-182-176.ec2.internal}
[email protected]/java.util.jar.JarFile.getEntry(JarFile.java:516)
2024-11-12T15:26:20.926Z {name=ip-10-242-182-176.ec2.internal}
[email protected]/java.util.jar.JarFile.getJarEntry(JarFile.java:478)
2024-11-12T15:26:20.926Z {name=ip-10-242-182-176.ec2.internal}
org.apache.catalina.webresources.AbstractSingleArchiveResourceSet.getArchiveEntry(AbstractSingleArchiveResourceSet.java:97)
2024-11-12T15:26:20.926Z {name=ip-10-242-182-176.ec2.internal}
org.apache.catalina.webresources.AbstractArchiveResourceSet.getResource(AbstractArchiveResourceSet.java:244)
2024-11-12T15:26:20.926Z {name=ip-10-242-182-176.ec2.internal}
org.apache.catalina.webresources.StandardRoot.getResourceInternal(StandardRoot.java:272)
2024-11-12T15:26:20.926Z {name=ip-10-242-182-176.ec2.internal}
org.apache.catalina.webresources.Cache.getResource(Cache.java:64)
2024-11-12T15:26:20.926Z {name=ip-10-242-182-176.ec2.internal}
org.apache.catalina.webresources.StandardRoot.getResource(StandardRoot.java:211)
2024-11-12T15:26:20.926Z {name=ip-10-242-182-176.ec2.internal}
org.apache.catalina.webresources.StandardRoot.getClassLoaderResource(StandardRoot.java:220)
2024-11-12T15:26:20.926Z {name=ip-10-242-182-176.ec2.internal}
org.apache.catalina.loader.WebappClassLoaderBase.findClassInternal(WebappClassLoaderBase.java:2170)
2024-11-12T15:26:20.926Z {name=ip-10-242-182-176.ec2.internal}
org.apache.catalina.loader.WebappClassLoaderBase.findClass(WebappClassLoaderBase.java:797)
2024-11-12T15:26:20.926Z {name=ip-10-242-182-176.ec2.internal}
org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1272)
2024-11-12T15:26:20.926Z {name=ip-10-242-182-176.ec2.internal}
org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1120)
2024-11-12T15:47:12.497Z {name=ip-10-243-125-250.ec2.internal} ERROR
[2024-11-12T15:47:08,652]
PQSL-STAT,start=2024-11-12.15:46:07,instance=i-05996408538cc4fa2,host=ip-10-243-125-250,sub=main,version=2024.11.0.7644
31/10/2024
07:39:01,hours=0.02,threadBlktime=0,threads=130,run=16,block=12,wait=78,timed=24,locks=[org.apache.tapestry5.internal.plastic.PlasticClassLoader(9),org.apache.tapestry5.beanmodel.internal.services.PropertyAccessImpl(3)],heapuse=607,heapmax=24849,gc=7,
2024-11-12T15:47:12.497Z {name=ip-10-243-125-250.ec2.internal} ERROR
[2024-11-12T15:47:08,653]
org.apache.tapestry5.internal.plastic.PlasticClassPool.realizeTransformedClass(PlasticClassPool.java:164)
2024-11-12T15:47:12.497Z {name=ip-10-243-125-250.ec2.internal}
org.apache.tapestry5.internal.plastic.PlasticClassImpl.createInstantiator(PlasticClassImpl.java:650)
2024-11-12T15:47:12.497Z {name=ip-10-243-125-250.ec2.internal}
org.apache.tapestry5.plastic.PlasticManager.createProxy(PlasticManager.java:289)
2024-11-12T15:47:12.497Z {name=ip-10-243-125-250.ec2.internal}
org.apache.tapestry5.plastic.PlasticManager.createProxy(PlasticManager.java:262)
2024-11-12T15:47:12.497Z {name=ip-10-243-125-250.ec2.internal}
org.apache.tapestry5.plastic.PlasticManager.createProxy(PlasticManager.java:229)
2024-11-12T15:47:12.497Z {name=ip-10-243-125-250.ec2.internal}
org.apache.tapestry5.beanmodel.services.PlasticProxyFactoryImpl.createProxy(PlasticProxyFactoryImpl.java:86)
2024-11-12T15:47:12.497Z {name=ip-10-243-125-250.ec2.internal}
org.apache.tapestry5.beanmodel.internal.services.PropertyConduitSourceImpl.build(PropertyConduitSourceImpl.java:1527)
2024-11-12T15:47:12.497Z {name=ip-10-243-125-250.ec2.internal}
org.apache.tapestry5.beanmodel.internal.services.PropertyConduitSourceImpl.create(PropertyConduitSourceImpl.java:1441)
2024-11-12T15:47:12.497Z {name=ip-10-243-125-250.ec2.internal}
$PropertyConduitSource_134db79fe0.create(Unknown Source)
2024-11-12T15:47:12.497Z {name=ip-10-243-125-250.ec2.internal}
org.apache.tapestry5.internal.bindings.PropBindingFactory.newBinding(PropBindingFactory.java:56)
2024-11-12T15:47:12.497Z {name=ip-10-243-125-250.ec2.internal}
$BindingFactory_134db7a16b.newBinding(Unknown Source)
2024-11-12T15:47:12.497Z {name=ip-10-243-125-250.ec2.internal}
$BindingFactory_134db7a162.newBinding(Unknown Source)
2024-11-12T15:47:12.497Z {name=ip-10-243-125-250.ec2.internal}
org.apache.tapestry5.internal.services.BindingSourceImpl.newBinding(BindingSourceImpl.java:82)
2024-11-12T15:47:12.497Z {name=ip-10-243-125-250.ec2.internal}
$BindingSource_134db7a0ba.newBinding(Unknown Source)
2024-11-12T15:47:12.497Z {name=ip-10-243-125-250.ec2.internal}
org.apache.tapestry5.internal.services.PageElementFactoryImpl.parseAttributeExpansionExpression(PageElementFactoryImpl.java:117)
2024-11-12T15:47:12.497Z {name=ip-10-243-125-250.ec2.internal}
org.apache.tapestry5.internal.services.PageElementFactoryImpl.newBinding(PageElementFactoryImpl.java:177)
2024-11-12T15:47:12.497Z {name=ip-10-243-125-250.ec2.internal}
$PageElementFactory_134db7a0d5.newBinding(Unknown Source)
2024-11-12T15:47:12.497Z {name=ip-10-243-125-250.ec2.internal}
org.apache.tapestry5.internal.pageload.PageLoaderImpl$10.execute(PageLoaderImpl.java:941)
2024-11-12T15:47:12.497Z {name=ip-10-243-125-250.ec2.internal}
org.apache.tapestry5.internal.pageload.ComponentAssemblerImpl.runActions(ComponentAssemblerImpl.java:229)
2024-11-12T15:47:12.497Z {name=ip-10-243-125-250.ec2.internal}
org.apache.tapestry5.internal.pageload.ComponentAssemblerImpl.access$300(ComponentAssemblerImpl.java:37)
2024-11-12T15:47:12.497Z {name=ip-10-243-125-250.ec2.internal}
org.apache.tapestry5.internal.pageload.ComponentAssemblerImpl$2.run(ComponentAssemblerImpl.java:180)
2024-11-12T15:47:12.497Z {name=ip-10-243-125-250.ec2.internal}
org.apache.tapestry5.ioc.internal.OperationTrackerImpl.run(OperationTrackerImpl.java:56)
2024-11-12T15:47:12.497Z {name=ip-10-243-125-250.ec2.internal}
org.apache.tapestry5.ioc.internal.PerThreadOperationTracker.run(PerThreadOperationTracker.java:60)
2024-11-12T15:47:12.497Z {name=ip-10-243-125-250.ec2.internal}
org.apache.tapestry5.ioc.internal.RegistryImpl.run(RegistryImpl.java:1286)
2024-11-12T15:47:12.497Z {name=ip-10-243-125-250.ec2.internal}
org.apache.tapestry5.internal.pageload.ComponentAssemblerImpl.assembleEmbeddedComponent(ComponentAssemblerImpl.java:158)
2024-11-12T15:47:12.497Z {name=ip-10-243-125-250.ec2.internal}
org.apache.tapestry5.internal.pageload.PageLoaderImpl$12.execute(PageLoaderImpl.java:1021)
2024-11-12T15:47:12.497Z {name=ip-10-243-125-250.ec2.internal}
org.apache.tapestry5.internal.pageload.ComponentAssemblerImpl.runActions(ComponentAssemblerImpl.java:229)
2024-11-12T15:47:12.497Z {name=ip-10-243-125-250.ec2.internal}
org.apache.tapestry5.internal.pageload.ComponentAssemblerImpl.access$300(ComponentAssemblerImpl.java:37)
2024-11-12T15:47:12.497Z {name=ip-10-243-125-250.ec2.internal}
org.apache.tapestry5.internal.pageload.ComponentAssemblerImpl$2.run(ComponentAssemblerImpl.java:180)
2024-11-12T16:16:05.913Z {name=ip-10-243-120-52.ec2.internal} ERROR
[2024-11-12T16:15:56,585]
PQSL-STAT,start=2024-11-11.14:22:40,instance=i-08bb147e7134c32e0,host=ip-10-243-120-52,sub=main,version=2024.11.0.7644
31/10/2024
07:39:01,hours=25.89,threadBlktime=0,threads=436,run=70,block=93,wait=135,timed=130,locks=[org.apache.tapestry5.ioc.internal.util.ConcurrentBarrier$ThreadBoolean(31),java.io.RandomAccessFile(2),org.apache.logging.log4j.core.appender.rolling.RollingFileManager(1),java.lang.Object(45),org.apache.catalina.webresources.CachedResource(14)],heapuse=16444,heapmax=24849,gc=1,
2024-11-12T16:16:05.913Z {name=ip-10-243-120-52.ec2.internal} ERROR
[2024-11-12T16:15:56,585]
org.apache.catalina.webresources.AbstractSingleArchiveResourceSet.getArchiveEntries(AbstractSingleArchiveResourceSet.java:66)
2024-11-12T16:16:05.913Z {name=ip-10-243-120-52.ec2.internal}
org.apache.catalina.webresources.AbstractArchiveResourceSet.getResource(AbstractArchiveResourceSet.java:246)
2024-11-12T16:16:05.914Z {name=ip-10-243-120-52.ec2.internal}
org.apache.catalina.webresources.StandardRoot.getResourceInternal(StandardRoot.java:272)
2024-11-12T16:16:05.914Z {name=ip-10-243-120-52.ec2.internal}
org.apache.catalina.webresources.CachedResource.validateResource(CachedResource.java:127)
2024-11-12T16:16:05.914Z {name=ip-10-243-120-52.ec2.internal}
org.apache.catalina.webresources.Cache.getResource(Cache.java:78)
2024-11-12T16:16:05.914Z {name=ip-10-243-120-52.ec2.internal}
org.apache.catalina.webresources.StandardRoot.getResource(StandardRoot.java:211)
2024-11-12T16:16:05.914Z {name=ip-10-243-120-52.ec2.internal}
org.apache.catalina.webresources.StandardRoot.getClassLoaderResource(StandardRoot.java:220)
2024-11-12T16:16:05.914Z {name=ip-10-243-120-52.ec2.internal}
org.apache.catalina.loader.WebappClassLoaderBase.findResource(WebappClassLoaderBase.java:872)
2024-11-12T16:16:05.914Z {name=ip-10-243-120-52.ec2.internal}
org.apache.catalina.loader.WebappClassLoaderBase.getResource(WebappClassLoaderBase.java:981)
2024-11-12T16:16:05.914Z {name=ip-10-243-120-52.ec2.internal}
[email protected]/java.lang.Class.getResource(Class.java:2740)
07:39:01,hours=0.05,threadBlktime=0,threads=135,run=15,block=10,wait=84,timed=26,locks=[org.apache.tapestry5.internal.plastic.PlasticClassPool(3),java.util.concurrent.ConcurrentHashMap$ReservationNode(2),java.util.concurrent.ConcurrentHashMap$Node(1),org.apache.tapestry5.beanmodel.internal.services.PropertyAccessImpl(3),java.lang.Object(1)],heapuse=279,heapmax=24849,gc=1,
ERROR [2024-11-14T12:12:47,871]
org.apache.tapestry5.internal.plastic.PlasticClassLoader.loadClass(PlasticClassLoader.java:59)
[email protected]/java.lang.ClassLoader.loadClass(ClassLoader.java:522)
org.apache.tapestry5.internal.plastic.PlasticClassPool.createTransformation(PlasticClassPool.java:511)
org.apache.tapestry5.internal.plastic.PlasticClassPool.getPlasticClassTransformation(PlasticClassPool.java:492)
org.apache.tapestry5.internal.plastic.PlasticClassPool.loadAndTransformClass(PlasticClassPool.java:399)
org.apache.tapestry5.internal.plastic.PlasticClassLoader.loadClass(PlasticClassLoader.java:76)
[email protected]/java.lang.ClassLoader.loadClass(ClassLoader.java:522)
org.apache.tapestry5.internal.plastic.PlasticClassPool.getClassInstantiator(PlasticClassPool.java:667)
org.apache.tapestry5.plastic.PlasticManager.getClassInstantiator(PlasticManager.java:187)
org.apache.tapestry5.internal.services.ComponentInstantiatorSourceImpl$2.invoke(ComponentInstantiatorSourceImpl.java:436)
org.apache.tapestry5.internal.services.ComponentInstantiatorSourceImpl$2.invoke(ComponentInstantiatorSourceImpl.java:385)
org.apache.tapestry5.ioc.internal.OperationTrackerImpl.invoke(OperationTrackerImpl.java:82)
org.apache.tapestry5.ioc.internal.PerThreadOperationTracker.invoke(PerThreadOperationTracker.java:72)
org.apache.tapestry5.ioc.internal.RegistryImpl.invoke(RegistryImpl.java:1292)
org.apache.tapestry5.internal.services.ComponentInstantiatorSourceImpl.createInstantiatorForClass(ComponentInstantiatorSourceImpl.java:383)
org.apache.tapestry5.internal.services.ComponentInstantiatorSourceImpl$$Lambda$351/0x0000000800872040.apply(Unknown
Source)
[email protected]/java.util.concurrent.ConcurrentHashMap.computeIfAbsent(ConcurrentHashMap.java:1737)
Have I uncovered a genuine thread locking issue that I should raise a JIRA
ticket for?
Or does anyone have any ideas of something I can change to prevent this?
I realise I’m only providing a tiny snippet of our overall system, but any
suggestions would be welcome.
Thank you.
Scott
Confidentiality note: This e-mail may contain confidential information from
Clarivate. If you are not the intended recipient, be aware that any disclosure,
copying, distribution or use of the contents of this e-mail is strictly
prohibited. If you have received this e-mail in error, please delete this
e-mail and notify the sender as soon as possible.
