Spring jms 4.3.8 与 4.0.2 与 activemq 5.13.0 问题

Question

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

我们看到的是 spring-jms 或 activemq 端的连续循环，并且 CPU 在 [=52= 中启动应用程序后始终固定在 20-40 左右的范围内].

如果我们返回并用 4.0.2 版本替换 lib 中的 spring-jms 4.3.8，启动后一切正常。

spring 中 "DefaultMessageListenerContainer" 的并发消费者为 2，缓存级别设置为 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，所以某种循环。

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

谢谢。

Answer 1

发现问题，升级后的 4.3.8 版本现在有 0 的接收超时，而不是之前的 -1 等待直到它收到我们使用过的新消息，这就是它尝试从代理获取消息的原因(activemq) 在一个循环中，并用那些导致继续 CPU 使用的调用轰炸它。

来自 JmsDestinationAccessor 的代码片段 class。

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();
    }
}

Spring jms 4.3.8 与 4.0.2 与 activemq 5.13.0 问题

Spring jms 4.3.8 vs 4.0.2 with activemq 5.13.0 issue

activemq

spring-jms