Spring jms 4.3.8 vs 4.0.2 与 activemq 5.13.0 问题答案

【问题标题】：Spring jms 4.3.8 vs 4.0.2 with activemq 5.13.0 issueSpring jms 4.3.8 vs 4.0.2 与 activemq 5.13.0 问题
【发布时间】：2017-11-26 03:47:22
【问题描述】：

在我们尝试将 spring-jms-4.0.2 升级到 4.3.8 并且 activemq 停留在 5.13.0 之后，我们遇到了一个奇怪的问题。

我们看到的是 spring-jms 或 activemq 端的连续循环，并且在我们在 Tomcat 中启动应用程序后，CPU 始终保持在 20-40 左右的范围内。

如果我们回去，只需将 lib 中的 spring-jms 4.3.8 替换为 4.0.2 版本，启动后一切正常。

并发消费者为 2，spring 中“DefaultMessageListenerContainer”的缓存级别设置为 3。

这里有几个指标：

我们为 springframework 和 activemq 启用了调试日志记录，我们在 spring 日志中看到的只有 3 行，与 spring jms jar 版本无关。

2017-06-22T12:09:02,928 DEBUG [org.springframework.jms.listener.DefaultMessageListenerContainer] Established shared JMS Connection
2017-06-22T12:09:02,930 DEBUG [org.springframework.jms.listener.DefaultMessageListenerContainer] Resumed paused task: org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker@bd71008
2017-06-22T12:09:02,930 DEBUG [org.springframework.jms.listener.DefaultMessageListenerContainer] Resumed paused task: org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker@7814de81

但是这里是activemq日志的区别

当我们使用 spring-jms-4.0.2 时

2017-06-22 12:00:46,921 | DEBUG | Received WireFormat: WireFormatInfo { version=11, properties={TcpNoDelayEnabled=true, SizePrefixDisabled=false, CacheSize=1024, StackTraceEnabled=true, CacheEnabled=true, TightEncodingEnabled=true, MaxFrameSize=9223372036854775807, MaxInactivityDuration=30000, MaxInactivityDurationInitalDelay=30000}, magic=[A,c,t,i,v,e,M,Q]} | org.apache.activemq.transport.WireFormatNegotiator | ActiveMQ Transport: tcp:///127.0.0.1:49504@61616
2017-06-22 12:00:46,922 | DEBUG | tcp:///127.0.0.1:49504@61616 before negotiation: OpenWireFormat{version=11, cacheEnabled=false, stackTraceEnabled=false, tightEncodingEnabled=false, sizePrefixDisabled=false, maxFrameSize=9223372036854775807} | org.apache.activemq.transport.WireFormatNegotiator | ActiveMQ Transport: tcp:///127.0.0.1:49504@61616
2017-06-22 12:00:46,922 | DEBUG | tcp:///127.0.0.1:49504@61616 after negotiation: OpenWireFormat{version=11, cacheEnabled=true, stackTraceEnabled=true, tightEncodingEnabled=true, sizePrefixDisabled=false, maxFrameSize=9223372036854775807} | org.apache.activemq.transport.WireFormatNegotiator | ActiveMQ Transport: tcp:///127.0.0.1:49504@61616
2017-06-22 12:00:46,927 | DEBUG | Setting up new connection id: ID:39235aa-49503-1498147246722-1:1, address: tcp://127.0.0.1:49504, info: ConnectionInfo {commandId = 1, responseRequired = true, connectionId = ID:39235aa-49503-1498147246722-1:1, clientId = ID:39235aa-49503-1498147246722-0:1, clientIp = null, userName = null, password = *****, brokerPath = null, brokerMasterConnector = false, manageable = true, clientMaster = true, faultTolerant = true, failoverReconnect = false} | org.apache.activemq.broker.TransportConnection | ActiveMQ Transport: tcp:///127.0.0.1:49504@61616
2017-06-22 12:00:46,935 | DEBUG | Tomcat01.CE01 adding consumer: ID:39235aa-49503-1498147246722-1:1:-1:1 for destination: ActiveMQ.Advisory.TempQueue,ActiveMQ.Advisory.TempTopic | org.apache.activemq.broker.region.AbstractRegion | ActiveMQ Transport: tcp:///127.0.0.1:49504@61616
2017-06-22 12:00:46,973 | DEBUG | Tomcat01.CE01 adding consumer: ID:39235aa-49503-1498147246722-1:1:2:1 for destination: queue://company.CD.Tomcat01.Repo.Request | org.apache.activemq.broker.region.AbstractRegion | ActiveMQ Transport: tcp:///127.0.0.1:49504@61616
2017-06-22 12:00:46,976 | DEBUG | queue://company.CD.Tomcat01.Repo.Request add sub: QueueSubscription: consumer=ID:39235aa-49503-1498147246722-1:1:2:1, destinations=0, dispatched=0, delivered=0, pending=0, dequeues: 0, dispatched: 0, inflight: 0 | org.apache.activemq.broker.region.Queue | ActiveMQ Transport: tcp:///127.0.0.1:49504@61616
2017-06-22 12:00:46,976 | DEBUG | queue://company.CD.Tomcat01.Repo.Request, subscriptions=1, memory=0%, size=0, pending=0 toPageIn: 0, Inflight: 0, pagedInMessages.size 0, pagedInPendingDispatch.size 0, enqueueCount: 0, dequeueCount: 0, memUsage:0 | org.apache.activemq.broker.region.Queue | Queue:company.CD.Tomcat01.Repo.Request
2017-06-22 12:00:46,976 | DEBUG | Tomcat01.CE01 adding consumer: ID:39235aa-49503-1498147246722-1:1:1:1 for destination: queue://company.CD.Tomcat01.Repo.Request | org.apache.activemq.broker.region.AbstractRegion | ActiveMQ Transport: tcp:///127.0.0.1:49504@61616
2017-06-22 12:00:46,977 | DEBUG | queue://company.CD.Tomcat01.Repo.Request add sub: QueueSubscription: consumer=ID:39235aa-49503-1498147246722-1:1:1:1, destinations=0, dispatched=0, delivered=0, pending=0, dequeues: 0, dispatched: 0, inflight: 0 | org.apache.activemq.broker.region.Queue | ActiveMQ Transport: tcp:///127.0.0.1:49504@61616
2017-06-22 12:00:46,977 | DEBUG | queue://company.CD.Tomcat01.Repo.Request, subscriptions=2, memory=0%, size=0, pending=0 toPageIn: 0, Inflight: 0, pagedInMessages.size 0, pagedInPendingDispatch.size 0, enqueueCount: 0, dequeueCount: 0, memUsage:0 | org.apache.activemq.broker.region.Queue | Queue:company.CD.Tomcat01.Repo.Request
2017-06-22 12:00:46,978 | DEBUG | queue://company.CD.Tomcat01.Repo.Request, subscriptions=2, memory=0%, size=0, pending=0 toPageIn: 0, Inflight: 0, pagedInMessages.size 0, pagedInPendingDispatch.size 0, enqueueCount: 0, dequeueCount: 0, memUsage:0 | org.apache.activemq.broker.region.Queue | ActiveMQ Transport: tcp:///127.0.0.1:49504@61616
2017-06-22 12:00:46,978 | DEBUG | queue://company.CD.Tomcat01.Repo.Request, subscriptions=2, memory=0%, size=0, pending=0 toPageIn: 0, Inflight: 0, pagedInMessages.size 0, pagedInPendingDispatch.size 0, enqueueCount: 0, dequeueCount: 0, memUsage:0 | org.apache.activemq.broker.region.Queue | ActiveMQ Transport: tcp:///127.0.0.1:49504@61616
2017-06-22 12:01:04,340 | DEBUG | queue://company.CD.Tomcat01.Repo.Request expiring messages .. | org.apache.activemq.broker.region.Queue | ActiveMQ Broker[Tomcat01.CE01] Scheduler
2017-06-22 12:01:04,342 | DEBUG | queue://company.CD.Tomcat01.Repo.Request expiring messages done. | org.apache.activemq.broker.region.Queue | ActiveMQ Broker[Tomcat01.CE01] Scheduler
2017-06-22 12:01:04,342 | DEBUG | queue://company.CD.Tomcat01.Repo.Request, subscriptions=2, memory=0%, size=0, pending=0 toPageIn: 0, Inflight: 0, pagedInMessages.size 0, pagedInPendingDispatch.size 0, enqueueCount: 0, dequeueCount: 0, memUsage:0 | org.apache.activemq.broker.region.Queue | Queue:company.CD.Tomcat01.Repo.Request

而且，当我们使用升级后的 spring-jms-4.3.8 或 .9

2017-06-22 12:09:03,037 | DEBUG | Received WireFormat: WireFormatInfo { version=11, properties={TcpNoDelayEnabled=true, SizePrefixDisabled=false, CacheSize=1024, StackTraceEnabled=true, CacheEnabled=true, TightEncodingEnabled=true, MaxFrameSize=9223372036854775807, MaxInactivityDuration=30000, MaxInactivityDurationInitalDelay=30000}, magic=[A,c,t,i,v,e,M,Q]} | org.apache.activemq.transport.WireFormatNegotiator | ActiveMQ Transport: tcp:///127.0.0.1:49636@61616
2017-06-22 12:09:03,037 | DEBUG | tcp:///127.0.0.1:49636@61616 before negotiation: OpenWireFormat{version=11, cacheEnabled=false, stackTraceEnabled=false, tightEncodingEnabled=false, sizePrefixDisabled=false, maxFrameSize=9223372036854775807} | org.apache.activemq.transport.WireFormatNegotiator | ActiveMQ Transport: tcp:///127.0.0.1:49636@61616
2017-06-22 12:09:03,038 | DEBUG | tcp:///127.0.0.1:49636@61616 after negotiation: OpenWireFormat{version=11, cacheEnabled=true, stackTraceEnabled=true, tightEncodingEnabled=true, sizePrefixDisabled=false, maxFrameSize=9223372036854775807} | org.apache.activemq.transport.WireFormatNegotiator | ActiveMQ Transport: tcp:///127.0.0.1:49636@61616
2017-06-22 12:09:03,043 | DEBUG | Setting up new connection id: ID:39235aa-49635-1498147742821-1:1, address: tcp://127.0.0.1:49636, info: ConnectionInfo {commandId = 1, responseRequired = true, connectionId = ID:39235aa-49635-1498147742821-1:1, clientId = ID:39235aa-49635-1498147742821-0:1, clientIp = null, userName = null, password = *****, brokerPath = null, brokerMasterConnector = false, manageable = true, clientMaster = true, faultTolerant = true, failoverReconnect = false} | org.apache.activemq.broker.TransportConnection | ActiveMQ Transport: tcp:///127.0.0.1:49636@61616
2017-06-22 12:09:03,051 | DEBUG | Tomcat01.CE01 adding consumer: ID:39235aa-49635-1498147742821-1:1:-1:1 for destination: ActiveMQ.Advisory.TempQueue,ActiveMQ.Advisory.TempTopic | org.apache.activemq.broker.region.AbstractRegion | ActiveMQ Transport: tcp:///127.0.0.1:49636@61616
2017-06-22 12:09:03,092 | DEBUG | Tomcat01.CE01 adding consumer: ID:39235aa-49635-1498147742821-1:1:2:1 for destination: queue://company.CD.Tomcat01.Repo.Request | org.apache.activemq.broker.region.AbstractRegion | ActiveMQ Transport: tcp:///127.0.0.1:49636@61616
2017-06-22 12:09:03,095 | DEBUG | queue://company.CD.Tomcat01.Repo.Request add sub: QueueSubscription: consumer=ID:39235aa-49635-1498147742821-1:1:2:1, destinations=0, dispatched=0, delivered=0, pending=0, dequeues: 0, dispatched: 0, inflight: 0 | org.apache.activemq.broker.region.Queue | ActiveMQ Transport: tcp:///127.0.0.1:49636@61616
2017-06-22 12:09:03,095 | DEBUG | queue://company.CD.Tomcat01.Repo.Request, subscriptions=1, memory=0%, size=0, pending=0 toPageIn: 0, Inflight: 0, pagedInMessages.size 0, pagedInPendingDispatch.size 0, enqueueCount: 0, dequeueCount: 0, memUsage:0 | org.apache.activemq.broker.region.Queue | Queue:company.CD.Tomcat01.Repo.Request
2017-06-22 12:09:03,096 | DEBUG | Tomcat01.CE01 adding consumer: ID:39235aa-49635-1498147742821-1:1:1:1 for destination: queue://company.CD.Tomcat01.Repo.Request | org.apache.activemq.broker.region.AbstractRegion | ActiveMQ Transport: tcp:///127.0.0.1:49636@61616
2017-06-22 12:09:03,096 | DEBUG | queue://company.CD.Tomcat01.Repo.Request add sub: QueueSubscription: consumer=ID:39235aa-49635-1498147742821-1:1:1:1, destinations=0, dispatched=0, delivered=0, pending=0, dequeues: 0, dispatched: 0, inflight: 0 | org.apache.activemq.broker.region.Queue | ActiveMQ Transport: tcp:///127.0.0.1:49636@61616
2017-06-22 12:09:03,097 | DEBUG | queue://company.CD.Tomcat01.Repo.Request, subscriptions=2, memory=0%, size=0, pending=0 toPageIn: 0, Inflight: 0, pagedInMessages.size 0, pagedInPendingDispatch.size 0, enqueueCount: 0, dequeueCount: 0, memUsage:0 | org.apache.activemq.broker.region.Queue | Queue:company.CD.Tomcat01.Repo.Request
2017-06-22 12:09:03,097 | DEBUG | queue://company.CD.Tomcat01.Repo.Request, subscriptions=2, memory=0%, size=0, pending=0 toPageIn: 0, Inflight: 0, pagedInMessages.size 0, pagedInPendingDispatch.size 0, enqueueCount: 0, dequeueCount: 0, memUsage:0 | org.apache.activemq.broker.region.Queue | ActiveMQ Transport: tcp:///127.0.0.1:49636@61616
2017-06-22 12:09:03,105 | DEBUG | queue://company.CD.Tomcat01.Repo.Request, subscriptions=2, memory=0%, size=0, pending=0 toPageIn: 0, Inflight: 0, pagedInMessages.size 0, pagedInPendingDispatch.size 0, enqueueCount: 0, dequeueCount: 0, memUsage:0 | org.apache.activemq.broker.region.Queue | ActiveMQ Transport: tcp:///127.0.0.1:49636@61616
2017-06-22 12:09:03,114 | DEBUG | queue://company.CD.Tomcat01.Repo.Request, subscriptions=2, memory=0%, size=0, pending=0 toPageIn: 0, Inflight: 0, pagedInMessages.size 0, pagedInPendingDispatch.size 0, enqueueCount: 0, dequeueCount: 0, memUsage:0 | org.apache.activemq.broker.region.Queue | ActiveMQ Transport: tcp:///127.0.0.1:49636@61616
2017-06-22 12:09:03,114 | DEBUG | queue://company.CD.Tomcat01.Repo.Request, subscriptions=2, memory=0%, size=0, pending=0 toPageIn: 0, Inflight: 0, pagedInMessages.size 0, pagedInPendingDispatch.size 0, enqueueCount: 0, dequeueCount: 0, memUsage:0 | org.apache.activemq.broker.region.Queue | ActiveMQ Transport: tcp:///127.0.0.1:49636@61616
2017-06-22 12:09:03,114 | DEBUG | queue://company.CD.Tomcat01.Repo.Request, subscriptions=2, memory=0%, size=0, pending=0 toPageIn: 0, Inflight: 0, pagedInMessages.size 0, pagedInPendingDispatch.size 0, enqueueCount: 0, dequeueCount: 0, memUsage:0 | org.apache.activemq.broker.region.Queue | ActiveMQ Transport: tcp:///127.0.0.1:49636@61616
2017-06-22 12:09:03,114 | DEBUG | queue://company.CD.Tomcat01.Repo.Request, subscriptions=2, memory=0%, size=0, pending=0 toPageIn: 0, Inflight: 0, pagedInMessages.size 0, pagedInPendingDispatch.size 0, enqueueCount: 0, dequeueCount: 0, memUsage:0 | org.apache.activemq.broker.region.Queue | ActiveMQ Transport: tcp:///127.0.0.1:49636@61616
2017-06-22 12:09:03,115 | DEBUG | queue://company.CD.Tomcat01.Repo.Request, subscriptions=2, memory=0%, size=0, pending=0 toPageIn: 0, Inflight: 0, pagedInMessages.size 0, pagedInPendingDispatch.size 0, enqueueCount: 0, dequeueCount: 0, memUsage:0 | org.apache.activemq.broker.region.Queue | ActiveMQ Transport: tcp:///127.0.0.1:49636@61616
2017-06-22 12:09:03,115 | DEBUG | queue://company.CD.Tomcat01.Repo.Request, subscriptions=2, memory=0%, size=0, pending=0 toPageIn: 0, Inflight: 0, pagedInMessages.size 0, pagedInPendingDispatch.size 0, enqueueCount: 0, dequeueCount: 0, memUsage:0 | org.apache.activemq.broker.region.Queue | ActiveMQ Transport: tcp:///127.0.0.1:49636@61616

如果我们看一下两个activemq日志的区别，

它显示队列订阅行仅打印一次或两次，然后在 30 秒的间隙后到期时间开始，循环继续

但是在第二个日志中，过期永远不会开始，并且每毫秒打印一次队列订阅行，并且日志会在几分钟内进入 GB，所以某种循环。

我们正在尝试对此进行调试，但如果有人有任何想法或建议，请通过。

谢谢。

【问题讨论】：

标签： activemq spring-jms

【解决方案1】：

发现问题了，升级后的 4.3.8 版本现在有 0 表示接收超时，而不是早期的 -1 表示等待它收到我们使用过的新消息，以及为什么它试图从代理 (activemq) 获取消息) 在一个循环中，并用那些导致 CPU 持续使用的调用轰炸它。

来自 JmsDestinationAccessor 类的代码 sn-p。

protected Message receiveFromConsumer(MessageConsumer consumer, long timeout) throws JMSException {
    if (timeout > 0) {
        return consumer.receive(timeout);
    }
    else if (timeout < 0) {
        return consumer.receiveNoWait();
    }
    else {
        return consumer.receive();
    }
}

【讨论】：