Hi All,
I just realised I'd previously posted this into the DEV group when I should
have posted it in the USER group.
Reposting in the correct mailing list - Sorry about that...
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]
java.base@11.0.16/java.util.zip.ZipFile.getEntry(ZipFile.java:347)<mailto:java.base@11.0.16/java.util.zip.ZipFile.getEntry(ZipFile.java:347)>
2024-11-12T15:26:20.925Z {name=ip-10-242-182-176.ec2.internal}
java.base@11.0.16/java.util.zip.ZipFile$1.getEntry(ZipFile.java:1143)<mailto:java.base@11.0.16/java.util.zip.ZipFile$1.getEntry(ZipFile.java:1143)>
2024-11-12T15:26:20.925Z {name=ip-10-242-182-176.ec2.internal}
java.base@11.0.16/java.util.jar.JarFile.getEntry0(JarFile.java:586)<mailto:java.base@11.0.16/java.util.jar.JarFile.getEntry0(JarFile.java:586)>
2024-11-12T15:26:20.925Z {name=ip-10-242-182-176.ec2.internal}
java.base@11.0.16/java.util.jar.JarFile.getEntry(JarFile.java:516)<mailto:java.base@11.0.16/java.util.jar.JarFile.getEntry(JarFile.java:516)>
2024-11-12T15:26:20.926Z {name=ip-10-242-182-176.ec2.internal}
java.base@11.0.16/java.util.jar.JarFile.getJarEntry(JarFile.java:478)<mailto:java.base@11.0.16/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}
java.base@11.0.16/java.lang.Class.getResource(Class.java:2740)<mailto:java.base@11.0.16/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)
java.base@11.0.16/java.lang.ClassLoader.loadClass(ClassLoader.java:522)<mailto:java.base@11.0.16/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)
java.base@11.0.16/java.lang.ClassLoader.loadClass(ClassLoader.java:522)<mailto:java.base@11.0.16/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)
java.base@11.0.16/java.util.concurrent.ConcurrentHashMap.computeIfAbsent(ConcurrentHashMap.java:1737)<mailto:java.base@11.0.16/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.
