Bug 450202 - When doing small transactions the sync operations times out waitihg for a response from the broker
Summary: When doing small transactions the sync operations times out waitihg for a res...
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Red Hat Enterprise MRG
Classification: Red Hat
Component: qpid-cpp
Version: beta
Hardware: All
OS: Linux
urgent
high
Target Milestone: ---
: ---
Assignee: Gordon Sim
QA Contact: Kim van der Riet
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2008-06-05 21:04 UTC by Rajith Attapattu
Modified: 2009-05-07 20:09 UTC (History)
2 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2008-12-02 16:06:22 UTC
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)

Description Rajith Attapattu 2008-06-05 21:04:38 UTC
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 13:04:51 UTC
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 07:47:10 UTC
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-20 03:53:14 UTC
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.