11 Replies Latest reply on Jan 22, 2004 11:42 AM by eoin

    Consumer failing when MessageCache full? (3.0.8 200306050849

    eoin

       

      "eoin" wrote:
      I'm doing a load-test on my system, using JMS, with jdbc2 persistence (hsqldb). I have changed the messagecache to use 16m/32m memory limits. From a client i send messages onto one queue. In the server VM, I have a message consumer (not a mdb) which receives these messages and routes them to another queue.

      The problem is, after a while (presumably when the message cache hits some limit), this message appears in the log file. However, my consumer does not get any exception (I catch JMSException, which should catch SpyJMSException). Messages stop getting delivered to my consumer.

      2004-01-09 16:17:56,722 DEBUG [org.jboss.util.NestedThrowable] org.jboss.util.NestedThrowable.parentTraceEnabled=true
      2004-01-09 16:17:56,722 DEBUG [org.jboss.util.NestedThrowable] org.jboss.util.NestedThrowable.nestedTraceEnabled=false
      2004-01-09 16:17:56,723 DEBUG [org.jboss.util.NestedThrowable] org.jboss.util.NestedThrowable.detectDuplicateNesting=true
      2004-01-09 16:17:56,723 WARN [org.jboss.util.NestedThrowable] Duplicate throwable nesting of same base type: class org.jboss.mq.SpyJMSException is assignable from: class org.jbos
      s.mq.SpyJMSException
      2004-01-09 16:17:56,723 WARN [org.jboss.mq.SpyMessageConsumer] Message consumer closing due to error in listening thread.
      org.jboss.mq.SpyJMSException: Cannot acknowlege a message; - nested throwable: (org.jboss.mq.SpyJMSException: Could not delete the message from the database: delete affected 0 row
      s)
      at org.jboss.mq.Connection.send(Connection.java:901)
      at org.jboss.mq.SpySession.doAcknowledge(SpySession.java:601)
      at org.jboss.mq.SpyMessage.doAcknowledge(SpyMessage.java:537)
      at org.jboss.mq.SpyMessageConsumer.run(SpyMessageConsumer.java:568)
      at java.lang.Thread.run(Thread.java:534)
      Caused by: org.jboss.mq.SpyJMSException: Could not delete the message from the database: delete affected 0 rows
      at org.jboss.mq.pm.jdbc2.PersistenceManager.remove(PersistenceManager.java:937)
      at org.jboss.mq.server.BasicQueue.acknowledge(BasicQueue.java:402)
      at org.jboss.mq.server.JMSQueue.acknowledge(JMSQueue.java:114)
      at org.jboss.mq.server.ClientConsumer.acknowledge(ClientConsumer.java:324)
      at org.jboss.mq.server.JMSDestinationManager.acknowledge(JMSDestinationManager.java:520)
      at org.jboss.mq.server.JMSDestinationManager.acknowledge(JMSDestinationManager.java:504)
      at org.jboss.mq.server.JMSServerInterceptorSupport.acknowledge(JMSServerInterceptorSupport.java:197)
      at org.jboss.mq.server.TracingInterceptor.acknowledge(TracingInterceptor.java:404)
      at org.jboss.mq.server.JMSServerInvoker.acknowledge(JMSServerInvoker.java:199)
      at org.jboss.mq.il.jvm.JVMServerIL.acknowledge(JVMServerIL.java:215)
      at org.jboss.mq.Connection.send(Connection.java:897)
      ... 4 more
      2004-01-09 16:17:56,724 DEBUG [org.jboss.mq.SpyMessageConsumer] Message consumer closing.

      When the consumer eventually closes it's session, i get this exception:

      org.jboss.mq.SpyJMSException: Cannot acknowlege a message; - nested throwable: (javax.jms.JMSException: The provided subscription does not exist)
      at org.jboss.mq.Connection.send(Connection.java:901)
      at org.jboss.mq.SpySession.close(SpySession.java:379)
      at org.jboss.mq.Connection.close(Connection.java:464)
      at Router.stop(Router.java:225)
      ...
      Caused by: javax.jms.JMSException: The provided subscription does not exist
      at org.jboss.mq.server.ClientConsumer.acknowledge(ClientConsumer.java:317)
      at org.jboss.mq.server.JMSDestinationManager.acknowledge(JMSDestinationManager.java:520)
      at org.jboss.mq.server.JMSDestinationManager.acknowledge(JMSDestinationManager.java:504)
      at org.jboss.mq.server.JMSServerInterceptorSupport.acknowledge(JMSServerInterceptorSupport.java:197)
      at org.jboss.mq.server.TracingInterceptor.acknowledge(TracingInterceptor.java:404)
      at org.jboss.mq.server.JMSServerInvoker.acknowledge(JMSServerInvoker.java:199)
      at org.jboss.mq.il.jvm.JVMServerIL.acknowledge(JVMServerIL.java:215)
      at org.jboss.mq.Connection.send(Connection.java:897)
      ... 27 more

      I can't find any posts / bugs about the 'Could not delete the message from the database' error message, except this http://www.geocrawler.com/archives/3/10766/2002/5/200/8775758/ , which seems to be about a different issue (class circularity error).

      eoin.


        • 1. Re: Consumer failing when MessageCache full? (3.0.8 20030605
          genman

           

          "eoin" wrote:
          I have reproduced this problem with a simpler configuration. Using a standard distro of 3.0.8, i edited run.sh to set max mem at 256m, jbossmq-service.xml to set messagecache to 50/60 and to use jdbc2 persistence with default hypersonic configuration.

          In a standard 3.2.3 distro, i set max mem to 256m (the other settings are by default what i made for 3.0.8).

          Running both my sender and the receiver (which sends onto another queue) outside the server, i can reproduce this problem every time.

          When using 3.2.3 everything works as it should. Using 3.0.8, after the sender has sent about 51000 messages onto the queue A, and the receiver has received and re-sent about 27000 onto queue B. On the client, I get the exception logged, but not thrown to my code.

          Also, I ran the test on 3.0.8 with the default persistence file storage, without problem. Just in case, I also tried running 3.0.8 with the hsqldb.jar and hsqldb-plugin.jar from 3.2.3, but this actually just made the problem occur earlier (due to this hypersonic memory caching?).

          My test code follows.

          import javax.jms.*;
          import javax.naming.Context;
          import javax.naming.InitialContext;
          
          public class JBossBugTest
          {
           protected String connectionFactoryJndiName = "java:/ConnectionFactory";
           private QueueConnectionFactory factory;
           private Queue queueB;
           private Queue queueA;
          
           public static void main(String[] args)
           throws Exception
           {
           new JBossBugTest().runTest();
           }
          
           public void runTest() throws Exception
           {
           Context namespaceRoot = new InitialContext();
           factory = (QueueConnectionFactory) namespaceRoot.lookup(connectionFactoryJndiName);
           queueA = (Queue) namespaceRoot.lookup("queue/A");
           queueB = (Queue) namespaceRoot.lookup("queue/B");
          
           new Thread(new MySender()).start();
           new MyRouter().startRouting();
           }
          
           class MyRouter implements MessageListener
           {
           private QueueSender sender;
           int numReceived=0;
          
           public void startRouting() throws JMSException
           {
           QueueConnection queueConnection = factory.createQueueConnection();
           QueueSession queueSession = queueConnection.createQueueSession(false, Session.AUTO_ACKNOWLEDGE);
           QueueReceiver receiver = queueSession.createReceiver(queueA);
           sender = queueSession.createSender(queueB);
           receiver.setMessageListener(this);
           queueConnection.start();
           }
          
           public void onMessage(Message message)
           {
           try
           {
           sender.send(message);
           numReceived++;
           if((numReceived%1000)==0)
           {
           System.out.println("Have routed "+numReceived);
           }
           }
           catch (JMSException e)
           {
           e.printStackTrace();
           }
           }
           }
          
           class MySender implements Runnable
           {
           public void run()
           {
           try
           {
           QueueConnection queueConnection = factory.createQueueConnection();
           QueueSession queueSession = queueConnection.createQueueSession(false,Session.AUTO_ACKNOWLEDGE);
          
           QueueSender sender = queueSession.createSender(queueA);
          
           for(int j=1; j<=200; j++)
           {
           long start = System.currentTimeMillis();
           for(int i=0;i<1000;i++)
           {
           TextMessage textMessage = queueSession.createTextMessage(
          "Test message with some content."+
          " Test message with some content. Test message with some content."+
          " Test message with some content. Test message with some content."+
          " Test message with some content. "+i);
           sender.send(textMessage);
           }
           long end = System.currentTimeMillis();
           double throughput = 1000.0/((end-start)/1000.0);
           System.out.println("Sent "+(j*1000)+" at "+throughput+" per sec");
           }
          
           queueSession.close();
           queueConnection.close();
           }
           catch(Exception e)
           {
           e.printStackTrace();
           }
           }
           }
          }


          which on 3.0.8 produces the output (you can see that after the exception, the sending runs quicker since the receiver is not operational):

          ...(omitted)...
          Have routed 26000
          Sent 49000 at 649.3506493506493 per sec
          Sent 50000 at 413.5649296939619 per sec
          Have routed 27000
          Sent 51000 at 697.350069735007 per sec
          - Duplicate throwable nesting of same base type: class org.jboss.mq.SpyJMSException is assignable from: class org.jboss.mq.SpyJMSException
          - Message consumer closing due to error in listening thread.
          org.jboss.mq.SpyJMSException: Cannot acknowlege a message; - nested throwable: (org.jboss.mq.SpyJMSException: Could not delete the message from the database: delete affected 0 rows)
           at org.jboss.mq.Connection.send(Connection.java:901)
           at org.jboss.mq.SpySession.doAcknowledge(SpySession.java:601)
           at org.jboss.mq.SpyMessage.doAcknowledge(SpyMessage.java:537)
           at org.jboss.mq.SpyMessageConsumer.run(SpyMessageConsumer.java:568)
           at java.lang.Thread.run(Thread.java:534)
          Caused by: org.jboss.mq.SpyJMSException: Could not delete the message from the database: delete affected 0 rows
           at org.jboss.mq.pm.jdbc2.PersistenceManager.remove(PersistenceManager.java:937)
           at org.jboss.mq.server.BasicQueue.acknowledge(BasicQueue.java:402)
           at org.jboss.mq.server.JMSQueue.acknowledge(JMSQueue.java:114)
           at org.jboss.mq.server.ClientConsumer.acknowledge(ClientConsumer.java:324)
           at org.jboss.mq.server.JMSDestinationManager.acknowledge(JMSDestinationManager.java:520)
           at org.jboss.mq.server.JMSDestinationManager.acknowledge(JMSDestinationManager.java:504)
           at org.jboss.mq.server.JMSServerInterceptorSupport.acknowledge(JMSServerInterceptorSupport.java:197)
           at org.jboss.mq.server.TracingInterceptor.acknowledge(TracingInterceptor.java:404)
           at org.jboss.mq.server.JMSServerInvoker.acknowledge(JMSServerInvoker.java:199)
           at org.jboss.mq.il.oil.OILServerILService$Client.run(OILServerILService.java:244)
           ... 1 more
          Sent 52000 at 799.3605115907275 per sec
          Sent 53000 at 1193.3174224343677 per sec
          ...(omitted)...
          


          I am going to migrate our software to using 3.2.3, but I would like to find out what is causing this problem (i.e. am I misusing the JMS somehow)?

          regards,

          eoin.


          • 2. Re: Consumer failing when MessageCache full? (3.0.8 20030605
            genman

             

            "genman" wrote:

            The message cache settings seem a bit low, especially if the server itself uses more than 32MB of memory without any messages on it. You should be running JBoss with 256MB of memory (use the JVM setting -Xmx256MB) and a higher cache setting. If that doesn't help, post a test case. Since we don't know what's going on in your client code, we're not sure it's a problem with your client code or not.


            • 3. Re: Consumer failing when MessageCache full? (3.0.8 20030605
              eoin

               

              "eoin" wrote:
              I was experimenting with the messageCache settings, since in this test, I was hitting the same problem eventually even if it's set to 500/600. So this doesn't change things, it just makes the problem happen a bit faster. (I had -Xmx set high)

              I have run again, with -Xmx 600000000, and MessageCache set to 128 and 160. I get the same problem (eventually).

              The bit of code that routes messages from one queue to another looks basically like this (pseudo code). The code usually has multiple destination queues, but in this test i just have one. This code is run in-vm (i.e. uses the JVM IL, or java:/ConnectionFactory):

              <pre>
              queueConnection = queueConnectionFactory.createQueueConnection();
              session = queueConnection.createQueueSession(false, Session.AUTO_ACKNOWLEDGE);
              queueReceiver = session.createReceiver(incomingQueue);
              queueSender = session.createSender(outgoingQueue);
              queueReceiver.setMessageListener(myListener);
              connection.start();

              myListener
              {
              onMessage(message)
              {
              try
              {
              queueSender.send(message);
              }
              catch(JMSException jmse) { close(); }
              }
              }
              </pre>

              The client sending the messages is outside the VM, and uses an auto-acknowledge session to send messages onto the queue.

              Having a look at the SpyConsumer source, the exception is happening when it tries to acknowledge the message after my onMessage(), which is why i don't see an exception. I can't see any way to be notified that the listener thread has closed - unless i change to receiving and acknowledge the messages myself?

              I resend the message supplied to the event handler. I suspected this might be causing a problem, but changing it to send a copy of the message object did not help.

              I can put together a test case, but it will take a little while. Do you have a standard way to package test cases (i.e. the test code together with the service.xml, war files etc. that it runs against)?

              I suppose I should also try the test against a version of jboss from the 3.2.x branch? (although i'd like to avoid upgrading at the moment)


              eoin.


              • 4. Re: Consumer failing when MessageCache full? (3.0.8 20030605
                eoin

                 

                "eoin" wrote:
                I have reproduced this problem with a simpler configuration. Using a standard distro of 3.0.8, i edited run.sh to set max mem at 256m, jbossmq-service.xml to set messagecache to 50/60 and to use jdbc2 persistence with default hypersonic configuration.

                In a standard 3.2.3 distro, i set max mem to 256m (the other settings are by default what i made for 3.0.8).

                Running both my sender and the receiver (which sends onto another queue) outside the server, i can reproduce this problem every time.

                When using 3.2.3 everything works as it should. Using 3.0.8, after the sender has sent about 51000 messages onto the queue A, and the receiver has received and re-sent about 27000 onto queue B. On the client, I get the exception logged, but not thrown to my code.

                Also, I ran the test on 3.0.8 with the default persistence file storage, without problem. Just in case, I also tried running 3.0.8 with the hsqldb.jar and hsqldb-plugin.jar from 3.2.3, but this actually just made the problem occur earlier (due to this hypersonic memory caching?).

                My test code follows.

                import javax.jms.*;
                import javax.naming.Context;
                import javax.naming.InitialContext;
                
                public class JBossBugTest
                {
                 protected String connectionFactoryJndiName = "java:/ConnectionFactory";
                 private QueueConnectionFactory factory;
                 private Queue queueB;
                 private Queue queueA;
                
                 public static void main(String[] args)
                 throws Exception
                 {
                 new JBossBugTest().runTest();
                 }
                
                 public void runTest() throws Exception
                 {
                 Context namespaceRoot = new InitialContext();
                 factory = (QueueConnectionFactory) namespaceRoot.lookup(connectionFactoryJndiName);
                 queueA = (Queue) namespaceRoot.lookup("queue/A");
                 queueB = (Queue) namespaceRoot.lookup("queue/B");
                
                 new Thread(new MySender()).start();
                 new MyRouter().startRouting();
                 }
                
                 class MyRouter implements MessageListener
                 {
                 private QueueSender sender;
                 int numReceived=0;
                
                 public void startRouting() throws JMSException
                 {
                 QueueConnection queueConnection = factory.createQueueConnection();
                 QueueSession queueSession = queueConnection.createQueueSession(false, Session.AUTO_ACKNOWLEDGE);
                 QueueReceiver receiver = queueSession.createReceiver(queueA);
                 sender = queueSession.createSender(queueB);
                 receiver.setMessageListener(this);
                 queueConnection.start();
                 }
                
                 public void onMessage(Message message)
                 {
                 try
                 {
                 sender.send(message);
                 numReceived++;
                 if((numReceived%1000)==0)
                 {
                 System.out.println("Have routed "+numReceived);
                 }
                 }
                 catch (JMSException e)
                 {
                 e.printStackTrace();
                 }
                 }
                 }
                
                 class MySender implements Runnable
                 {
                 public void run()
                 {
                 try
                 {
                 QueueConnection queueConnection = factory.createQueueConnection();
                 QueueSession queueSession = queueConnection.createQueueSession(false,Session.AUTO_ACKNOWLEDGE);
                
                 QueueSender sender = queueSession.createSender(queueA);
                
                 for(int j=1; j<=200; j++)
                 {
                 long start = System.currentTimeMillis();
                 for(int i=0;i<1000;i++)
                 {
                 TextMessage textMessage = queueSession.createTextMessage(
                "Test message with some content."+
                " Test message with some content. Test message with some content."+
                " Test message with some content. Test message with some content."+
                " Test message with some content. "+i);
                 sender.send(textMessage);
                 }
                 long end = System.currentTimeMillis();
                 double throughput = 1000.0/((end-start)/1000.0);
                 System.out.println("Sent "+(j*1000)+" at "+throughput+" per sec");
                 }
                
                 queueSession.close();
                 queueConnection.close();
                 }
                 catch(Exception e)
                 {
                 e.printStackTrace();
                 }
                 }
                 }
                }


                which on 3.0.8 produces the output (you can see that after the exception, the sending runs quicker since the receiver is not operational):

                ...(omitted)...
                Have routed 26000
                Sent 49000 at 649.3506493506493 per sec
                Sent 50000 at 413.5649296939619 per sec
                Have routed 27000
                Sent 51000 at 697.350069735007 per sec
                - Duplicate throwable nesting of same base type: class org.jboss.mq.SpyJMSException is assignable from: class org.jboss.mq.SpyJMSException
                - Message consumer closing due to error in listening thread.
                org.jboss.mq.SpyJMSException: Cannot acknowlege a message; - nested throwable: (org.jboss.mq.SpyJMSException: Could not delete the message from the database: delete affected 0 rows)
                 at org.jboss.mq.Connection.send(Connection.java:901)
                 at org.jboss.mq.SpySession.doAcknowledge(SpySession.java:601)
                 at org.jboss.mq.SpyMessage.doAcknowledge(SpyMessage.java:537)
                 at org.jboss.mq.SpyMessageConsumer.run(SpyMessageConsumer.java:568)
                 at java.lang.Thread.run(Thread.java:534)
                Caused by: org.jboss.mq.SpyJMSException: Could not delete the message from the database: delete affected 0 rows
                 at org.jboss.mq.pm.jdbc2.PersistenceManager.remove(PersistenceManager.java:937)
                 at org.jboss.mq.server.BasicQueue.acknowledge(BasicQueue.java:402)
                 at org.jboss.mq.server.JMSQueue.acknowledge(JMSQueue.java:114)
                 at org.jboss.mq.server.ClientConsumer.acknowledge(ClientConsumer.java:324)
                 at org.jboss.mq.server.JMSDestinationManager.acknowledge(JMSDestinationManager.java:520)
                 at org.jboss.mq.server.JMSDestinationManager.acknowledge(JMSDestinationManager.java:504)
                 at org.jboss.mq.server.JMSServerInterceptorSupport.acknowledge(JMSServerInterceptorSupport.java:197)
                 at org.jboss.mq.server.TracingInterceptor.acknowledge(TracingInterceptor.java:404)
                 at org.jboss.mq.server.JMSServerInvoker.acknowledge(JMSServerInvoker.java:199)
                 at org.jboss.mq.il.oil.OILServerILService$Client.run(OILServerILService.java:244)
                 ... 1 more
                Sent 52000 at 799.3605115907275 per sec
                Sent 53000 at 1193.3174224343677 per sec
                ...(omitted)...
                


                I am going to migrate our software to using 3.2.3, but I would like to find out what is causing this problem (i.e. am I misusing the JMS somehow)?

                regards,

                eoin.


                • 5. Re: Consumer failing when MessageCache full? (3.0.8 20030605

                   

                  "adrian@jboss.org" wrote:
                  "adrian@jboss.org" wrote:
                  Most likely this is the change to create the hsql tables with
                  create cached table

                  As always, I don't recommend hsql for production. It is fine for testing/demos.

                  Regards,
                  Adrian


                  • 6. Re: Also occurs using MySQL persistence.
                    eoin

                     

                    "eoin" wrote:
                    "adrian@jboss.org" wrote:
                    Most likely this is the change to create the hsql tables with
                    create cached table

                    As always, I don't recommend hsql for production. It is fine for testing/demos.

                    Regards,
                    Adrian


                    I don't think that this is the case. I have just reproduced the problem using mysql for the jms persistence (after 106000 messages sent).

                    I've migrated my software to 3.2.3. However, if this is not a known bug in 3.0.8, can I be sure that the same problem won't arise in 3.2.3?

                    regards,

                    eoin.


                    • 7. Re: Consumer failing when MessageCache full? (3.0.8 20030605
                      eoin

                       

                      "eoin" wrote:
                      Some further info from test with MySQL:

                      The test queues 200000 messages. The consumer may move these from one queue to another, but there should be a total of 200000 messages in the system after the test completes (minus the one for which acknowledge() failed?). In fact, i get
                      mysql> select count(*) from JMS_MESSAGES;
                      +----------+
                      | count(*) |
                      +----------+
                      | 199649 |
                      +----------+
                      


                      so it seems that the MessageCache/CacheStore mechanism is delivering messages that it has not persisted?

                      Also, I have set an ExceptionListener on the connection, but it does not get called when this exception occurs, which would allow me to re-open the connection. (But i am more worried about losing messages than halting delivery).

                      e.


                      • 8. Re: Consumer failing when MessageCache full? (3.0.8 20030605

                         

                        "adrian@jboss.org" wrote:
                        Ok then, my next guess are the following two fixes:

                        http://cvs.sourceforge.net/viewcvs.py/jboss/jbossmq/src/main/org/jboss/mq/server/MessageCache.java?only_with_tag=JBoss_3_2_2_RC2
                        http://cvs.sourceforge.net/viewcvs.py/jboss/jbossmq/src/main/org/jboss/mq/server/MessageCache.java?only_with_tag=JBoss_3_2_3

                        It is hard for me to determine what fixed the problem since there is no explicit fix
                        for it that I'm aware of.

                        Try enabling TRACE logging for org.jboss.mq.server and org.jboss.mq.pm
                        to see what is happening to the messages in the cache and persistence manager.

                        onException won't catch the error since it is not a connection failure. It is
                        an internal error in the server for this consumer only. It just bails because
                        it has no idea what is happening.

                        Regards,
                        Adrian


                        • 9. Re: Consumer failing when MessageCache full? (3.0.8 20030605
                          eoin

                           

                          "eoin" wrote:
                          i don't have time at the moment to investigate this problem further (TRACE logs etc.), but I might in a month or so.

                          meanwhile, i should submit this as a bug against 3.0.8?

                          eoin.


                          • 10. Re: Consumer failing when MessageCache full? (3.0.8 20030605

                             

                            "adrian@jboss.org" wrote:
                            You can do, but test it with 3.0.9RC1 first (from cvs or the nightly snapshot)
                            Most of the important 3.2.x fixes have already been backported to that unreleased version.

                            Regards,
                            Adrian


                            • 11. Re: Consumer failing when MessageCache full? (3.0.8 20030605
                              eoin

                               

                              "eoin" wrote:
                              I have just built 3.0.9RC1 from the snapshot and re-ran my test. I get the problem the same as against 3.0.8.

                              eoin.