activemq-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Matthias Strolz (JIRA)" <j...@apache.org>
Subject [jira] Created: (AMQ-2500) Active MQ Blocks when sending and receiving messages and doesn't release resources even after queue is empty
Date Wed, 18 Nov 2009 13:26:52 GMT
Active MQ Blocks when sending and receiving messages and doesn't release resources even after
queue is empty
------------------------------------------------------------------------------------------------------------

                 Key: AMQ-2500
                 URL: https://issues.apache.org/activemq/browse/AMQ-2500
             Project: ActiveMQ
          Issue Type: Bug
    Affects Versions: 5.2.0
         Environment: JDK 1.6.0.x, Windows XP and Vista, ActiveMQ Default-configurations
            Reporter: Matthias Strolz


The following test-programm reads and writes messages into the same queue (testQueue). After
Reading several messages the class starts two threads that are writing messages in the same
queue. After writing several messages the producer hangs on:

producer.send()

and doesn't recover even if the reader continues reading messages from the queue. Even stopping
the clients (via kill) doesn't change the broker's behaviour. In this state further connections
opened from other clients hang on the same method call (producer.send()). The client's connections
will remain open as you can see in the jconsole-screenshot, that has been taken after the
producer in the example hung. Althogh the consumer may continue reading new producer can only
continue writing messages into the queue after activeMQ has been restarted. 

The following two snippets show the difference between the first (127.0.0.1:49372) and the
second (127.0.0.1:49385) message producer: The first producer works as expected and adds it's
messages to the queue. The second producer stops with the following log-entry: 2009-11-13
09:41:45,639 [127.0.0.1:49385] DEBUG AbstractRegion                 - Adding consumer: ID:JoergsPC-49370-1258101701975-0:14:-1:1

...
2009-11-13 09:41:42,376 [eue://testQueue] DEBUG Queue                          - queue://testQueue
- Recovery - Message pushed '21290107 - Message ID:JoergsPC-50687-1258047095293-0:2810:1:1:1
dropped=false locked=false' to subscription: 'QueueSubscription: consumer=ID:JoergsPC-49370-1258101701975-0:0:1:1,
destinations=1, dispatched=197, delivered=0, pending=0'
2009-11-13 09:41:42,376 [eue://testQueue] DEBUG Queue                          - queue://testQueue
- Recovery - Message pushed '31931917 - Message ID:JoergsPC-50687-1258047095293-0:2811:1:1:1
dropped=false locked=false' to subscription: 'QueueSubscription: consumer=ID:JoergsPC-49370-1258101701975-0:0:1:1,
destinations=1, dispatched=198, delivered=0, pending=0'
2009-11-13 09:41:42,376 [eue://testQueue] DEBUG Queue                          - queue://testQueue
- Recovery - Message pushed '10144386 - Message ID:JoergsPC-50687-1258047095293-0:2812:1:1:1
dropped=false locked=false' to subscription: 'QueueSubscription: consumer=ID:JoergsPC-49370-1258101701975-0:0:1:1,
destinations=1, dispatched=199, delivered=0, pending=0'
2009-11-13 09:41:42,381 [127.0.0.1:49372] DEBUG WireFormatNegotiator           - Received
WireFormat: WireFormatInfo { version=3, properties={CacheSize=1024, CacheEnabled=true, SizePrefixDisabled=false,
MaxInactivityDurationInitalDelay=10000, TcpNoDelayEnabled=true, MaxInactivityDuration=30000,
TightEncodingEnabled=true, StackTraceEnabled=true}, magic=[A,c,t,i,v,e,M,Q]}
2009-11-13 09:41:42,381 [127.0.0.1:49372] DEBUG WireFormatNegotiator           - Sending:
WireFormatInfo { version=3, properties={CacheSize=1024, CacheEnabled=true, SizePrefixDisabled=false,
MaxInactivityDurationInitalDelay=10000, TcpNoDelayEnabled=true, MaxInactivityDuration=30000,
TightEncodingEnabled=true, StackTraceEnabled=true}, magic=[A,c,t,i,v,e,M,Q]}
2009-11-13 09:41:42,382 [127.0.0.1:49372] DEBUG WireFormatNegotiator           - tcp:///127.0.0.1:49372
before negotiation: OpenWireFormat{version=3, cacheEnabled=false, stackTraceEnabled=false,
tightEncodingEnabled=false, sizePrefixDisabled=false}
2009-11-13 09:41:42,394 [127.0.0.1:49372] DEBUG WireFormatNegotiator           - tcp:///127.0.0.1:49372
after negotiation: OpenWireFormat{version=3, cacheEnabled=true, stackTraceEnabled=true, tightEncodingEnabled=true,
sizePrefixDisabled=false}
2009-11-13 09:41:42,395 [127.0.0.1:49372] DEBUG TransportConnection            - Setting up
new connection: /127.0.0.1:49372
2009-11-13 09:41:42,409 [127.0.0.1:49372] DEBUG AbstractRegion                 - Adding consumer:
ID:JoergsPC-49370-1258101701975-0:1:-1:1
2009-11-13 09:41:42,414 [127.0.0.1:49372] DEBUG AbstractRegion                 - Adding destination:
topic://ActiveMQ.Advisory.Producer.Queue.testQueue
2009-11-13 09:41:42,416 [127.0.0.1:49372] DEBUG AMQMessageStore                - Journalled
message add for: ID:JoergsPC-49370-1258101701975-0:1:1:1:1, at: offset = 10684963, file =
4, size = 270, type = 1
2009-11-13 09:41:42,416 [eue://testQueue] DEBUG AMQMessageStore                - Doing batch
update... adding: 1 removing: 0 
2009-11-13 09:41:42,417 [eue://testQueue] DEBUG AMQMessageStore                - Batch update
done.
2009-11-13 09:41:42,418 [eue://testQueue] DEBUG Usage                          - Memory usage
change.  from: 7, to: 8
2009-11-13 09:41:42,418 [eue://testQueue] DEBUG Usage                          - Memory usage
change.  from: 1, to: 2
2009-11-13 09:41:42,425 [eue://testQueue] DEBUG Usage                          - Memory usage
change.  from: 8, to: 9
2009-11-13 09:41:42,433 [eue://testQueue] DEBUG Usage                          - Memory usage
change.  from: 9, to: 10
2009-11-13 09:41:42,440 [eue://testQueue] DEBUG Usage                          - Memory usage
change.  from: 10, to: 11
2009-11-13 09:41:42,470 [127.0.0.1:49371] DEBUG AbstractRegion                 - Removing
consumer: ID:JoergsPC-49370-1258101701975-0:0:1:1
2009-11-13 09:41:42,474 [127.0.0.1:49371] DEBUG AMQMessageStore                - flush starting
...
2009-11-13 09:41:42,474 [127.0.0.1:49371] DEBUG AbstractRegion                 - Removing
consumer: ID:JoergsPC-49370-1258101701975-0:0:-1:1
2009-11-13 09:41:42,477 [127.0.0.1:49371] DEBUG TransportConnection            - Stopping
connection: /127.0.0.1:49371
...


...
2009-11-13 09:41:45,319 [eue://testQueue] DEBUG Queue                          - queue://testQueue
- Recovery - Message pushed '21569784 - Message ID:JoergsPC-50687-1258047095293-0:3422:1:1:1
dropped=false locked=false' to subscription: 'QueueSubscription: consumer=ID:JoergsPC-49370-1258101701975-0:13:1:1,
destinations=1, dispatched=797, delivered=0, pending=0'
2009-11-13 09:41:45,320 [eue://testQueue] DEBUG Usage                          - Memory usage
change.  from: 181, to: 182
2009-11-13 09:41:45,327 [eue://testQueue] DEBUG Usage                          - Memory usage
change.  from: 182, to: 183
2009-11-13 09:41:45,331 [eue://testQueue] DEBUG Usage                          - Memory usage
change.  from: 183, to: 184
2009-11-13 09:41:45,332 [eue://testQueue] DEBUG Usage                          - Memory usage
change.  from: 45, to: 46
2009-11-13 09:41:45,338 [eue://testQueue] DEBUG Usage                          - Memory usage
change.  from: 184, to: 185
2009-11-13 09:41:45,344 [eue://testQueue] DEBUG Usage                          - Memory usage
change.  from: 185, to: 186
2009-11-13 09:41:45,349 [eue://testQueue] DEBUG Usage                          - Memory usage
change.  from: 186, to: 187
2009-11-13 09:41:45,356 [eue://testQueue] DEBUG Usage                          - Memory usage
change.  from: 187, to: 188
2009-11-13 09:41:45,356 [eue://testQueue] DEBUG Usage                          - Memory usage
change.  from: 46, to: 47
2009-11-13 09:41:45,442 [127.0.0.1:49384] DEBUG AbstractRegion                 - Removing
consumer: ID:JoergsPC-49370-1258101701975-0:13:1:1
2009-11-13 09:41:45,445 [eue://testQueue] DEBUG Usage                          - Memory usage
change.  from: 188, to: 189
2009-11-13 09:41:45,443 [127.0.0.1:49372] DEBUG AbstractRegion                 - Removing
consumer: ID:JoergsPC-49370-1258101701975-0:1:-1:1
2009-11-13 09:41:45,632 [127.0.0.1:49372] DEBUG TransportConnection            - Stopping
connection: /127.0.0.1:49372
2009-11-13 09:41:45,632 [127.0.0.1:49372] DEBUG TcpTransport                   - Stopping
transport tcp:///127.0.0.1:49372
2009-11-13 09:41:45,632 [127.0.0.1:49372] DEBUG TransportConnection            - Stopped transport:
/127.0.0.1:49372
2009-11-13 09:41:45,632 [127.0.0.1:49372] DEBUG TransportConnection            - Connection
Stopped: /127.0.0.1:49372
2009-11-13 09:41:45,636 [127.0.0.1:49385] DEBUG WireFormatNegotiator           - Sending:
WireFormatInfo { version=3, properties={CacheSize=1024, CacheEnabled=true, SizePrefixDisabled=false,
MaxInactivityDurationInitalDelay=10000, TcpNoDelayEnabled=true, MaxInactivityDuration=30000,
TightEncodingEnabled=true, StackTraceEnabled=true}, magic=[A,c,t,i,v,e,M,Q]}
2009-11-13 09:41:45,638 [127.0.0.1:49385] DEBUG WireFormatNegotiator           - Received
WireFormat: WireFormatInfo { version=3, properties={CacheSize=1024, CacheEnabled=true, SizePrefixDisabled=false,
MaxInactivityDurationInitalDelay=10000, TcpNoDelayEnabled=true, MaxInactivityDuration=30000,
TightEncodingEnabled=true, StackTraceEnabled=true}, magic=[A,c,t,i,v,e,M,Q]}
2009-11-13 09:41:45,638 [127.0.0.1:49385] DEBUG WireFormatNegotiator           - tcp:///127.0.0.1:49385
before negotiation: OpenWireFormat{version=3, cacheEnabled=false, stackTraceEnabled=false,
tightEncodingEnabled=false, sizePrefixDisabled=false}
2009-11-13 09:41:45,638 [127.0.0.1:49385] DEBUG WireFormatNegotiator           - tcp:///127.0.0.1:49385
after negotiation: OpenWireFormat{version=3, cacheEnabled=true, stackTraceEnabled=true, tightEncodingEnabled=true,
sizePrefixDisabled=false}
2009-11-13 09:41:45,638 [127.0.0.1:49385] DEBUG TransportConnection            - Setting up
new connection: /127.0.0.1:49385
2009-11-13 09:41:45,639 [127.0.0.1:49385] DEBUG AbstractRegion                 - Adding consumer:
ID:JoergsPC-49370-1258101701975-0:14:-1:1
2009-11-13 09:41:45,641 [eue://testQueue] DEBUG Usage                          - Memory usage
change.  from: 189, to: 190
2009-11-13 09:41:45,647 [eue://testQueue] DEBUG Usage                          - Memory usage
change.  from: 190, to: 191
2009-11-13 09:41:45,653 [eue://testQueue] DEBUG Usage                          - Memory usage
change.  from: 191, to: 192
2009-11-13 09:41:45,653 [eue://testQueue] DEBUG Usage                          - Memory usage
change.  from: 47, to: 48
2009-11-13 09:41:45,658 [eue://testQueue] DEBUG Usage                          - Memory usage
change.  from: 192, to: 193
2009-11-13 09:41:45,663 [127.0.0.1:49384] DEBUG Usage                          - Memory usage
change.  from: 193, to: 192
2009-11-13 09:41:45,663 [127.0.0.1:49384] DEBUG Usage                          - Memory usage
change.  from: 192, to: 191
2009-11-13 09:41:45,663 [127.0.0.1:49384] DEBUG Usage                          - Memory usage
change.  from: 48, to: 47
2009-11-13 09:41:45,663 [127.0.0.1:49384] DEBUG Usage                          - Memory usage
change.  from: 191, to: 190
2009-11-13 09:41:45,664 [127.0.0.1:49384] DEBUG Usage                          - Memory usage
change.  from: 190, to: 189
2009-11-13 09:41:45,664 [127.0.0.1:49384] DEBUG AMQMessageStore                - flush starting
...
2009-11-13 09:41:45,664 [127.0.0.1:49384] DEBUG AbstractRegion                 - Removing
consumer: ID:JoergsPC-49370-1258101701975-0:13:-1:1
2009-11-13 09:41:45,665 [127.0.0.1:49384] DEBUG TransportConnection            - Stopping
connection: /127.0.0.1:49384
...




-- 
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.


Mime
View raw message