So while working on reproducing tomcat webapp hang as earlier discussed, a
different tomcat serving up a single webapp on same box also stopped
responding, jvm for this tomcat is still running but when trying to reach it
via browser I get error page of unable to connect.
Thread dumps for both problem tomcats seem to exhibit same core problem, at
least in my analysis. I would really appreciate your feedback on my
analysis of the situation and things anyone thinks I may be over looking.
On both tomcat jvms when they get to the point of locking up, thread dumps
show that almost all ajp/exec threads are blocked and there are either one
or two ajp/exec threads runnable. The blocked threads are waiting for locks
on an object held by one of the threads in runnable state. The commonality
between the two that really has to be the root of the problem, in my
estimation, is that on both tomcats the runnable threads are sitting on
socketRead0 to our database and not budging, just stuck in runnable and
never getting to the point of releasing their locks... Potential networking
issue with that socket read? Take a look at the thread dump below, I've
shortened a lot of the stacktraces - Thanks for any thoughts on the matter
AJP Threads 3, 5, 7,12
java.lang.Thread.State: BLOCKED (on object monitor)
at
com.acompany.view.backing.cact.product.ProductsView.setCustomerData(ProductsView.java:57)
- waiting to lock <0x00002aaad303cad0> (a
com.acompany.model.customer.CustomerData)
at
com.acompany.view.backing.cact.product.Products.<init>(Products.java:101)
AJP Threads 9,10,11
java.lang.Thread.State: BLOCKED (on object monitor)
at
com.acompany.view.backing.cact.membership.MembershipsView.setCustomerData(MembershipsView.java:58)
- waiting to lock <0x00002aaad303cad0> (a
com.acompany.model.customer.CustomerData)
at
com.acompany.view.backing.cact.membership.Memberships.<init>(Memberships.java:99)
AJP Threads 4, 6, 8
java.lang.Thread.State: BLOCKED (on object monitor)
at
com.acompany.view.backing.cact.meeting.MeetingsView.setCustomerData(MeetingsView.java:66)
- waiting to lock <0x00002aaad303cad0> (a
com.acompany.model.customer.CustomerData)
at
com.acompany.view.backing.cact.meeting.Meetings.<init>(Meetings.java:135)
AJP threads 13, 14, 15, 16 - WAITING on object monitor - probably what
they're supposed to be doing
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00002aaad34cdbd8> (a
org.apache.tomcat.util.net.AprEndpoint$Worker)
at java.lang.Object.wait(Object.java:485)
at
org.apache.tomcat.util.net.AprEndpoint$Worker.await(AprEndpoint.java:1540)
- locked <0x00002aaad34cdbd8> (a
org.apache.tomcat.util.net.AprEndpoint$Worker)
at
org.apache.tomcat.util.net.AprEndpoint$Worker.run(AprEndpoint.java:1565)
at java.lang.Thread.run(Thread.java:619)
AJP thread 2 - RUNNABLE - sitting on socketRead0
"ajp-9011-2" daemon prio=10 tid=0x000000005e342800 nid=0x3f0a runnable
[0x0000000040f07000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at oracle.net.ns.Packet.receive(Packet.java:293)
at oracle.net.ns.DataPacket.receive(DataPacket.java:92)
at oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:174)
at oracle.net.ns.NetInputStream.read(NetInputStream.java:119)
at oracle.net.ns.NetInputStream.read(NetInputStream.java:94)
at oracle.net.ns.NetInputStream.read(NetInputStream.java:79)
at
oracle.jdbc.driver.T4CSocketInputStreamWrapper.readNextPacket(T4CSocketInputStreamWrapper.java:112)
at
oracle.jdbc.driver.T4CSocketInputStreamWrapper.read(T4CSocketInputStreamWrapper.java:73)
at oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1040)
at oracle.jdbc.driver.T4CMAREngine.unmarshalSB1(T4CMAREngine.java:1016)
at oracle.jdbc.driver.T4C8Oall.receive(T4C8Oall.java:588)
at
oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:194)
at
oracle.jdbc.driver.T4CPreparedStatement.executeForDescribe(T4CPreparedStatement.java:791)
at
oracle.jdbc.driver.T4CPreparedStatement.executeMaybeDescribe(T4CPreparedStatement.java:866)
at
oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1187)
at
oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3386)
at
oracle.jdbc.driver.OraclePreparedStatement.executeQuery(OraclePreparedStatement.java:3430)
- locked <0x00002aaacf0584b0> (a oracle.jdbc.driver.T4CConnection)
at
oracle.jdbc.driver.OraclePreparedStatementWrapper.executeQuery(OraclePreparedStatementWrapper.java:1491)
at
org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:92)
at
org.hibernate.jdbc.AbstractBatcher.getResultSet(AbstractBatcher.java:120)
at org.hibernate.loader.Loader.getResultSet(Loader.java:1272)
at org.hibernate.loader.Loader.doQuery(Loader.java:391)
at
org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:218)
at org.hibernate.loader.Loader.loadEntity(Loader.java:1345)
at org.hibernate.loader.entity.EntityLoader.load(EntityLoader.java:116)
at org.hibernate.loader.entity.EntityLoader.load(EntityLoader.java:101)
My thoughts are this is the thread causing all the backup
AJP Thread 1 RUNNABLE, sitting on socketRead0, Has locked
<0x00002aaad303cad0> (a com.acompany.model.customer.CustomerData) which
almost all other threads are blocked waiting for lock on
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at oracle.net.ns.Packet.receive(Packet.java:293)
at oracle.net.ns.DataPacket.receive(DataPacket.java:92)
at oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:174)
at oracle.net.ns.NetInputStream.read(NetInputStream.java:119)
at oracle.net.ns.NetInputStream.read(NetInputStream.java:94)
at oracle.net.ns.NetInputStream.read(NetInputStream.java:79)
at
oracle.jdbc.driver.T4CSocketInputStreamWrapper.readNextPacket(T4CSocketInputStreamWrapper.java:112)
at
oracle.jdbc.driver.T4CSocketInputStreamWrapper.read(T4CSocketInputStreamWrapper.java:73)
at oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1040)
at oracle.jdbc.driver.T4CMAREngine.unmarshalSB1(T4CMAREngine.java:1016)
at oracle.jdbc.driver.T4C8Oall.receive(T4C8Oall.java:588)
at
oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:194)
at
oracle.jdbc.driver.T4CPreparedStatement.executeForDescribe(T4CPreparedStatement.java:791)
at
oracle.jdbc.driver.T4CPreparedStatement.executeMaybeDescribe(T4CPreparedStatement.java:866)
at
oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1187)
at
oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3386)
at
oracle.jdbc.driver.OraclePreparedStatement.executeQuery(OraclePreparedStatement.java:3430)
- locked <0x00002aaad0bbd688> (a oracle.jdbc.driver.T4CConnection)
at
oracle.jdbc.driver.OraclePreparedStatementWrapper.executeQuery(OraclePreparedStatementWrapper.java:1491)
at
org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:92)
at
org.hibernate.jdbc.AbstractBatcher.getResultSet(AbstractBatcher.java:120)
at org.hibernate.loader.Loader.getResultSet(Loader.java:1272)
at org.hibernate.loader.Loader.doQuery(Loader.java:391)
at
org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:218)
at org.hibernate.loader.Loader.loadCollection(Loader.java:1434)
at
org.hibernate.loader.collection.OneToManyLoader.initialize(OneToManyLoader.java:111)
at
org.hibernate.persister.collection.AbstractCollectionPersister.initialize(AbstractCollectionPersister.java:488)
at
org.hibernate.event.def.DefaultInitializeCollectionEventListener.onInitializeCollection(DefaultInitializeCollectionEventListener.java:60)
at
org.hibernate.impl.SessionImpl.initializeCollection(SessionImpl.java:1430)
at
org.hibernate.collection.AbstractPersistentCollection.forceInitialization(AbstractPersistentCollection.java:280)
at
org.hibernate.engine.PersistenceContext.initializeNonLazyCollections(PersistenceContext.java:796)
at
org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:223)
at org.hibernate.loader.Loader.doList(Loader.java:1593)
at org.hibernate.loader.Loader.list(Loader.java:1577)
at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:395)
at
org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:271)
at org.hibernate.impl.SessionImpl.list(SessionImpl.java:844)
at org.hibernate.impl.QueryImpl.list(QueryImpl.java:74)
at
org.springframework.orm.hibernate3.HibernateTemplate$32.doInHibernate(HibernateTemplate.java:815)
at
org.springframework.orm.hibernate3.HibernateTemplate.execute(HibernateTemplate.java:312)
at
org.springframework.orm.hibernate3.HibernateTemplate.findByNamedQuery(HibernateTemplate.java:806)
at
com.acompany.model.dao.hibernateimpl.OrderDAOImpl.loadOrders(OrderDAOImpl.java:46)
at
com.acompany.model.service.impl.OrderServiceImpl.loadOrders(OrderServiceImpl.java:63)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:288)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:155)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:122)
at
org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:57)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:144)
at
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:174)
at $Proxy33.loadOrders(Unknown Source)
at
com.acompany.model.customer.CustomerOrderData.load(CustomerOrderData.java:254)
at
com.acompany.model.customer.CustomerOrderData.getCurrentOrders(CustomerOrderData.java:153)
at
com.acompany.model.customer.CustomerOrderData.getCurrentOrderSize(CustomerOrderData.java:131)
at
com.acompany.view.backing.cact.product.ProductsView.buildNodeLists(ProductsView.java:411)
at
com.acompany.view.backing.cact.product.ProductsView.refreshOrders(ProductsView.java:150)
at
com.acompany.view.backing.cact.product.ProductsView.setCustomerData(ProductsView.java:68)
- locked <0x00002aaad303cad0> (a
com.acompany.model.customer.CustomerData)
at
com.acompany.view.backing.cact.product.Products.<init>(Products.java:101)
at sun.reflect.GeneratedConstructorAccessor180.newInstance(Unknown
Source)
at
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
at java.lang.Class.newInstance0(Class.java:355)
at java.lang.Class.newInstance(Class.java:308)
at java.beans.Beans.instantiate(Beans.java:204)
at java.beans.Beans.instantiate(Beans.java:48)
at
com.sun.faces.config.ManagedBeanFactory.newInstance(ManagedBeanFactory.java:223)
"ajp-9011-Acceptor-0" daemon prio=10 tid=0x00002aab344bb800 nid=0x3efb
runnable [0x0000000042c32000]
java.lang.Thread.State: RUNNABLE
at org.apache.tomcat.jni.Socket.accept(Native Method)
at
org.apache.tomcat.util.net.AprEndpoint$Acceptor.run(AprEndpoint.java:1169)
at java.lang.Thread.run(Thread.java:619)
"ajp-9011-CometPoller-0" daemon prio=10 tid=0x00002aab34ae4000 nid=0x3efa in
Object.wait() [0x0000000042b31000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00002aaad0f5d530> (a
org.apache.tomcat.util.net.AprEndpoint$Poller)
at java.lang.Object.wait(Object.java:485)
at
org.apache.tomcat.util.net.AprEndpoint$Poller.run(AprEndpoint.java:1336)
- locked <0x00002aaad0f5d530> (a
org.apache.tomcat.util.net.AprEndpoint$Poller)
at java.lang.Thread.run(Thread.java:619)
"ajp-9011-Poller-0" daemon prio=10 tid=0x00002aab3426d000 nid=0x3ef9
runnable [0x0000000042a30000]
java.lang.Thread.State: RUNNABLE
at org.apache.tomcat.jni.Poll.poll(Native Method)
at
org.apache.tomcat.util.net.AprEndpoint$Poller.run(AprEndpoint.java:1373)
at java.lang.Thread.run(Thread.java:619)
"http-8082-Acceptor-0" daemon prio=10 tid=0x00002aab3432a000 nid=0x3ef8
runnable [0x000000004292f000]
java.lang.Thread.State: RUNNABLE
at org.apache.tomcat.jni.Socket.accept(Native Method)
at
org.apache.tomcat.util.net.AprEndpoint$Acceptor.run(AprEndpoint.java:1169)
at java.lang.Thread.run(Thread.java:619)
"http-8082-Sendfile-0" daemon prio=10 tid=0x00002aab343e3800 nid=0x3ef7 in
Object.wait() [0x000000004282e000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00002aaad0f5dc58> (a
org.apache.tomcat.util.net.AprEndpoint$Sendfile)
at java.lang.Object.wait(Object.java:485)
at
org.apache.tomcat.util.net.AprEndpoint$Sendfile.run(AprEndpoint.java:1805)
- locked <0x00002aaad0f5dc58> (a
org.apache.tomcat.util.net.AprEndpoint$Sendfile)
at java.lang.Thread.run(Thread.java:619)
"http-8082-CometPoller-0" daemon prio=10 tid=0x00002aab3450f800 nid=0x3ef6
in Object.wait() [0x000000004272d000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00002aaad0f5dfb8> (a
org.apache.tomcat.util.net.AprEndpoint$Poller)
at java.lang.Object.wait(Object.java:485)
at
org.apache.tomcat.util.net.AprEndpoint$Poller.run(AprEndpoint.java:1336)
- locked <0x00002aaad0f5dfb8> (a
org.apache.tomcat.util.net.AprEndpoint$Poller)
at java.lang.Thread.run(Thread.java:619)
"http-8082-Poller-0" daemon prio=10 tid=0x00002aab3448e800 nid=0x3ef5 in
Object.wait() [0x000000004262c000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00002aaad0f5e250> (a
org.apache.tomcat.util.net.AprEndpoint$Poller)
at java.lang.Object.wait(Object.java:485)
at
org.apache.tomcat.util.net.AprEndpoint$Poller.run(AprEndpoint.java:1336)
- locked <0x00002aaad0f5e250> (a
org.apache.tomcat.util.net.AprEndpoint$Poller)
at java.lang.Thread.run(Thread.java:619)
"ContainerBackgroundProcessor[StandardEngine[Catalina]]" daemon prio=10
tid=0x00002aab34b11000 nid=0x3ef4 waiting on condition [0x000000004252b000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at
org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1579)
at java.lang.Thread.run(Thread.java:619)
"GC Daemon" daemon prio=10 tid=0x00002aab340fa800 nid=0x3ee2 in
Object.wait() [0x000000004119b000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00002aaace2253a0> (a sun.misc.GC$LatencyLock)
at sun.misc.GC$Daemon.run(GC.java:100)
- locked <0x00002aaace2253a0> (a sun.misc.GC$LatencyLock)
"Low Memory Detector" daemon prio=10 tid=0x000000005d1d4800 nid=0x3ee0
runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"CompilerThread1" daemon prio=10 tid=0x000000005d1d2800 nid=0x3edf waiting
on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"CompilerThread0" daemon prio=10 tid=0x000000005d1cc800 nid=0x3ede waiting
on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Signal Dispatcher" daemon prio=10 tid=0x000000005d1ca800 nid=0x3edd waiting
on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Finalizer" daemon prio=10 tid=0x000000005d1a6000 nid=0x3edc in
Object.wait() [0x000000004242a000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00002aaace2256f8> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
- locked <0x00002aaace2256f8> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)
"Reference Handler" daemon prio=10 tid=0x000000005d1a4000 nid=0x3edb in
Object.wait() [0x0000000042329000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00002aaace225390> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:485)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
- locked <0x00002aaace225390> (a java.lang.ref.Reference$Lock)
"main" prio=10 tid=0x000000005d142800 nid=0x3ed5 runnable
[0x0000000041e23000]
java.lang.Thread.State: RUNNABLE
at java.net.PlainSocketImpl.socketAccept(Native Method)
at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:390)
- locked <0x00002aaad08d9170> (a java.net.SocksSocketImpl)
at java.net.ServerSocket.implAccept(ServerSocket.java:453)
at java.net.ServerSocket.accept(ServerSocket.java:421)
at
org.apache.catalina.core.StandardServer.await(StandardServer.java:389)
at org.apache.catalina.startup.Catalina.await(Catalina.java:662)
at org.apache.catalina.startup.Catalina.start(Catalina.java:614)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:289)
at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:414)
"VM Thread" prio=10 tid=0x000000005d19f800 nid=0x3eda runnable
"GC task thread#0 (ParallelGC)" prio=10 tid=0x000000005d155800 nid=0x3ed6
runnable
"GC task thread#1 (ParallelGC)" prio=10 tid=0x000000005d157800 nid=0x3ed7
runnable
"GC task thread#2 (ParallelGC)" prio=10 tid=0x000000005d159000 nid=0x3ed8
runnable
"GC task thread#3 (ParallelGC)" prio=10 tid=0x000000005d15b000 nid=0x3ed9
runnable
"VM Periodic Task Thread" prio=10 tid=0x000000005d1d7000 nid=0x3ee1 waiting
on condition
JNI global references: 2132
Heap
PSYoungGen total 248832K, used 12080K [0x00002aab1e210000,
0x00002aab2e210000, 0x00002aab2e210000)
eden space 234560K, 5% used
[0x00002aab1e210000,0x00002aab1eddc240,0x00002aab2c720000)
from space 14272K, 0% used
[0x00002aab2d420000,0x00002aab2d420000,0x00002aab2e210000)
to space 13312K, 0% used
[0x00002aab2c720000,0x00002aab2c720000,0x00002aab2d420000)
PSOldGen total 1310720K, used 93616K [0x00002aaace210000,
0x00002aab1e210000, 0x00002aab1e210000)
object space 1310720K, 7% used
[0x00002aaace210000,0x00002aaad3d7c178,0x00002aab1e210000)
PSPermGen total 524288K, used 109830K [0x00002aaaae210000,
0x00002aaace210000, 0x00002aaace210000)
object space 524288K, 20% used
[0x00002aaaae210000,0x00002aaab4d51a20,0x00002aaace210000)
Jason
