jakarta-ee - WildFly - HornetQ 连接超时和性能问题

Question

在 WildFly 8.2.1-Final 大容量安装中，我们在大约一周内遇到性能下降，直到需要重新启动为止，并且由于事务处于 ABORT_ONLY 状态而越来越频繁地发生发送 JMS 消息的失败:

Caused by: javax.ejb.EJBException: javax.jms.JMSException: Could not create a session: IJ000457: Unchecked throwable in managedConnectionReconnected()
Caused by: javax.resource.ResourceException: IJ000457: Unchecked throwable in managedConnectionReconnected() cl=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@3915e409[state=NORMAL managed connection=org.hornetq.ra.HornetQRAManagedConnection@7d6bcd06 connection handles=0 lastUse=1494579251303 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.PoolByCri@691085ec mcp=SemaphoreArrayListManagedConnectionPool@66a127f5[pool=HornetQConnectionDefinition] xaResource=XAResourceWrapperImpl@56a9bb4[xaResource=org.hornetq.ra.HornetQRAXAResource@4ca920eb pad=false overrideRmValue=null productName=HornetQ productVersion=2.0 jndiName=java:/JmsXA] txSync=null]
        at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.reconnectManagedConnection(AbstractConnectionManager.java:780)
        at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:518)
        at org.hornetq.ra.HornetQRASessionFactoryImpl.allocateConnection(HornetQRASessionFactoryImpl.java:948)
        ... 261 more
Caused by: javax.resource.ResourceException: IJ000461: Could not enlist in transaction on entering meta-aware object
        at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.managedConnectionReconnected(TxConnectionManagerImpl.java:551)
        at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.reconnectManagedConnection(AbstractConnectionManager.java:775)
        ... 263 more
Caused by: javax.transaction.SystemException: IJ000356: Failed to enlist: java.lang.Throwable: Unabled to enlist resource, see the previous warnings. tx=TransactionImple < ac, BasicAction: 0:ffff0a0001c3:682851c6:5900737b:dd09939 status: ActionStatus.ABORT_ONLY >
        at org.jboss.jca.core.connectionmanager.listener.TxConnectionListener$TransactionSynchronization.checkEnlisted(TxConnectionListener.java:848)
        at org.jboss.jca.core.connectionmanager.listener.TxConnectionListener.enlist(TxConnectionListener.java:383)
        at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.managedConnectionReconnected(TxConnectionManagerImpl.java:544)
        ... 264 more

事务处于 ABORT_ONLY 状态的原因是之前记录的警告:

2017-05-30 11:33:15,977 WARN  [com.arjuna.ats.jta] (Thread-123) ARJUNA016086: TransactionImple.enlistResource setTransactionTimeout on XAResource < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff0a0001c3:-7a698606:591fe1ff:82cea51, node_name=1, branch_uid=0:ffff0a0001c3:-7a698606:591fe1ff:830e516, subordinatenodename=null, eis_name=java:/JmsXA > threw: XAException.XAER_RMERR: javax.transaction.xa.XAException
Caused by: HornetQConnectionTimedOutException[errorType=CONNECTION_TIMEDOUT message=HQ119014: Timed out waiting for response when sending packet 51]
       at org.hornetq.core.protocol.core.impl.ChannelImpl.sendBlocking(ChannelImpl.java:390)
       at org.hornetq.core.client.impl.ClientSessionImpl.start(ClientSessionImpl.java:1901)

一些细节:

• 超时的两种数据包类型是 51 (SESS_XA_START) 和 63 (SESS_XA_SET_TIMEOUT)
• 事务中唯一的其他参与者是 Oracle XA 连接
• 有 0 个队列和 1 个(持久)主题正在使用消息(消息计数等于或略高于 0)

消息是从单例EJB发送的，相关业务方法用@Lock(LockType.READ)注释，因此可以并发调用。EJB 注入(inject) java:/JmsXA TopicConnectionFactory 和 Topic 并创建一个新的 TopicConnection、Session 和 MessageProducer 在每次调用该方法(发送每条消息)时都会执行此操作，并注意在 finally {} block 中关闭所有这些内容。

由于发送数据包 51 (SESS_XA_START) 和 63 (SESS_XA_SET_TIMEOUT) 发生超时，因此启动 session 似乎很慢或挂起。

知道原因是什么吗？

Answer 1

由于我们可以看到，在数千个错误中，只涉及几个不同的连接，因此我们怀疑连接以某种方式断开并保留在池中，因此这些断开的连接被重用，从而导致连续的错误。

在此发布#5 similar issue说:

The connections from the JmsXA connection factory do indeed come from a pool. However, each of those connections has a listener attached to it so that when a connection-level error occurs it should be kicked out of the pool automatically by the JCA implementation. The strangest thing about your issue is that everything is local so there shouldn't be any broken connections or any connectivity problems of any sort.

为了确保从池中删除这些断开的连接，我们在 AbstractConnectionManager#reconnectManagedConnection(ConnectionListener) 的第 799 行插入了对 cl.getManagedConnection().destroy() 的调用code> 从ironjacamar-core-impl 1.1.9开始，替换了JAR并让系统运行了几周。

到目前为止运行稳定，没有变慢甚至挂起。

添加到同一方法中的一些日志记录了池统计信息，我们可以看到在此期间有 100 个连接被破坏，但更重要的是，在每个初始错误中都涉及一个单独的连接，因此这些损坏的连接不会被重用更多。

导致连接中断的初始错误仍不清楚。从日志记录来看，同一个 JMS 连接似乎同时被两个线程使用，从而扰乱了通信，导致超时并最终使连接处于损坏状态。

另一种猜测是，这是 Ironjacamar 1.1.9 中的问题，很久以前就已修复，并且在 WildFly 的后续版本中不会出现。