Uploaded image for project: 'Qpid'
  1. Qpid
  2. QPID-6863

AMQP 1.0 message flow to consumers stops

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Closed
    • Major
    • Resolution: Invalid
    • qpid-java-6.0
    • None
    • Broker-J
    • None

    Description

      I am seeing an issue whilst running the Java perf tests (transient/autoack plain) where the flow of messages to the participant consumers is seen to stop. The problem manifests for me for at around the 32768 flow rate..

      The Broker seems to indicate that flow to all queues is suspended (indicated by a succession of SUB-1003 messages with times steadily increasing). The participant producers continue to fill the Broker, which eventually runs out of direct memory.

      To reproduce I am running with QPID-6852 applied and a local change to perftests/etc/testdefs/defaultTests.js to run only the second test. Test fails after about 1 min.

           mvn -f perftests/pom.xml -Dclient=qpid-jms-client exec:java -Dqpid.disttest.hillclimb=true -Dqpid.disttest.duration=20000 -Dqpid.disttest.hillclimb.start_target_rate=16384 -Dqpid.disttest.loglevel=debug

      2015-11-17 07:32:00,881 INFO  [IO-/127.0.0.1:57540] (q.m.s.state) - [IO Pool] [sub:108(vh(/default)/qu(testQueue_7)] SUB-1003 : Suspended for 10,059 ms
2015-11-17 07:32:04,071 INFO  [IO-/127.0.0.1:57542] (q.m.s.state) - [IO Pool] [sub:109(vh(/default)/qu(testQueue_8)] SUB-1003 : Suspended for 10,000 ms
2015-11-17 07:32:04,604 INFO  [IO-/127.0.0.1:57539] (q.m.q.flow_to_disk_active) - [con:75(guest@/127.0.0.1:57539/default)/ch:1] [vh(/default)/qu(testQueue_7)] QUE-1014 : Message flow to disk active :  Message memory use 46277632 kB exceeds threshold 46277154 kB
2015-11-17 07:32:07,704 INFO  [IO-/127.0.0.1:57541] (q.m.q.flow_to_disk_active) - [con:77(guest@/127.0.0.1:57541/default)/ch:1] [vh(/default)/qu(testQueue_8)] QUE-1014 : Message flow to disk active :  Message memory use 46277632 kB exceeds threshold 46277154 kB
2015-11-17 07:32:09,001 INFO  [VirtualHostNode-default-Config] (q.m.s.close) - [con:66(guest@/127.0.0.1:57530/default)/ch:1] [sub:103(vh(/default)/qu(testQueue_2)] SUB-1002 : Close
2015-11-17 07:32:09,112 INFO  [VirtualHostNode-default-Config] (q.m.s.close) - [con:80(guest@/127.0.0.1:57544/default)/ch:1] [sub:110(vh(/default)/qu(testQueue_9)] SUB-1002 : Close
2015-11-17 07:32:09,140 INFO  [VirtualHostNode-default-Config] (q.m.s.close) - [con:64(guest@/127.0.0.1:57528/default)/ch:1] [sub:102(vh(/default)/qu(testQueue_1)] SUB-1002 : Close
2015-11-17 07:32:09,205 INFO  [VirtualHostNode-default-Config] (q.m.s.close) - [con:72(guest@/127.0.0.1:57536/default)/ch:1] [sub:106(vh(/default)/qu(testQueue_5)] SUB-1002 : Close
2015-11-17 07:32:09,314 INFO  [VirtualHostNode-default-Config] (q.m.s.close) - [con:70(guest@/127.0.0.1:57534/default)/ch:1] [sub:105(vh(/default)/qu(testQueue_4)] SUB-1002 : Close
2015-11-17 07:32:09,316 INFO  [VirtualHostNode-default-Config] (q.m.s.close) - [con:68(guest@/127.0.0.1:57532/default)/ch:1] [sub:104(vh(/default)/qu(testQueue_3)] SUB-1002 : Close
2015-11-17 07:32:09,353 INFO  [VirtualHostNode-default-Config] (q.m.s.close) - [con:62(guest@/127.0.0.1:57526/default)/ch:1] [sub:101(vh(/default)/qu(testQueue_0)] SUB-1002 : Close
2015-11-17 07:32:10,581 INFO  [IO-/127.0.0.1:57541] (q.m.q.flow_to_disk_inactive) - [con:77(guest@/127.0.0.1:57541/default)/ch:1] [vh(/default)/qu(testQueue_8)] QUE-1015 : Message flow to disk inactive : Message memory use 50240512 kB within threshold 456207857 kB
2015-11-17 07:32:10,581 INFO  [IO-/127.0.0.1:57539] (q.m.q.flow_to_disk_inactive) - [con:75(guest@/127.0.0.1:57539/default)/ch:1] [vh(/default)/qu(testQueue_7)] QUE-1015 : Message flow to disk inactive : Message memory use 50536448 kB within threshold 458895152 kB
2015-11-17 07:32:10,813 INFO  [IO-/127.0.0.1:57540] (q.m.s.state) - [IO Pool] [sub:108(vh(/default)/qu(testQueue_7)] SUB-1003 : Suspended for 20,000 ms
2015-11-17 07:32:14,353 INFO  [IO-/127.0.0.1:57542] (q.m.s.state) - [IO Pool] [sub:109(vh(/default)/qu(testQueue_8)] SUB-1003 : Suspended for 20,282 ms
2015-11-17 07:32:15,206 INFO  [IO-/127.0.0.1:57538] (q.m.s.state) - [IO Pool] [sub:107(vh(/default)/qu(testQueue_6)] SUB-1003 : Suspended for 10,000 ms
2015-11-17 07:32:20,813 INFO  [IO-/127.0.0.1:57540] (q.m.s.state) - [IO Pool] [sub:108(vh(/default)/qu(testQueue_7)] SUB-1003 : Suspended for 30,000 ms
2015-11-17 07:32:24,071 INFO  [IO-/127.0.0.1:57542] (q.m.s.state) - [IO Pool] [sub:109(vh(/default)/qu(testQueue_8)] SUB-1003 : Suspended for 30,000 ms
2015-11-17 07:32:24,561 INFO  [IO-/127.0.0.1:57525] (q.m.q.flow_to_disk_active) - [con:61(guest@/127.0.0.1:57525/default)/ch:1] [vh(/default)/qu(testQueue_0)] QUE-1014 : Message flow to disk active :  Message memory use 50650112 kB exceeds threshold 50649468 kB
2015-11-17 07:32:25,209 INFO  [IO-/127.0.0.1:57538] (q.m.s.state) - [IO Pool] [sub:107(vh(/default)/qu(testQueue_6)] SUB-1003 : Suspended for 20,004 ms
2015-11-17 07:32:27,973 INFO  [IO-/127.0.0.1:57527] (q.m.q.flow_to_disk_active) - [con:63(guest@/127.0.0.1:57527/default)/ch:1] [vh(/default)/qu(testQueue_1)] QUE-1014 : Message flow to disk active :  Message memory use 55094272 kB exceeds threshold 55094198 kB
2015-11-17 07:32:28,589 INFO  [IO-/127.0.0.1:57543] (q.m.q.flow_to_disk_active) - [con:79(guest@/127.0.0.1:57543/default)/ch:1] [vh(/default)/qu(testQueue_9)] QUE-1014 : Message flow to disk active :  Message memory use 58702848 kB exceeds threshold 58702054 kB
2015-11-17 07:32:28,680 INFO  [IO-/127.0.0.1:57529] (q.m.q.flow_to_disk_active) - [con:65(guest@/127.0.0.1:57529/default)/ch:1] [vh(/default)/qu(testQueue_2)] QUE-1014 : Message flow to disk active :  Message memory use 58404864 kB exceeds threshold 58404499 kB
2015-11-17 07:32:29,293 INFO  [IO-/127.0.0.1:57531] (q.m.q.flow_to_disk_active) - [con:67(guest@/127.0.0.1:57531/default)/ch:1] [vh(/default)/qu(testQueue_3)] QUE-1014 : Message flow to disk active :  Message memory use 60897280 kB exceeds threshold 60896523 kB
2015-11-17 07:32:29,519 INFO  [IO-/127.0.0.1:57533] (q.m.q.flow_to_disk_active) - [con:69(guest@/127.0.0.1:57533/default)/ch:1] [vh(/default)/qu(testQueue_4)] QUE-1014 : Message flow to disk active :  Message memory use 61827072 kB exceeds threshold 61826383 kB

2015-11-17 07:32:30,440 INFO  [IO-/127.0.0.1:57535] (q.m.q.flow_to_disk_active) - [con:71(guest@/127.0.0.1:57535/default)/ch:1] [vh(/default)/qu(testQueue_5)] QUE-1014 : Message flow to disk active :  Message memory use 67294208 kB exceeds threshold 67293959 kB
2015-11-17 07:32:30,817 INFO  [IO-/127.0.0.1:57540] (q.m.s.state) - [IO Pool] [sub:108(vh(/default)/qu(testQueue_7)] SUB-1003 : Suspended for 40,004 ms
2015-11-17 07:32:34,072 INFO  [IO-/127.0.0.1:57542] (q.m.s.state) - [IO Pool] [sub:109(vh(/default)/qu(testQueue_8)] SUB-1003 : Suspended for 40,000 ms
2015-11-17 07:32:35,268 INFO  [IO-/127.0.0.1:57538] (q.m.s.state) - [IO Pool] [sub:107(vh(/default)/qu(testQueue_6)] SUB-1003 : Suspended for 30,062 ms
2015-11-17 07:32:40,955 INFO  [IO-/127.0.0.1:57540] (q.m.s.state) - [IO Pool] [sub:108(vh(/default)/qu(testQueue_7)] SUB-1003 : Suspended for 50,142 ms
2015-11-17 07:32:40,965 INFO  [IO-/127.0.0.1:57529] (q.m.q.flow_to_disk_inactive) - [con:65(guest@/127.0.0.1:57529/default)/ch:1] [vh(/default)/qu(testQueue_2)] QUE-1015 : Message flow to disk inactive : Message memory use 91884544 kB within threshold 136494259 kB
2015-11-17 07:32:40,965 INFO  [IO-/127.0.0.1:57533] (q.m.q.flow_to_disk_inactive) - [con:69(guest@/127.0.0.1:57533/default)/ch:1] [vh(/default)/qu(testQueue_4)] QUE-1015 : Message flow to disk inactive : Message memory use 92329984 kB within threshold 137155966 kB
2015-11-17 07:32:40,965 INFO  [IO-/127.0.0.1:57527] (q.m.q.flow_to_disk_inactive) - [con:63(guest@/127.0.0.1:57527/default)/ch:1] [vh(/default)/qu(testQueue_1)] QUE-1015 : Message flow to disk inactive : Message memory use 90429440 kB within threshold 134332681 kB
2015-11-17 07:32:40,965 INFO  [IO-/127.0.0.1:57543] (q.m.q.flow_to_disk_inactive) - [con:79(guest@/127.0.0.1:57543/default)/ch:1] [vh(/default)/qu(testQueue_9)] QUE-1015 : Message flow to disk inactive : Message memory use 91532288 kB within threshold 135970978 kB
2015-11-17 07:32:40,966 INFO  [IO-/127.0.0.1:57531] (q.m.q.flow_to_disk_inactive) - [con:67(guest@/127.0.0.1:57531/default)/ch:1] [vh(/default)/qu(testQueue_3)] QUE-1015 : Message flow to disk inactive : Message memory use 92062720 kB within threshold 136758942 kB
2015-11-17 07:32:40,968 INFO  [IO-/127.0.0.1:57535] (q.m.q.flow_to_disk_inactive) - [con:71(guest@/127.0.0.1:57535/default)/ch:1] [vh(/default)/qu(testQueue_5)] QUE-1015 : Message flow to disk inactive : Message memory use 93029376 kB within threshold 138194923 kB
2015-11-17 07:32:40,969 INFO  [IO-/127.0.0.1:57525] (q.m.q.flow_to_disk_inactive) - [con:61(guest@/127.0.0.1:57525/default)/ch:1] [vh(/default)/qu(testQueue_0)] QUE-1015 : Message flow to disk inactive : Message memory use 89222144 kB within threshold 132539226 kB
2015-11-17 07:32:44,071 INFO  [IO-/127.0.0.1:57542] (q.m.s.state) - [IO Pool] [sub:109(vh(/default)/qu(testQueue_8)] SUB-1003 : Suspended for 50,000 ms
2015-11-17 07:32:45,210 INFO  [IO-/127.0.0.1:57538] (q.m.s.state) - [IO Pool] [sub:107(vh(/default)/qu(testQueue_6)] SUB-1003 : Suspended for 40,004 ms
2015-11-17 07:32:50,897 INFO  [IO-/127.0.0.1:57540] (q.m.s.state) - [IO Pool] [sub:108(vh(/default)/qu(testQueue_7)] SUB-1003 : Suspended for 60,084 ms

      Attachments

        Issue Links

          relates to

          Bug - A problem which impairs or prevents the functions of the product. QPID-6947 [Java Broker] deliverycount advanced outside a previous drain attempt that used all credit

          • Major - Major loss of function.
          • Open

          Bug - A problem which impairs or prevents the functions of the product. PROTON-1077 receiver link and transport view of credit can become disjoint when sending link sends flow frames

          • Major - Major loss of function.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. QPIDJMS-139 Message flow to synchronous consumer from Qpid Java broker unexpectedly ceases

          • Major - Major loss of function.
          • Closed

          Activity

            People

              Unassigned Unassigned
              kwall Keith Wall
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: