Indefinute wait on count down latch during createSessionFactory.

[whitingjr]

Hi,

I am testing running EAP7 with the Shenandoah jvm option. Which at the moment causes the jvm to not operate not quickly at the moment.

This slowdown is causing an installed application with does operate normally (without the Shenandoah flag) to cease processing requests.

A stack dump shows all but one of the threads processing jms requests to be blocked waiting on a lock. The one thread that has the lock is waiting on a count down latch. But this latch is never counted down.

Has this been seen before ?

1. "httpWorker task-10" #547 prio=5 os_prio=0 tid=0x00002acc1c044000
2. nid=0xf422 waiting on condition [0x00002ac9a7ffc000]
3.     java.lang.Thread.State: TIMED_WAITING (parking)
4.      at sun.misc.Unsafe.park(Native Method)
5.      - parking to wait for  <0x00002ac2d0f072d0> (a
6. java.util.concurrent.CountDownLatch$Sync)
7.      at
8. java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
9.      at
10. java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:1037)
11.      at
12. java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1328)
13.      at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:277)
14.      at
15. org.apache.activemq.artemis.core.client.impl.ClientSessionFactoryImpl.waitForTopology(ClientSessionFactoryImpl.java:453)
16.      at
17. org.apache.activemq.artemis.core.client.impl.ServerLocatorImpl.createSessionFactory(ServerLocatorImpl.java:790)
18.      at
19. org.apache.activemq.artemis.jms.client.ActiveMQConnectionFactory.createConnectionInternal(ActiveMQConnectionFactory.java:724)
20.      - locked <0x00002ac31e7b69b8> (a
21. org.apache.activemq.artemis.jms.client.ActiveMQXAConnectionFactory)
22.      at
23. org.apache.activemq.artemis.jms.client.ActiveMQConnectionFactory.createXAQueueConnection(ActiveMQConnectionFactory.java:333)
24.      at
25. org.apache.activemq.artemis.jms.client.ActiveMQConnectionFactory.createXAQueueConnection(ActiveMQConnectionFactory.java:329)
26.      at
27. org.apache.activemq.artemis.ra.ActiveMQRAManagedConnection.setup(ActiveMQRAManagedConnection.java:771)
28.      at
29. org.apache.activemq.artemis.ra.ActiveMQRAManagedConnection.<init>(ActiveMQRAManagedConnection.java:163)
30.      at
31. org.apache.activemq.artemis.ra.ActiveMQRAManagedConnectionFactory.createManagedConnection(ActiveMQRAManagedConnectionFactory.java:149)
32.      at
33. org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreConcurrentLinkedDequeManagedConnectionPool.createConnectionEventListener(SemaphoreConcurrentLinkedDequeManagedConnectionPool.java:1320)
34.      at
35. org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreConcurrentLinkedDequeManagedConnectionPool.getConnection(SemaphoreConcurrentLinkedDequeManagedConnectionPool.java:496)
36.      at
37. org.jboss.jca.core.connectionmanager.pool.AbstractPool.getTransactionNewConnection(AbstractPool.java:699)
38.      at
39. org.jboss.jca.core.connectionmanager.pool.AbstractPool.getConnection(AbstractPool.java:598)
40.      at
41. org.jboss.jca.core.connectionmanager.AbstractConnectionManager.getManagedConnection(AbstractConnectionManager.java:590)
42.      at
43. org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.getManagedConnection(TxConnectionManagerImpl.java:429)
44.      at
45. org.jboss.jca.core.connectionmanager.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:747)
46.      at
47. org.apache.activemq.artemis.ra.ActiveMQRASessionFactoryImpl.allocateConnection(ActiveMQRASessionFactoryImpl.java:853)
48.      - locked <0x00002ac2d342c260> (a java.util.HashSet)
49.      at
50. org.apache.activemq.artemis.ra.ActiveMQRASessionFactoryImpl.createQueueSession(ActiveMQRASessionFactoryImpl.java:296)
51.      at
52. org.spec.jent.ejb.orders.session.LargeOrderSenderSession.sendOrdersToManufacturing(LargeOrderSenderSession.java:50)
53.      at sun.reflect.GeneratedMethodAccessor450.invoke(Unknown Source)
54.      at
55. sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
56.      at java.lang.reflect.Method.invoke(Method.java:498)
57.      at
58. org.jboss.as.ee.component.ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptor.java:52)
59.      at
60. org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
61.      at
62. org.jboss.as.ejb3.component.invocationmetrics.ExecutionTimeInterceptor.processInvocation(ExecutionTimeInterceptor.java:43)
63.      at
64. org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
65.      at
66. org.jboss.as.jpa.interceptor.SBInvocationInterceptor.processInvocation(SBInvocationInterceptor.java:47)
67.      at
68. org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
69.      at
70. org.jboss.as.ee.concurrent.ConcurrentContextInterceptor.processInvocation(ConcurrentContextInterceptor.java:45)
71.      at
72. org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
73.      at
74. org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:21)
75.      at
76. org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
77.      at
78. org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)
79.      at
80. org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:52)
81.      at
82. org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
83.      at
84. org.jboss.as.ejb3.component.pool.PooledInstanceInterceptor.processInvocation(PooledInstanceInterceptor.java:51)
85.      at
86. org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
87.      at
88. org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInCallerTx(CMTTxInterceptor.java:254)
89.      at
90. org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:329)
91.      at
92. org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:239)
93.      at
94. org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
95.      at
96. org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41)
97.      at
98. org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
99.      at
100. org.jboss.as.ejb3.component.invocationmetrics.WaitTimeInterceptor.processInvocation(WaitTimeInterceptor.java:43)
101.      at
102. org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
103.      at
104. org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64)
105.      at
106. org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
107.      at
108. org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:66)
109.      at
110. org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
111.      at
112. org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50)
113.      at
114. org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
115.      at
116. org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:54)
117.      at
118. org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
119.      at
120. org.jboss.invocation.ContextClassLoaderInterceptor.processInvocation(ContextClassLoaderInterceptor.java:64)
121.      at
122. org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
123.      at
124. org.jboss.invocation.InterceptorContext.run(InterceptorContext.java:356)
125.      at
126. org.wildfly.security.manager.WildFlySecurityManager.doChecked(WildFlySecurityManager.java:636)
127.      at
128. org.jboss.invocation.AccessCheckingInterceptor.processInvocation(AccessCheckingInterceptor.java:61)
129.      at
130. org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
131.      at
132. org.jboss.invocation.InterceptorContext.run(InterceptorContext.java:356)
133.      at
134. org.jboss.invocation.PrivilegedWithCombinerInterceptor.processInvocation(PrivilegedWithCombinerInterceptor.java:80)
135.      at
136. org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
137.      at
138. org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)
139.      at
140. org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:195)
141.      at
142. org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:185)
143.      at
144. org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
145.      at
146. org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)
147.      at
148. org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:73)
149.      at
150. org.spec.jent.ejb.orders.session.LargeOrderSenderSessionLocal$$$view11.sendOrdersToManufacturing(Unknown
151. Source)
152.      at
153. org.spec.jent.ejb.orders.session.OrderSession.newOrder(OrderSession.java:165)
154.      at sun.reflect.GeneratedMethodAccessor219.invoke(Unknown Source)
155.      at
156. sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
157.      at java.lang.reflect.Method.invoke(Method.java:498)
158.      at
159. org.jboss.as.ee.component.ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptor.java:52)
160.      at
161. org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
162.      at
163. org.jboss.as.ejb3.component.invocationmetrics.ExecutionTimeInterceptor.processInvocation(ExecutionTimeInterceptor.java:43)
164.      at
165. org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
166.      at
167. org.jboss.as.jpa.interceptor.SBInvocationInterceptor.processInvocation(SBInvocationInterceptor.java:47)
168.      at
169. org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
170.      at
171. org.jboss.as.ee.concurrent.ConcurrentContextInterceptor.processInvocation(ConcurrentContextInterceptor.java:45)
172.      at
173. org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
174.      at
175. org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:21)
176.      at
177. org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
178.      at
179. org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)
180.      at
181. org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:52)
182.      at
183. org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
184.      at
185. org.jboss.as.ejb3.component.pool.PooledInstanceInterceptor.processInvocation(PooledInstanceInterceptor.java:51)
186.      at
187. org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
188.      at
189. org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:275)
190.      at
191. org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:327)
192.      at
193. org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:239)
194.      at
195. org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
196.      at
197. org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41)
198.      at
199. org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
200.      at
201. org.jboss.as.ejb3.component.invocationmetrics.WaitTimeInterceptor.processInvocation(WaitTimeInterceptor.java:43)
202.      at
203. org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
204.      at
205. org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64)
206.      at
207. org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
208.      at
209. org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:66)
210.      at
211. org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
212.      at
213. org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50)
214.      at
215. org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
216.      at
217. org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:54)
218.      at
219. org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
220.      at
221. org.jboss.invocation.ContextClassLoaderInterceptor.processInvocation(ContextClassLoaderInterceptor.java:64)
222.      at
223. org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
224.      at
225. org.jboss.invocation.InterceptorContext.run(InterceptorContext.java:356)
226.      at
227. org.wildfly.security.manager.WildFlySecurityManager.doChecked(WildFlySecurityManager.java:636)
228.      at
229. org.jboss.invocation.AccessCheckingInterceptor.processInvocation(AccessCheckingInterceptor.java:61)
230.      at
231. org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
232.      at
233. org.jboss.invocation.InterceptorContext.run(InterceptorContext.java:356)
234.      at
235. org.jboss.invocation.PrivilegedWithCombinerInterceptor.processInvocation(PrivilegedWithCombinerInterceptor.java:80)
236.      at
237. org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
238.      at
239. org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)
240.      at
241. org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:195)
242.      at
243. org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:185)
244.      at
245. org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)
246.      at
247. org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)
248.      at
249. org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:73)
250.      at
251. org.spec.jent.ejb.orders.session.OrderSessionLocal$$$view3.newOrder(Unknown
252. Source)
253.      at
254. org.spec.jent.servlet.helper.SpecAction.doPurchase(SpecAction.java:340)
255.      at
256. org.spec.jent.servlet.helper.SpecServletAction.doPurchase(SpecServletAction.java:502)
257.      at
258. org.spec.jent.servlet.SpecAppServlet.performTask(SpecAppServlet.java:199)
259.      at org.spec.jent.servlet.SpecAppServlet.doGet(SpecAppServlet.java:78)
260.      at javax.servlet.http.HttpServlet.service(HttpServlet.java:687)
261.      at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
262.      at
263. io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:85)
264.      at
265. io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62)
266.      at
267. io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36)
268.      at
269. io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:131)
270.      at
271. io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:57)
272.      at
273. io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
274.      at
275. io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:46)
276.      at
277. io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:64)
278.      at
279. io.undertow.security.handlers.AuthenticationMechanismsHandler.handleRequest(AuthenticationMechanismsHandler.java:60)
280.      at
281. io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:77)
282.      at
283. io.undertow.security.handlers.AbstractSecurityContextAssociationHandler.handleRequest(AbstractSecurityContextAssociationHandler.java:43)
284.      at
285. io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
286.      at
287. io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
288.      at
289. io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:285)
290.      at
291. io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:264)
292.      at
293. io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81)
294.      at
295. io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:175)
296.      at
297. io.undertow.server.Connectors.executeRootHandler(Connectors.java:202)
298.      at
299. io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:792)
300.      at
301. java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
302.      at
303. java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
304.      at java.lang.Thread.run(Thread.java:745)

Regards,

Jeremy

[whitingjr]

These were the options passed to the JVM for EAP7 in standalone mode.

-Xmx20g -Xmx20g -Xss256m -XX:-UseCompressedOops -XX:+UseShenandoahGC -XX:+PrintGCDetails

To investigate this further I added some useful logging messages. At the point where the topology update messages are dispatched and received.

Initially when the server starts up the count of dispatched and received match.

Then load is pushed at the server. Using a benchmark.

After 12 seconds the ability of the server to process messages collapses.

Doing a subsequent count of the dispatched at 118 and received 116. A discrepancy of 2.

This indicates messages dispatched on the channel are being lost.

I'll continue investigating where the packets go missing.