Could not enqueue message and Too many open files

• Key: AMQ-275
• Type: Bug
• Status: Resolved
• Resolution: Fixed
• Priority: Major
• Assignee: Unassigned
• Reporter: Glen Klyuzner
• Component/s: Broker
• Affects Version/s: 3.0
• Fix Version/s: 4.0.1

Description

Relaited to slow consumer condition.

WARN 2005-06-22 12:55:44,135 - Queue is full, waiting for it to be dequeued.

2005-06-22 11:51:09,678 [ocalport=61616]] WARN BrokerClientImpl - Connection: ID:ny-cap-33-2024-1119453996333-6:0 is a slow consumer
2005-06-22 11:51:09,678 [ocalport=61616]] WARN BrokerClientImpl - Connection: ID:ny-cap-33-2024-1119453996333-6:0 is a slow consumer
2005-06-22 11:51:09,694 [ocalport=61616]] INFO DataContainer - making directory for temporary spooled data: ActiveMQTemp
2005-06-22 11:51:11,069 [ocalport=61616]] WARN BrokerClientImpl - Connection: ID:ny-cap-33-2005-1119453893347-6:0 is a slow consumer
2005-06-22 11:51:11,069 [ocalport=61616]] WARN BrokerClientImpl - Connection: ID:ny-cap-33-2005-1119453893347-6:0 is a slow consumer

2005-06-22 11:51:17,288 [ocalport=61616]] DEBUG ientTopicBoundedMessageManager - Adding consumer: CONSUMER_INFO: id = 336 ConsumerInfo{ browser = false, destination = ActiveMQ.Advisory.TempDestinations.temp-queue.TemporaryQueue-{TD{ID:ny-cap-33-2150-1119455437835-16:0}TD}ID:ny-cap-33-2150-1119455437835-23:0, consumerIdentifier = 'ID:ny-cap-33-2024-1119453996333-16:0.27.53' , clientId = 'ID:ny-cap-33-2024-1119453996333-16:0' , sessionId = '27' , consumerName = '' , selector = '' , startTime = 1119455477008, started = true, consumerNo = 53, noLocal = false, prefetchNumber = 1000, consumerKey = '[ID:ny-cap-33-2024-1119453996333-16:0:]' }
2005-06-22 11:51:54,773 [ocalport=61616]] ERROR BrokerClientImpl - Could not enqueue message ACTIVEMQ_OBJECT_MESSAGE: id = 0 ActiveMQMessage{ , jmsMessageID = ID:ny-cap-33-2005-1119453893347-68:121589, bodyAsBytes = org.activemq.io.util.ByteArray@1f07377, readOnlyMessage = false, jmsClientID = 'ID:ny-cap-33-2005-1119453893347-6:0' , jmsCorrelationID = 'null' , jmsDestination = Topic.sds.PropertyTemplatePublisher, jmsReplyTo = null, jmsDeliveryMode = 2, jmsRedelivered = false, jmsType = 'null' , jmsExpiration = 1119455573508, jmsPriority = 4, jmsTimestamp = 1119455513508, properties = null, readOnlyProperties = false, entryBrokerName = 'ID:nyotc023-2882-1119382254093-0:0' , entryClusterName = 'default' , consumerNos = [I@12cb4ae, transactionId = 'null' , xaTransacted = false, consumerIdentifer = 'null' , messageConsumed = false, transientConsumed = false, sequenceNumber = 121589, deliveryCount = 1, dispatchedFromDLQ = false, messageAcknowledge = null, jmsMessageIdentity = null, producerKey = ID:ny-cap-33-2005-1119453893347-68: } ActiveMQObjectMessage{ object = null } to SpooledBoundedQueue for this slow consumer
javax.jms.JMSException: enqueNoBlock failed: Too many open files
at org.activemq.io.util.SpooledBoundedActiveMQMessageQueue.enqueueNoBlock(SpooledBoundedActiveMQMessageQueue.java:121)
at org.activemq.io.util.SpooledBoundedActiveMQMessageQueue.enqueue(SpooledBoundedActiveMQMessageQueue.java:91)
at org.activemq.broker.impl.BrokerClientImpl.dispatch(BrokerClientImpl.java:198)
at org.activemq.service.boundedvm.TransientTopicBoundedMessageContainer.dispatchToQueue(TransientTopicBoundedMessageContainer.java:223)
at org.activemq.service.boundedvm.TransientTopicBoundedMessageContainer.targetAndDispatch(TransientTopicBoundedMessageContainer.java:155)
at org.activemq.service.boundedvm.TransientTopicBoundedMessageManager.doSendMessage(TransientTopicBoundedMessageManager.java:225)
at org.activemq.service.boundedvm.TransientTopicBoundedMessageManager.sendMessage(TransientTopicBoundedMessageManager.java:204)
at org.activemq.broker.impl.DefaultBroker.doMessageSend(DefaultBroker.java:563)
at org.activemq.broker.impl.DefaultBroker.sendMessage(DefaultBroker.java:305)
at org.activemq.broker.impl.BrokerContainerImpl.sendMessage(BrokerContainerImpl.java:462)
at org.activemq.broker.impl.BrokerConnectorImpl.sendMessage(BrokerConnectorImpl.java:271)
at org.activemq.broker.impl.BrokerClientImpl.consumeActiveMQMessage(BrokerClientImpl.java:706)
at org.activemq.broker.impl.BrokerClientImpl.consume(BrokerClientImpl.java:310)
at org.activemq.transport.TransportChannelSupport.doConsumePacket(TransportChannelSupport.java:374)
at org.activemq.transport.TransportChannelSupport.doConsumePacket(TransportChannelSupport.java:368)
at org.activemq.transport.tcp.TcpTransportChannel.run(TcpTransportChannel.java:311)
at java.lang.Thread.run(Thread.java:534)

Comments

[Hiram Chirino]

To reproduce:

1. Set the file decriptor limit low, run:
ulimit -n 100
2. Start the broker in the session with the low file descriptor limit
2. Run a slow consumer using our sample programs:
ant consumer -Dtopic=true -DsleepTime=10000 -Dmax=1000000
3. Thow alot of messages at the topic using our sample programs:
ant producer -Dtopic=true -Dmax=100000000

[Hiram Chirino]

Fixed.

[Glen Klyuzner]

Installed M5 release and was able to reproduce the same error condition:

singleton bean 'derby-ds'
2005-07-18 15:12:02,667 [main ] INFO ActiveMQBeanFactory - Autowiring by type from bean name 'jdbcPersistence' via constructor to bean named 'derby-ds'
2005-07-18 15:12:02,683 [main ] INFO ActiveMQBeanFactory - Bean 'jdbcPersistence' instantiated via constructor [public org.activemq.store.jdbc.JDBCPersistenceAdapter()]
2005-07-18 16:37:34,533 [ocalport=61616]] WARN BrokerClientImpl - Connection: ID:ny-cap-33-1550-1121719043944-19:0 is a slow consumer
2005-07-18 16:37:58,831 [ocalport=61616]] ERROR BrokerClientImpl - Could not enqueue message ACTIVEMQ_OBJECT_MESSAGE: id = 0 ActiveMQMessage{ , jmsMessageID = ID:ny-cap-33-1206-1121716722976-94:80900, bodyAsBytes = org.activemq.io.util.ByteArray@f9e48, readOnlyMessage = false, jmsClientID = 'ID:ny-cap-33-1206-1121716722976-19:0' , jmsCorrelationID = 'null' , jmsDestination = Topic.sds.PropertyTemplatePublisher, jmsReplyTo = null, jmsDeliveryMode = 2, jmsRedelivered = false, jmsType = 'null' , jmsExpiration = 1121719138600, jmsPriority = 4, jmsTimestamp = 1121719078600, properties = null, readOnlyProperties = false, entryBrokerName = 'nyotc023-broker-1' , entryClusterName = 'default' , consumerNos = [I@160bf5e, transactionId = 'null' , xaTransacted = false, consumerIdentifer = 'null' , messageConsumed = false, transientConsumed = false, sequenceNumber = 80900, deliveryCount = 1, dispatchedFromDLQ = false, messageAcknowledge = null, jmsMessageIdentity = null, producerKey = ID:ny-cap-33-1206-1121716722976-94: } ActiveMQObjectMessage{ object = null } to SpooledBoundedQueue for this slow consumer
javax.jms.JMSException: enqueNoBlock failed: Too many open files
at org.activemq.io.util.SpooledBoundedActiveMQMessageQueue.enqueueNoBlock(SpooledBoundedActiveMQMessageQueue.java:121)
at org.activemq.io.util.SpooledBoundedActiveMQMessageQueue.enqueue(SpooledBoundedActiveMQMessageQueue.java:91)
at org.activemq.broker.impl.BrokerClientImpl.dispatch(BrokerClientImpl.java:205)
at org.activemq.service.boundedvm.TransientTopicBoundedMessageContainer.dispatchToQueue(TransientTopicBoundedMessageContainer.java:223)
at org.activemq.service.boundedvm.TransientTopicBoundedMessageContainer.targetAndDispatch(TransientTopicBoundedMessageContainer.java:155)
at org.activemq.service.boundedvm.TransientTopicBoundedMessageManager.doSendMessage(TransientTopicBoundedMessageManager.java:225)
at org.activemq.service.boundedvm.TransientTopicBoundedMessageManager.sendMessage(TransientTopicBoundedMessageManager.java:204)
at org.activemq.broker.impl.DefaultBroker.doMessageSend(DefaultBroker.java:563)
at org.activemq.broker.impl.DefaultBroker.sendMessage(DefaultBroker.java:305)
at org.activemq.broker.impl.BrokerContainerImpl.sendMessage(BrokerContainerImpl.java:462)
at org.activemq.broker.impl.BrokerConnectorImpl.sendMessage(BrokerConnectorImpl.java:271)
at org.activemq.broker.impl.BrokerClientImpl.consumeActiveMQMessage(BrokerClientImpl.java:713)
at org.activemq.broker.impl.BrokerClientImpl.consume(BrokerClientImpl.java:317)
at org.activemq.transport.TransportChannelSupport.doConsumePacket(TransportChannelSupport.java:374)
at org.activemq.transport.TransportChannelSupport.doConsumePacket(TransportChannelSupport.java:368)
at org.activemq.transport.tcp.TcpTransportChannel.run(TcpTransportChannel.java:311)
at java.lang.Thread.run(Thread.java:534)

App log:
INFO 2005-07-18 16:37:27,881 - Queue Name= AE.Queue.sds.PropertyTemplatePublisher - class com.tullib.core.message.jms.MessageServerJMSStub
WARN 2005-07-18 16:37:42,787 - Queue is full, waiting for it to be dequeued.
WARN 2005-07-18 16:37:42,881 - Queue is full, waiting for it to be dequeued.
...
WARN 2005-07-18 16:46:15,463 - Queue is full, waiting for it to be dequeued.
WARN 2005-07-18 16:46:15,572 - Queue is full, waiting for it to be dequeued.
WARN 2005-07-18 16:46:15,666 - Queue is full, waiting for it to be dequeued.

Process finished with exit code 1

[Glen Klyuzner]

ACTIVEMQ_HOME was pointing to the old M3 release.
Could not reproduce it anymore with M5 release and correct ACTIVEMQ-HOME.

[Nigel Leck]

we could reproduce this problem in version 3.2 of ActiveMQ.

We created a topic and had a fast producer which created messages as fast a posible and a consumer which did a Thread.sleep( 1000) between each message. Once the memory was filled. It starts to write the messages to a series of files and a handle to these files into a array list but the file handle is still open so after a number of files are created we get a "Too Many Files Open" Exception.

[Nigel Leck]

Here is the patch file for FileDataBlock.java

basically we need to close the file handle before it is placed into the collection otherwise we will get "too many files open" error.

[Kieran Murphy]

We also had this problem and have found that the patch above – closing the file handle before it is passed to the collection – prevents the problem. There is still a problem when the SpooledBoundedActiveMQMessageQueue is full, all messages slow down waiting for the queue to be dequeued.

The "Queue is full, waiting for it to be dequeued" log message is being reported on the consumer's side, and is refering to a MemoryBoundedQueue which queues messages read off the socket. This is a slightly different but very significant problem – if the consumer's MemoryBoundedQueue is full, there is a call to wait(). This prevents any messages at all from being read on the consumer's side, so all messaging slows to a standstill. This will eventually lead to a breakdown in the reliable protocol – see AMQ-443 – the KeepAlive packets sent to a consumer are not enqueued-dequeued fast enough on the consumer side, so the KeepAliveDaemon prompts the consumer to reconnect.

We have corrected this consumer-side problem by first applying the patch to FileDataBlock above, then refactoring ActiveMQSession to create a SpooledBoundedActiveMQMessageQueue for each consumer rather than a MemoryBoundedQueue. This required some other minor refactoring to other files – adding "enqueueFirstNoBlock" to SpooledBoundedMessageQueue, for example. This has not only prevented the problems described above, it also seems to have prevented the "slow consumer" situation entirely.

[James Strachan]

This issue is fixed now in 4.0.1