You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@qpid.apache.org by "David Kellum (Created) (JIRA)" <ji...@apache.org> on 2011/10/31 22:41:32 UTC

[jira] [Created] (QPID-3567) CPU util slowly increases/consumer rate reduced with Java Client

CPU util slowly increases/consumer rate reduced with Java Client
----------------------------------------------------------------

                 Key: QPID-3567
                 URL: https://issues.apache.org/jira/browse/QPID-3567
             Project: Qpid
          Issue Type: Bug
          Components: Java Client
    Affects Versions: 0.12
         Environment: java version "1.6.0_26"
Java(TM) SE Runtime Environment (build 1.6.0_26-b03)
Java HotSpot(TM) 64-Bit Server VM (build 20.1-b02, mixed mode)

RHEL 5.6
Broker: qpidd (qpidc) version 0.8

            Reporter: David Kellum


For several hours on initial startup, a single threaded Java consumer application processes about 120 message/sec using only ~4% of a CPU.  But CPU gradually increases and eventually impedes message consumption rate. 

At this last instance I caught it utilizing 90% CPU while consumption rate had dropped to 20 messages/sec (queue filling up.) Before restaring:

* Checked GC: nothing unusual, very little time spent in collections.

* Took a series of stack samples, which all have the following suspect runnable thread in the same location:

{noformat} 
"Dispatcher-Channel-0" daemon prio=10 tid=0x00002aaab0998000 nid=0x3384 runnable [0x0000000041f5e000]
   java.lang.Thread.State: RUNNABLE
	at java.util.concurrent.ConcurrentLinkedQueue.remove(ConcurrentLinkedQueue.java:432)
	at org.apache.qpid.client.AMQSession_0_10.acknowledgeMessage(AMQSession_0_10.java:259)
	at org.apache.qpid.client.BasicMessageConsumer.postDeliver(BasicMessageConsumer.java:796)
	at org.apache.qpid.client.BasicMessageConsumer_0_10.postDeliver(BasicMessageConsumer_0_10.java:448)
	at org.apache.qpid.client.BasicMessageConsumer.notifyMessage(BasicMessageConsumer.java:726)
	at org.apache.qpid.client.BasicMessageConsumer_0_10.notifyMessage(BasicMessageConsumer_0_10.java:167)
{noformat}

Its seems odd that ConcurrentLinkedQueue.remove() call could be occupying the Dispatcher thread for 3 out of 3 samples.

I will attach the complete stack trace.

After restarting the application it again returns to its normal high message-rate/low CPU behaviour.






--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira

        

---------------------------------------------------------------------
Apache Qpid - AMQP Messaging Implementation
Project:      http://qpid.apache.org
Use/Interact: mailto:dev-subscribe@qpid.apache.org


[jira] [Commented] (QPID-3567) CPU util slowly increases/consumer rate reduced with Java Client

Posted by "Robbie Gemmell (Commented) (JIRA)" <ji...@apache.org>.
    [ https://issues.apache.org/jira/browse/QPID-3567?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13216606#comment-13216606 ] 

Robbie Gemmell commented on QPID-3567:
--------------------------------------

Thanks for the update David.

Just as an FYI, calling message.acknowledge() on anything except a CLIENT_ACK session is essentially a no-op, the only difference is an 'if CLIENT_ACK' evaluation that prevents anything being done for the other acknowledgment modes.

Given that you havent seen the issue again and we havent had any other reports or encountered it ourselves, I am just going to resolve the issue now.

Regards,
Robbie
                
> CPU util slowly increases/consumer rate reduced with Java Client
> ----------------------------------------------------------------
>
>                 Key: QPID-3567
>                 URL: https://issues.apache.org/jira/browse/QPID-3567
>             Project: Qpid
>          Issue Type: Bug
>          Components: Java Client
>    Affects Versions: 0.12
>         Environment: java version "1.6.0_26"
> Java(TM) SE Runtime Environment (build 1.6.0_26-b03)
> Java HotSpot(TM) 64-Bit Server VM (build 20.1-b02, mixed mode)
> RHEL 5.6
> Broker: qpidd (qpidc) version 0.8
>            Reporter: David Kellum
>         Attachments: qpid-0.12-stack-samples.txt
>
>
> For several hours on initial startup, a single threaded Java consumer application processes about 120 message/sec using only ~4% of a CPU.  But CPU gradually increases and eventually impedes message consumption rate. 
> At this last instance I caught it utilizing 90% CPU while consumption rate had dropped to 20 messages/sec (queue filling up.) Before restaring:
> * Checked GC: nothing unusual, very little time spent in collections.
> * Took a series of stack samples, which all have the following suspect runnable thread in the same location:
> {noformat} 
> "Dispatcher-Channel-0" daemon prio=10 tid=0x00002aaab0998000 nid=0x3384 runnable [0x0000000041f5e000]
>    java.lang.Thread.State: RUNNABLE
> 	at java.util.concurrent.ConcurrentLinkedQueue.remove(ConcurrentLinkedQueue.java:432)
> 	at org.apache.qpid.client.AMQSession_0_10.acknowledgeMessage(AMQSession_0_10.java:259)
> 	at org.apache.qpid.client.BasicMessageConsumer.postDeliver(BasicMessageConsumer.java:796)
> 	at org.apache.qpid.client.BasicMessageConsumer_0_10.postDeliver(BasicMessageConsumer_0_10.java:448)
> 	at org.apache.qpid.client.BasicMessageConsumer.notifyMessage(BasicMessageConsumer.java:726)
> 	at org.apache.qpid.client.BasicMessageConsumer_0_10.notifyMessage(BasicMessageConsumer_0_10.java:167)
> {noformat}
> Its seems odd that ConcurrentLinkedQueue.remove() call could be occupying the Dispatcher thread for 3 out of 3 samples.
> I will attach the complete stack trace.
> After restarting the application it again returns to its normal high message-rate/low CPU behaviour.

--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira

        

---------------------------------------------------------------------
Apache Qpid - AMQP Messaging Implementation
Project:      http://qpid.apache.org
Use/Interact: mailto:dev-subscribe@qpid.apache.org


[jira] [Commented] (QPID-3567) CPU util slowly increases/consumer rate reduced with Java Client

Posted by "Robbie Gemmell (Commented) (JIRA)" <ji...@apache.org>.
    [ https://issues.apache.org/jira/browse/QPID-3567?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13140621#comment-13140621 ] 

Robbie Gemmell commented on QPID-3567:
--------------------------------------

Hi David,

It would be good if you can try 0.10 as well, to help narrow when any issue may have been introduced. Also, trunk is about to be branched later this week in the run up to 0.14 (currently aimed for release in around a month) and although I cant think of anything done to fix an issue like you are describing, there has been some change in that area so it also would be useful if you can see whether it shows the same symptoms. If you dont have a trunk checkout handy to roll your own, you can get a nightly build of the the client here: https://builds.apache.org/view/M-R/view/Qpid/job/Qpid-Java-Release/lastSuccessfulBuild/artifact/trunk/qpid/java/client/release/

It would also be good if you could post a simple reproducer (or failing that, the actual code you are using now) to help anyone investigating the issue to more closely reproduce what you are doing.

Regards,
Robbie
                
> CPU util slowly increases/consumer rate reduced with Java Client
> ----------------------------------------------------------------
>
>                 Key: QPID-3567
>                 URL: https://issues.apache.org/jira/browse/QPID-3567
>             Project: Qpid
>          Issue Type: Bug
>          Components: Java Client
>    Affects Versions: 0.12
>         Environment: java version "1.6.0_26"
> Java(TM) SE Runtime Environment (build 1.6.0_26-b03)
> Java HotSpot(TM) 64-Bit Server VM (build 20.1-b02, mixed mode)
> RHEL 5.6
> Broker: qpidd (qpidc) version 0.8
>            Reporter: David Kellum
>         Attachments: qpid-0.12-stack-samples.txt
>
>
> For several hours on initial startup, a single threaded Java consumer application processes about 120 message/sec using only ~4% of a CPU.  But CPU gradually increases and eventually impedes message consumption rate. 
> At this last instance I caught it utilizing 90% CPU while consumption rate had dropped to 20 messages/sec (queue filling up.) Before restaring:
> * Checked GC: nothing unusual, very little time spent in collections.
> * Took a series of stack samples, which all have the following suspect runnable thread in the same location:
> {noformat} 
> "Dispatcher-Channel-0" daemon prio=10 tid=0x00002aaab0998000 nid=0x3384 runnable [0x0000000041f5e000]
>    java.lang.Thread.State: RUNNABLE
> 	at java.util.concurrent.ConcurrentLinkedQueue.remove(ConcurrentLinkedQueue.java:432)
> 	at org.apache.qpid.client.AMQSession_0_10.acknowledgeMessage(AMQSession_0_10.java:259)
> 	at org.apache.qpid.client.BasicMessageConsumer.postDeliver(BasicMessageConsumer.java:796)
> 	at org.apache.qpid.client.BasicMessageConsumer_0_10.postDeliver(BasicMessageConsumer_0_10.java:448)
> 	at org.apache.qpid.client.BasicMessageConsumer.notifyMessage(BasicMessageConsumer.java:726)
> 	at org.apache.qpid.client.BasicMessageConsumer_0_10.notifyMessage(BasicMessageConsumer_0_10.java:167)
> {noformat}
> Its seems odd that ConcurrentLinkedQueue.remove() call could be occupying the Dispatcher thread for 3 out of 3 samples.
> I will attach the complete stack trace.
> After restarting the application it again returns to its normal high message-rate/low CPU behaviour.

--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira

        

---------------------------------------------------------------------
Apache Qpid - AMQP Messaging Implementation
Project:      http://qpid.apache.org
Use/Interact: mailto:dev-subscribe@qpid.apache.org


[jira] [Commented] (QPID-3567) CPU util slowly increases/consumer rate reduced with Java Client

Posted by "David Kellum (Commented) (JIRA)" <ji...@apache.org>.
    [ https://issues.apache.org/jira/browse/QPID-3567?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13140588#comment-13140588 ] 

David Kellum commented on QPID-3567:
------------------------------------

I did not see this problem with the 0.8 java client and very little else has changed for this application. I will try rolling back to that version and seeing if the problem can still be reproduced.  I might also try 0.10.
                
> CPU util slowly increases/consumer rate reduced with Java Client
> ----------------------------------------------------------------
>
>                 Key: QPID-3567
>                 URL: https://issues.apache.org/jira/browse/QPID-3567
>             Project: Qpid
>          Issue Type: Bug
>          Components: Java Client
>    Affects Versions: 0.12
>         Environment: java version "1.6.0_26"
> Java(TM) SE Runtime Environment (build 1.6.0_26-b03)
> Java HotSpot(TM) 64-Bit Server VM (build 20.1-b02, mixed mode)
> RHEL 5.6
> Broker: qpidd (qpidc) version 0.8
>            Reporter: David Kellum
>         Attachments: qpid-0.12-stack-samples.txt
>
>
> For several hours on initial startup, a single threaded Java consumer application processes about 120 message/sec using only ~4% of a CPU.  But CPU gradually increases and eventually impedes message consumption rate. 
> At this last instance I caught it utilizing 90% CPU while consumption rate had dropped to 20 messages/sec (queue filling up.) Before restaring:
> * Checked GC: nothing unusual, very little time spent in collections.
> * Took a series of stack samples, which all have the following suspect runnable thread in the same location:
> {noformat} 
> "Dispatcher-Channel-0" daemon prio=10 tid=0x00002aaab0998000 nid=0x3384 runnable [0x0000000041f5e000]
>    java.lang.Thread.State: RUNNABLE
> 	at java.util.concurrent.ConcurrentLinkedQueue.remove(ConcurrentLinkedQueue.java:432)
> 	at org.apache.qpid.client.AMQSession_0_10.acknowledgeMessage(AMQSession_0_10.java:259)
> 	at org.apache.qpid.client.BasicMessageConsumer.postDeliver(BasicMessageConsumer.java:796)
> 	at org.apache.qpid.client.BasicMessageConsumer_0_10.postDeliver(BasicMessageConsumer_0_10.java:448)
> 	at org.apache.qpid.client.BasicMessageConsumer.notifyMessage(BasicMessageConsumer.java:726)
> 	at org.apache.qpid.client.BasicMessageConsumer_0_10.notifyMessage(BasicMessageConsumer_0_10.java:167)
> {noformat}
> Its seems odd that ConcurrentLinkedQueue.remove() call could be occupying the Dispatcher thread for 3 out of 3 samples.
> I will attach the complete stack trace.
> After restarting the application it again returns to its normal high message-rate/low CPU behaviour.

--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira

        

---------------------------------------------------------------------
Apache Qpid - AMQP Messaging Implementation
Project:      http://qpid.apache.org
Use/Interact: mailto:dev-subscribe@qpid.apache.org


[jira] [Resolved] (QPID-3567) CPU util slowly increases/consumer rate reduced with Java Client

Posted by "Robbie Gemmell (Resolved) (JIRA)" <ji...@apache.org>.
     [ https://issues.apache.org/jira/browse/QPID-3567?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Robbie Gemmell resolved QPID-3567.
----------------------------------

    Resolution: Cannot Reproduce
    
> CPU util slowly increases/consumer rate reduced with Java Client
> ----------------------------------------------------------------
>
>                 Key: QPID-3567
>                 URL: https://issues.apache.org/jira/browse/QPID-3567
>             Project: Qpid
>          Issue Type: Bug
>          Components: Java Client
>    Affects Versions: 0.12
>         Environment: java version "1.6.0_26"
> Java(TM) SE Runtime Environment (build 1.6.0_26-b03)
> Java HotSpot(TM) 64-Bit Server VM (build 20.1-b02, mixed mode)
> RHEL 5.6
> Broker: qpidd (qpidc) version 0.8
>            Reporter: David Kellum
>         Attachments: qpid-0.12-stack-samples.txt
>
>
> For several hours on initial startup, a single threaded Java consumer application processes about 120 message/sec using only ~4% of a CPU.  But CPU gradually increases and eventually impedes message consumption rate. 
> At this last instance I caught it utilizing 90% CPU while consumption rate had dropped to 20 messages/sec (queue filling up.) Before restaring:
> * Checked GC: nothing unusual, very little time spent in collections.
> * Took a series of stack samples, which all have the following suspect runnable thread in the same location:
> {noformat} 
> "Dispatcher-Channel-0" daemon prio=10 tid=0x00002aaab0998000 nid=0x3384 runnable [0x0000000041f5e000]
>    java.lang.Thread.State: RUNNABLE
> 	at java.util.concurrent.ConcurrentLinkedQueue.remove(ConcurrentLinkedQueue.java:432)
> 	at org.apache.qpid.client.AMQSession_0_10.acknowledgeMessage(AMQSession_0_10.java:259)
> 	at org.apache.qpid.client.BasicMessageConsumer.postDeliver(BasicMessageConsumer.java:796)
> 	at org.apache.qpid.client.BasicMessageConsumer_0_10.postDeliver(BasicMessageConsumer_0_10.java:448)
> 	at org.apache.qpid.client.BasicMessageConsumer.notifyMessage(BasicMessageConsumer.java:726)
> 	at org.apache.qpid.client.BasicMessageConsumer_0_10.notifyMessage(BasicMessageConsumer_0_10.java:167)
> {noformat}
> Its seems odd that ConcurrentLinkedQueue.remove() call could be occupying the Dispatcher thread for 3 out of 3 samples.
> I will attach the complete stack trace.
> After restarting the application it again returns to its normal high message-rate/low CPU behaviour.

--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira

        

---------------------------------------------------------------------
Apache Qpid - AMQP Messaging Implementation
Project:      http://qpid.apache.org
Use/Interact: mailto:dev-subscribe@qpid.apache.org


[jira] [Issue Comment Edited] (QPID-3567) CPU util slowly increases/consumer rate reduced with Java Client

Posted by "David Kellum (Issue Comment Edited) (JIRA)" <ji...@apache.org>.
    [ https://issues.apache.org/jira/browse/QPID-3567?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13216602#comment-13216602 ] 

David Kellum edited comment on QPID-3567 at 2/26/12 1:30 AM:
-------------------------------------------------------------

FWIW, We have not seen this issue with our applications again. It may be worth noting:

1. We were previously "double" acknowledging, i.e. explicitly calling acknowledge while auto acknowledge was also enabled. We have since changed to only do one or the other.

2. When originally observed we were still on qpidc 0.8 broker. We have since upgraded to 0.12.

We have just started to use 0.14 broker and client (for another app, actually) and have not seen any similar problem with that (though again, we avoid double ack.)

So I'm not sure what combination of factors lead to the issue originally, but I suspect upgrades and single acknowledgement is at least an adequate workaround.  

                
      was (Author: dekellum):
    FWIW, We have not seen this issue with our applications again. It may be worth nothing that:

1. We were previously "double acknowledging", i.e. explicit calling acknowledge while auto acknowledge was also enabled. We have since changed to only do one or the other.

2. When originally observed we were still on qpidc 0.8 broker. We have since upgraded to 0.12.

We have just started to use 0.14 broker and client (for another app, actually) and have not seen any similar problem with that (though again, we avoid double ack.)

So I'm not sure what combination of factors lead to the issue originally, but I suspect upgrades and single acknowledgement is at least an adequate workaround.  


                  
> CPU util slowly increases/consumer rate reduced with Java Client
> ----------------------------------------------------------------
>
>                 Key: QPID-3567
>                 URL: https://issues.apache.org/jira/browse/QPID-3567
>             Project: Qpid
>          Issue Type: Bug
>          Components: Java Client
>    Affects Versions: 0.12
>         Environment: java version "1.6.0_26"
> Java(TM) SE Runtime Environment (build 1.6.0_26-b03)
> Java HotSpot(TM) 64-Bit Server VM (build 20.1-b02, mixed mode)
> RHEL 5.6
> Broker: qpidd (qpidc) version 0.8
>            Reporter: David Kellum
>         Attachments: qpid-0.12-stack-samples.txt
>
>
> For several hours on initial startup, a single threaded Java consumer application processes about 120 message/sec using only ~4% of a CPU.  But CPU gradually increases and eventually impedes message consumption rate. 
> At this last instance I caught it utilizing 90% CPU while consumption rate had dropped to 20 messages/sec (queue filling up.) Before restaring:
> * Checked GC: nothing unusual, very little time spent in collections.
> * Took a series of stack samples, which all have the following suspect runnable thread in the same location:
> {noformat} 
> "Dispatcher-Channel-0" daemon prio=10 tid=0x00002aaab0998000 nid=0x3384 runnable [0x0000000041f5e000]
>    java.lang.Thread.State: RUNNABLE
> 	at java.util.concurrent.ConcurrentLinkedQueue.remove(ConcurrentLinkedQueue.java:432)
> 	at org.apache.qpid.client.AMQSession_0_10.acknowledgeMessage(AMQSession_0_10.java:259)
> 	at org.apache.qpid.client.BasicMessageConsumer.postDeliver(BasicMessageConsumer.java:796)
> 	at org.apache.qpid.client.BasicMessageConsumer_0_10.postDeliver(BasicMessageConsumer_0_10.java:448)
> 	at org.apache.qpid.client.BasicMessageConsumer.notifyMessage(BasicMessageConsumer.java:726)
> 	at org.apache.qpid.client.BasicMessageConsumer_0_10.notifyMessage(BasicMessageConsumer_0_10.java:167)
> {noformat}
> Its seems odd that ConcurrentLinkedQueue.remove() call could be occupying the Dispatcher thread for 3 out of 3 samples.
> I will attach the complete stack trace.
> After restarting the application it again returns to its normal high message-rate/low CPU behaviour.

--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira

        

---------------------------------------------------------------------
Apache Qpid - AMQP Messaging Implementation
Project:      http://qpid.apache.org
Use/Interact: mailto:dev-subscribe@qpid.apache.org


[jira] [Updated] (QPID-3567) CPU util slowly increases/consumer rate reduced with Java Client

Posted by "David Kellum (Updated) (JIRA)" <ji...@apache.org>.
     [ https://issues.apache.org/jira/browse/QPID-3567?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

David Kellum updated QPID-3567:
-------------------------------

    Attachment: qpid-0.12-stack-samples.txt

Here is full stack traces for three consecutive samples.
                
> CPU util slowly increases/consumer rate reduced with Java Client
> ----------------------------------------------------------------
>
>                 Key: QPID-3567
>                 URL: https://issues.apache.org/jira/browse/QPID-3567
>             Project: Qpid
>          Issue Type: Bug
>          Components: Java Client
>    Affects Versions: 0.12
>         Environment: java version "1.6.0_26"
> Java(TM) SE Runtime Environment (build 1.6.0_26-b03)
> Java HotSpot(TM) 64-Bit Server VM (build 20.1-b02, mixed mode)
> RHEL 5.6
> Broker: qpidd (qpidc) version 0.8
>            Reporter: David Kellum
>         Attachments: qpid-0.12-stack-samples.txt
>
>
> For several hours on initial startup, a single threaded Java consumer application processes about 120 message/sec using only ~4% of a CPU.  But CPU gradually increases and eventually impedes message consumption rate. 
> At this last instance I caught it utilizing 90% CPU while consumption rate had dropped to 20 messages/sec (queue filling up.) Before restaring:
> * Checked GC: nothing unusual, very little time spent in collections.
> * Took a series of stack samples, which all have the following suspect runnable thread in the same location:
> {noformat} 
> "Dispatcher-Channel-0" daemon prio=10 tid=0x00002aaab0998000 nid=0x3384 runnable [0x0000000041f5e000]
>    java.lang.Thread.State: RUNNABLE
> 	at java.util.concurrent.ConcurrentLinkedQueue.remove(ConcurrentLinkedQueue.java:432)
> 	at org.apache.qpid.client.AMQSession_0_10.acknowledgeMessage(AMQSession_0_10.java:259)
> 	at org.apache.qpid.client.BasicMessageConsumer.postDeliver(BasicMessageConsumer.java:796)
> 	at org.apache.qpid.client.BasicMessageConsumer_0_10.postDeliver(BasicMessageConsumer_0_10.java:448)
> 	at org.apache.qpid.client.BasicMessageConsumer.notifyMessage(BasicMessageConsumer.java:726)
> 	at org.apache.qpid.client.BasicMessageConsumer_0_10.notifyMessage(BasicMessageConsumer_0_10.java:167)
> {noformat}
> Its seems odd that ConcurrentLinkedQueue.remove() call could be occupying the Dispatcher thread for 3 out of 3 samples.
> I will attach the complete stack trace.
> After restarting the application it again returns to its normal high message-rate/low CPU behaviour.

--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira

        

---------------------------------------------------------------------
Apache Qpid - AMQP Messaging Implementation
Project:      http://qpid.apache.org
Use/Interact: mailto:dev-subscribe@qpid.apache.org


[jira] [Commented] (QPID-3567) CPU util slowly increases/consumer rate reduced with Java Client

Posted by "David Kellum (Commented) (JIRA)" <ji...@apache.org>.
    [ https://issues.apache.org/jira/browse/QPID-3567?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13216602#comment-13216602 ] 

David Kellum commented on QPID-3567:
------------------------------------

FWIW, We have not seen this issue with our applications again. It may be worth nothing that:

1. We were previously "double acknowledging", i.e. explicit calling acknowledge while auto acknowledge was also enabled. We have since changed to only do one or the other.

2. When originally observed we were still on qpidc 0.8 broker. We have since upgraded to 0.12.

We have just started to use 0.14 broker and client (for another app, actually) and have not seen any similar problem with that (though again, we avoid double ack.)

So I'm not sure what combination of factors lead to the issue originally, but I suspect upgrades and single acknowledgement is at least an adequate workaround.  


                
> CPU util slowly increases/consumer rate reduced with Java Client
> ----------------------------------------------------------------
>
>                 Key: QPID-3567
>                 URL: https://issues.apache.org/jira/browse/QPID-3567
>             Project: Qpid
>          Issue Type: Bug
>          Components: Java Client
>    Affects Versions: 0.12
>         Environment: java version "1.6.0_26"
> Java(TM) SE Runtime Environment (build 1.6.0_26-b03)
> Java HotSpot(TM) 64-Bit Server VM (build 20.1-b02, mixed mode)
> RHEL 5.6
> Broker: qpidd (qpidc) version 0.8
>            Reporter: David Kellum
>         Attachments: qpid-0.12-stack-samples.txt
>
>
> For several hours on initial startup, a single threaded Java consumer application processes about 120 message/sec using only ~4% of a CPU.  But CPU gradually increases and eventually impedes message consumption rate. 
> At this last instance I caught it utilizing 90% CPU while consumption rate had dropped to 20 messages/sec (queue filling up.) Before restaring:
> * Checked GC: nothing unusual, very little time spent in collections.
> * Took a series of stack samples, which all have the following suspect runnable thread in the same location:
> {noformat} 
> "Dispatcher-Channel-0" daemon prio=10 tid=0x00002aaab0998000 nid=0x3384 runnable [0x0000000041f5e000]
>    java.lang.Thread.State: RUNNABLE
> 	at java.util.concurrent.ConcurrentLinkedQueue.remove(ConcurrentLinkedQueue.java:432)
> 	at org.apache.qpid.client.AMQSession_0_10.acknowledgeMessage(AMQSession_0_10.java:259)
> 	at org.apache.qpid.client.BasicMessageConsumer.postDeliver(BasicMessageConsumer.java:796)
> 	at org.apache.qpid.client.BasicMessageConsumer_0_10.postDeliver(BasicMessageConsumer_0_10.java:448)
> 	at org.apache.qpid.client.BasicMessageConsumer.notifyMessage(BasicMessageConsumer.java:726)
> 	at org.apache.qpid.client.BasicMessageConsumer_0_10.notifyMessage(BasicMessageConsumer_0_10.java:167)
> {noformat}
> Its seems odd that ConcurrentLinkedQueue.remove() call could be occupying the Dispatcher thread for 3 out of 3 samples.
> I will attach the complete stack trace.
> After restarting the application it again returns to its normal high message-rate/low CPU behaviour.

--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira

        

---------------------------------------------------------------------
Apache Qpid - AMQP Messaging Implementation
Project:      http://qpid.apache.org
Use/Interact: mailto:dev-subscribe@qpid.apache.org