12 Replies Latest reply on Aug 25, 2009 10:06 PM by gaohoward

    Ordering Group and Queue-FullSize reload problem

    mclu

      Hi Howard!

      Again me with a JBM OrderingGroup BUG.
      Using newest Build of 1.4.5 (7304)

      My test scenario:

      - Client adds 500 Messages (Text with incrementing number) to a Queue.
      - The Queue is set to

      <attribute name="FullSize">50</attribute>
      <attribute name="PageSize">25</attribute>
      <attribute name="DownCacheSize">25</attribute>

      - The handler is slower than the producer.
      - On receiving side I see well ordered messages.

      like:
      ...
      14:20:12,234 INFO [TestMessageHandlerBean] Got:176 mID:ID:JBM-475cc9ad-cbf7-4039-9fb5-8edf19d3d3c1
      14:20:12,250 INFO [TestMessageHandlerBean] Got:177 mID:ID:JBM-f9f56a49-5d82-453a-80c7-9d850d090f73
      14:20:12,265 INFO [TestMessageHandlerBean] Got:178 mID:ID:JBM-657effd8-3099-47bc-887c-fd4289009635
      ...


      But if I kill jboss while it handles the 500 messages (lets say at message 100) and restart it I see the following:

      The rest(400) of the 500 Messages are in the Queue!
      While starting jboss up the messaging system reloads the messages from the database. I can see that inside the table the first 50 messages have page_ord null and the others incrementing numbers.

      Then it starts handling by continue at the last message.
      101, 102, 103 and so on.

      But while reloading messages after the fullsize barrier the order is scambled.

      On my first test only one message/number was missing which was handled then after message 500
      My second test all messages are fine and in order
      My third test results in:
      ...
      14:20:16,265 INFO [TestMessageHandlerBean] Got:208 mID:ID:JBM-c3d5eaa5-01aa-48de-b37d-f193f203fb49
      14:20:16,296 INFO [TestMessageHandlerBean] Got:209 mID:ID:JBM-b0e4841c-4acb-487d-9c89-d0fa7045bb7e
      14:20:16,328 INFO [TestMessageHandlerBean] Got:210 mID:ID:JBM-1a451bc1-c8a6-43f8-9bb6-e070fff2942a
      14:20:16,343 INFO [TestMessageHandlerBean] Got:492 mID:ID:JBM-64b01947-59fb-4404-8e3a-3cae255fb91f
      14:20:16,343 ERROR [TestMessageKeeper] Number sequence is not ok. Expected 211 but was:492
      14:20:16,359 ERROR [TestMessageKeeper] Resetting to:492
      14:20:16,375 INFO [TestMessageHandlerBean] Got:493 mID:ID:JBM-018565ac-4ed3-453c-84fb-14b7251062a4
      14:20:16,421 INFO [TestMessageHandlerBean] Got:494 mID:ID:JBM-cfc1f42b-6c5d-4309-8e71-d3c39cd91866
      14:20:16,453 INFO [TestMessageHandlerBean] Got:495 mID:ID:JBM-2f052b3a-e2c7-4c58-9615-b3bd299e8d9f
      14:20:16,468 INFO [TestMessageHandlerBean] Got:496 mID:ID:JBM-42841e9f-cd32-4aa9-89d7-d0232edc9987
      14:20:16,500 INFO [TestMessageHandlerBean] Got:497 mID:ID:JBM-aaf28cb8-6f1c-4e86-aac6-cee850440801
      14:20:16,531 INFO [TestMessageHandlerBean] Got:498 mID:ID:JBM-cdfac31d-3b21-497a-8e44-c649c4aead0c
      14:20:16,531 INFO [TestMessageHandlerBean] Got:499 mID:ID:JBM-3a2226c1-6375-49b9-baed-ca1945b41e02
      14:20:16,562 INFO [TestMessageHandlerBean] Got:500 mID:ID:JBM-0e720c52-1eb9-4b77-9596-9d78e31031ff
      14:20:16,578 INFO [TestMessageHandlerBean] Got:211 mID:ID:JBM-20ccaeca-f409-455a-b3b4-69519fd065e2
      14:20:16,578 ERROR [TestMessageKeeper] Number sequence is not ok. Expected 501 but was:211
      14:20:16,578 ERROR [TestMessageKeeper] Resetting to:211
      14:20:16,640 INFO [TestMessageHandlerBean] Got:212 mID:ID:JBM-67d13844-da4b-4a75-a78c-707e7c1b0d9e
      14:20:16,718 INFO [TestMessageHandlerBean] Got:213 mID:ID:JBM-84831294-f9d5-431d-982d-38994135c978
      14:20:16,765 INFO [TestMessageHandlerBean] Got:214 mID:ID:JBM-e99d350a-f824-42a8-9536-d265a0babc9b
      14:27:34,453 INFO [TestMessageHandlerBean] Got:215 mID:ID:JBM-41c58e16-fda5-449f-b508-a7c65f1f3d6e
      ...


      So it seams that the order is not garanteed anymore if the size of the queue exceeds the FullSize setting.
      Is this a BUG?


      By the way. I tested this Rollback Bug of OrderingGroup. This works now perferct! Good (and fast) Job :-)

        • 1. Re: Ordering Group and Queue-FullSize reload problem
          gaohoward

          Thanks Markus, I'll take a look at it.

          • 2. Re: Ordering Group and Queue-FullSize reload problem
            mclu

            Howard!

            Here more analysis!

            I can see that the order is scambled.
            But this has nothing to do with the ordered load of the messages. It has to do with updating the Page_ORD.

            The above error can be reproduced if you kill the server before all Page_Ord`s are updated.
            So before UpdatePageOrderRunner().executeWithRetry(); finishes.

            Then I see in my database this!

            ORD numbers not real numbers
            
            ORD PAGE_ORD
            1 NULL
            2 NULL
            ....
            24 NULL
            25 25
            26 26
            ...
            84 84
            85 NULL
            86 NULL
            ...
            115 NULL
            


            As you can see after Ord 85 the page_ord was not yet set!

            Then I restart the server and while starting the QueueService the load() method is called. This results in calling loadFromStart() at the JDBC PersistenceManager.
            I don't know why but after the first call it loads 50 unpaged messages to the Queue(pageOrd=NULL) and updated one (the last one) to 85. ?!?
            So the ord message 115 has now page_ord 85.??

            Then I stopped debugging.
            So it seams that setting the right page_ord numbers is not handled well if the system has not set the numbers for the newest messages!

            Hope this helps to reproduce the Bug

            • 3. Re: Ordering Group and Queue-FullSize reload problem
              gaohoward

              Thanks a lot Markus. I'll be on this one very soon (I'm closing another issue right now).

              • 4. Re: Ordering Group and Queue-FullSize reload problem
                gaohoward
                • 5. Re: Ordering Group and Queue-FullSize reload problem
                  gaohoward

                  Hi Markus,

                  I've fixed the related issue, can you help to verify it if you have time?

                  Thanks,
                  Howard

                  • 6. Re: Ordering Group and Queue-FullSize reload problem
                    mclu

                    Of course I can!

                    But I am overscheduled so I think I can try it not before Monday next week!
                    I keep you informed!

                    Thx Howard for quick support!

                    • 7. Re: Ordering Group and Queue-FullSize reload problem
                      gaohoward

                      No problem, thanks Markus.

                      Howard

                      • 8. Re: Ordering Group and Queue-FullSize reload problem
                        mclu

                        Hi Howard!

                        Sorry... But its not fixed :-(
                        I can reproduce the same issue with the latest branch version (from tomorrow)

                        I know... its had to reproduce but it happens only if not all messages have a page_ord set while killing the server.

                        • 9. Re: Ordering Group and Queue-FullSize reload problem
                          gaohoward

                          Thanks Markus! I'll reopen it and continue to investigate it.

                          Howard

                          • 10. Re: Ordering Group and Queue-FullSize reload problem
                            mclu

                            Hi Howard!

                            Sorry I am late.
                            I have just retested the problem with 1.4.5. Build 7766.

                            I have the same DB entries while my last tests.

                            Some page ords are filled some still NULL.

                            While I restart the Server I got:


                            15:22:26,843 INFO [TestMessageHandlerBean] Got:125 mID:ID:JBM-618ec024-cadb-486e-8d82-cf0315dbd522
                            15:22:26,875 INFO [TestMessageHandlerBean] Got:126 mID:ID:JBM-66160cb6-f743-4af5-a6d3-d1e592d20695
                            15:22:26,968 INFO [TestMessageHandlerBean] Got:127 mID:ID:JBM-b3f619b1-7a8a-43aa-9d4c-478addf3e647
                            15:22:27,031 INFO [TestMessageHandlerBean] Got:128 mID:ID:JBM-095a71b7-b8f9-420a-ae46-64027453e110
                            15:22:27,046 ERROR [ChannelSupport] Queue[15919140/2/176-testQueue] Failed to deliver
                            java.lang.IllegalStateException: Didn't load expected number of references, loaded: 36 expected: 50
                             at org.jboss.messaging.core.impl.JDBCPersistenceManager.getPagedReferenceInfos(JDBCPersistenceManager.java:914)
                             at org.jboss.messaging.core.impl.PagingChannelSupport.loadPagedReferences(PagingChannelSupport.java:253)
                             at org.jboss.messaging.core.impl.PagingChannelSupport.checkLoad(PagingChannelSupport.java:361)
                             at org.jboss.messaging.core.impl.PagingChannelSupport.removeFirstInMemory(PagingChannelSupport.java:345)
                             at org.jboss.messaging.core.impl.ChannelSupport.deliverInternal(ChannelSupport.java:725)
                             at org.jboss.messaging.core.impl.MessagingQueue.deliverInternal(MessagingQueue.java:506)
                             at org.jboss.messaging.core.impl.ChannelSupport.deliver(ChannelSupport.java:380)
                             at org.jboss.jms.server.endpoint.ServerSessionEndpoint$2.run(ServerSessionEndpoint.java:1574)
                             at org.jboss.messaging.util.OrderedExecutorFactory$ChildExecutor.run(OrderedExecutorFactory.java:120)
                             at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
                             at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
                             at java.lang.Thread.run(Thread.java:619)
                            15:22:27,093 INFO [TestMessageHandlerBean] Got:129 mID:ID:JBM-f819aaf8-e16b-4af4-957a-60ccd986aa20
                            15:22:27,093 ERROR [ChannelSupport] Queue[15919140/2/176-testQueue] Failed to deliver
                            java.lang.IllegalStateException: Didn't load expected number of references, loaded: 36 expected: 50
                             at org.jboss.messaging.core.impl.JDBCPersistenceManager.getPagedReferenceInfos(JDBCPersistenceManager.java:914)
                             at org.jboss.messaging.core.impl.PagingChannelSupport.loadPagedReferences(PagingChannelSupport.java:253)
                             at org.jboss.messaging.core.impl.PagingChannelSupport.checkLoad(PagingChannelSupport.java:361)
                             at org.jboss.messaging.core.impl.PagingChannelSupport.removeFirstInMemory(PagingChannelSupport.java:345)
                             at org.jboss.messaging.core.impl.ChannelSupport.deliverInternal(ChannelSupport.java:725)
                             at org.jboss.messaging.core.impl.MessagingQueue.deliverInternal(MessagingQueue.java:506)
                             at org.jboss.messaging.core.impl.ChannelSupport.deliver(ChannelSupport.java:380)
                             at org.jboss.jms.server.endpoint.ServerSessionEndpoint$2.run(ServerSessionEndpoint.java:1574)
                             at org.jboss.messaging.util.OrderedExecutorFactory$ChildExecutor.run(OrderedExecutorFactory.java:120)
                             at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
                             at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
                             at java.lang.Thread.run(Thread.java:619)
                            15:22:27,140 ERROR [ChannelSupport] Queue[15919140/2/176-testQueue] Failed to deliver
                            java.lang.IllegalStateException: Didn't load expected number of references, loaded: 36 expected: 50
                             at org.jboss.messaging.core.impl.JDBCPersistenceManager.getPagedReferenceInfos(JDBCPersistenceManager.java:914)
                             at org.jboss.messaging.core.impl.PagingChannelSupport.loadPagedReferences(PagingChannelSupport.java:253)
                             at org.jboss.messaging.core.impl.PagingChannelSupport.checkLoad(PagingChannelSupport.java:361)
                             at org.jboss.messaging.core.impl.PagingChannelSupport.removeFirstInMemory(PagingChannelSupport.java:345)
                             at org.jboss.messaging.core.impl.ChannelSupport.deliverInternal(ChannelSupport.java:725)
                             at org.jboss.messaging.core.impl.MessagingQueue.deliverInternal(MessagingQueue.java:506)
                             at org.jboss.messaging.core.impl.ChannelSupport.deliver(ChannelSupport.java:380)
                             at org.jboss.jms.server.endpoint.ServerSessionEndpoint$2.run(ServerSessionEndpoint.java:1574)
                             at org.jboss.messaging.util.OrderedExecutorFactory$ChildExecutor.run(OrderedExecutorFactory.java:120)
                             at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
                             at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
                             at java.lang.Thread.run(Thread.java:619)
                            15:22:27,187 INFO [TestMessageHandlerBean] Got:130 mID:ID:JBM-ed3b18f9-1d4f-4328-9940-1be79bd965d5
                            15:22:27,250 INFO [TestMessageHandlerBean] Got:131 mID:ID:JBM-001da397-5c6f-46a8-aafb-ccc7cf7e1042
                            15:22:27,250 ERROR [ChannelSupport] Queue[15919140/2/176-testQueue] Failed to deliver
                            java.lang.IllegalStateException: Didn't load expected number of references, loaded: 36 expected: 50
                             at org.jboss.messaging.core.impl.JDBCPersistenceManager.getPagedReferenceInfos(JDBCPersistenceManager.java:914)
                            


                            I can reproduce this with my databasebackup. So each time the same error occurs.
                            Any Idea?

                            • 11. Re: Ordering Group and Queue-FullSize reload problem
                              mclu

                              SORRY!

                              Forget last post.

                              I had still an old messaging jar in my lib dir.
                              So if you have this kind of error just replace the messaging.jar to the right version :-)

                              And by the way... The bugfix solved the bug also on my side.
                              Thx!!

                              • 12. Re: Ordering Group and Queue-FullSize reload problem
                                gaohoward

                                Hi Markus,

                                I also changed the db persistence config file (one sql statement), you need to update your xx-persistence-service.xml.

                                Thanks
                                Howard