Bug 450202 - When doing small transactions the sync operations times out waitihg for a response from the broker
When doing small transactions the sync operations times out waitihg for a res...
Status: CLOSED CURRENTRELEASE
Product: Red Hat Enterprise MRG
Classification: Red Hat
Component: qpid-cpp (Show other bugs)
beta
All Linux
urgent Severity high
: ---
: ---
Assigned To: Gordon Sim
Kim van der Riet
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2008-06-05 17:04 EDT by Rajith Attapattu
Modified: 2009-05-07 16:09 EDT (History)
2 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2008-12-02 11:06:22 EST
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Description Rajith Attapattu 2008-06-05 17:04:38 EDT
When doing small transactions, the java client times out waiting for a response
from the c++ broker.
Using qpid-queue-stats tool I could see that the client does consume a few
messages transactionally and then at one point when it does a sync after sending
a commit, the broker fails to respond in a timely manner.

     [java] java.lang.RuntimeException: timed out waiting for sync
     [java]     at org.apache.qpidity.transport.Session.sync(Session.java:334)
     [java]     at org.apache.qpidity.transport.Session.sync(Session.java:293)
     [java]     at
org.apache.qpidity.nclient.impl.ClientSession.sync(ClientSession.java:107)
     [java]     at
org.apache.qpid.client.AMQSession_0_10.sendCommit(AMQSession_0_10.java:225)
     [java]     at
org.apache.qpid.client.AMQSession_0_10.commit(AMQSession_0_10.java:770)
     [java]     at
org.jboss.jms.example.PerfExample$PerfListener.checkCommit(PerfExample.java:344)
     [java]     at
org.jboss.jms.example.PerfExample$PerfListener.onMessage(PerfExample.java:317)
     [java]     at
org.apache.qpid.client.BasicMessageConsumer.notifyMessage(BasicMessageConsumer.java:688)
     [java]     at
org.apache.qpid.client.BasicMessageConsumer_0_10.notifyMessage(BasicMessageConsumer_0_10.java:151)
     [java]     at
org.apache.qpid.client.BasicMessageConsumer.notifyMessage(BasicMessageConsumer.java:647)
     [java]     at
org.apache.qpid.client.BasicMessageConsumer_0_10.notifyMessage(BasicMessageConsumer_0_10.java:259)
     [java]     at
org.apache.qpid.client.AMQSession$Dispatcher.dispatchMessage(AMQSession.java:2848)
     [java]     at
org.apache.qpid.client.AMQSession$Dispatcher.run(AMQSession.java:2770)
Comment 1 Gordon Sim 2008-06-08 09:04:51 EDT
The following extract from
amd-38.coe.lga.redhat.com:/home/rajith/qpid/cpp/broker.log suggests that the
broker did respond with a completed:

63868:2008-jun-06 12:58:43 trace SENT [10.15.60.33:55383]: Frame[BEbe;
channel=1; {SessionCompletedBody: commands={ [0,1348] }; }]
64517:2008-jun-06 12:58:43 trace RECV [10.15.60.33:55383]: Frame[BEbe;
channel=1; {SessionCompletedBody: commands={ [780,1334] }; }]
64518:2008-jun-06 12:58:43 trace RECV [10.15.60.33:55383]: Frame[BEbe;
channel=1; {MessageAcceptBody: transfers={ [1333,1334] }; }]
64519:2008-jun-06 12:58:43 trace SENT [10.15.60.33:55383]: Frame[Bbe; channel=1;
{MessageTransferBody: destination=1; accept-mode=0; acquire-mode=0; }]
64520:2008-jun-06 12:58:43 trace SENT [10.15.60.33:55383]: Frame[be; channel=1;
header (110 bytes); properties={{MessageProperties: content-length=1024;
message-id=5c783b76-ec0a-4ece-97e5-fdebe2bd36cc;
content-type=application/octet-stream; application-headers={};
}{DeliveryProperties: priority=0; delivery-mode=2; timestamp=1212771506401;
expiration=0; exchange=amq.direct; routing-key=MyQueue; }}]
64521:2008-jun-06 12:58:43 trace SENT [10.15.60.33:55383]: Frame[Ebe; channel=1;
content (1024 bytes) \00\00\00\00\00\00\00\00\00\00\00\00\00\00\00\00...]
64522:2008-jun-06 12:58:43 trace SENT [10.15.60.33:55383]: Frame[Bbe; channel=1;
{MessageTransferBody: destination=1; accept-mode=0; acquire-mode=0; }]
64523:2008-jun-06 12:58:43 trace SENT [10.15.60.33:55383]: Frame[be; channel=1;
header (110 bytes); properties={{MessageProperties: content-length=1024;
message-id=aea20ee6-4da2-42f5-9fa0-f58084ea56ab;
content-type=application/octet-stream; application-headers={};
}{DeliveryProperties: priority=0; delivery-mode=2; timestamp=1212771506404;
expiration=0; exchange=amq.direct; routing-key=MyQueue; }}]
64524:2008-jun-06 12:58:43 trace SENT [10.15.60.33:55383]: Frame[Ebe; channel=1;
content (1024 bytes) \00\00\00\00\00\00\00\00\00\00\00\00\00\00\00\00...]
64525:2008-jun-06 12:58:43 trace RECV [10.15.60.33:55383]: Frame[BEbe;
channel=1; {TxCommitBody: }]
64527:2008-jun-06 12:58:43 trace SENT [10.15.60.33:55383]: Frame[BEbe;
channel=1; {SessionCompletedBody: commands={ [0,1350] }; }]
251804:2008-jun-06 12:59:43 trace RECV [10.15.60.33:55383]: Frame[BEbe;
channel=1; {SessionCompletedBody: commands={ [780,1336] }; }]
251805:2008-jun-06 12:59:43 trace SENT [10.15.60.33:55383]: Frame[Bbe;
channel=1; {MessageTransferBody: destination=1; accept-mode=0; acquire-mode=0; }]
Comment 2 Gordon Sim 2008-06-11 03:47:10 EDT
This turned out to be due to an OOM error on the java client that was being
swallowed and prevented the IO thread from continuing. That in turn was due to a
very large buffer being created for each message (2M even though only 1k was
used). This meant the incoming, unprocessed message queue was very large (up to
1000 messages of 2M each!). The issue has been resolved by setting a lower
default maximum size which can still be overridden.

Comment 3 Mike Bonnet 2008-06-19 23:53:14 EDT
qpidc-0.2.667603-1.el5, qpidc-perftest-0.2.667603-1.el5, qpidd-0.2.667603-1.el5, and rhm-0.2.2153-1.el5 have been pushed to the staging repo for testing

Note You need to log in before you can comment on or make changes to this bug.