12 Replies Latest reply on Jan 30, 2013 11:22 AM by Clebert Suconic

    Couldn't locate page transaction and OutOfMemoryError: Java heap space   after upgrade to 2.1.14

    Jan van de klok Newbie

      Hello,

       

      We run Jboss 6.0.1 and have just migrated hornetQ from version 2.2.5.  to 2.2.14 because we had a strange problem with losing messages from queue's (at least thats what we think what was happening). (see my previous discussion).

      We just replaced the hornet*.jar files in jboss with their 2.2.14 equivalents. This should be OK according one of the HornetQ developers.

       

      The jboss runs with the following memory settings set "JAVA_OPTS=-Xms512M -Xmx1536M -XX:MaxPermSize=256M"

      These settings have not been changed for over a year now and have always proved to be sufficient.

       

       

      We have at startup 1,55 GB  of data in 1599 hornet-data-xxxxx.hq files.

      We have in total just over 700 queues defined.

      In the paging directory there just 1 page for 1 queue (so practicaly nothing is paged)

       

      When we start The jboss server  (this is the first start after the upgrade) we get the following error:

       

      10:54:19,451 INFO  [FileLockNodeManager] Live Server Obtained live lock

      10:54:49,780 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15036418044, ignoring message on position PagePositionImpl [pageNr=1, messageNr=0, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,790 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15036418466, ignoring message on position PagePositionImpl [pageNr=1, messageNr=1, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,790 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15036435382, ignoring message on position PagePositionImpl [pageNr=1, messageNr=2, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,790 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15036436482, ignoring message on position PagePositionImpl [pageNr=1, messageNr=3, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,790 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15036441911, ignoring message on position PagePositionImpl [pageNr=1, messageNr=4, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,790 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15036517094, ignoring message on position PagePositionImpl [pageNr=1, messageNr=5, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,790 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15036518185, ignoring message on position PagePositionImpl [pageNr=1, messageNr=6, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,790 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15036555950, ignoring message on position PagePositionImpl [pageNr=1, messageNr=7, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,790 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15036555954, ignoring message on position PagePositionImpl [pageNr=1, messageNr=8, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,790 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15036556039, ignoring message on position PagePositionImpl [pageNr=1, messageNr=9, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,800 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15036556066, ignoring message on position PagePositionImpl [pageNr=1, messageNr=10, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,800 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15036556095, ignoring message on position PagePositionImpl [pageNr=1, messageNr=11, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,800 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15036556124, ignoring message on position PagePositionImpl [pageNr=1, messageNr=12, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,800 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15036556167, ignoring message on position PagePositionImpl [pageNr=1, messageNr=13, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,800 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15036556234, ignoring message on position PagePositionImpl [pageNr=1, messageNr=14, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,800 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15036556726, ignoring message on position PagePositionImpl [pageNr=1, messageNr=15, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,800 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15036556773, ignoring message on position PagePositionImpl [pageNr=1, messageNr=16, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,800 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15036556854, ignoring message on position PagePositionImpl [pageNr=1, messageNr=17, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,800 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15036556903, ignoring message on position PagePositionImpl [pageNr=1, messageNr=18, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,800 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15036557038, ignoring message on position PagePositionImpl [pageNr=1, messageNr=19, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,800 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15036557483, ignoring message on position PagePositionImpl [pageNr=1, messageNr=20, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,800 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15036557556, ignoring message on position PagePositionImpl [pageNr=1, messageNr=21, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,810 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15036557673, ignoring message on position PagePositionImpl [pageNr=1, messageNr=22, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,810 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15036557742, ignoring message on position PagePositionImpl [pageNr=1, messageNr=23, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,810 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15036557805, ignoring message on position PagePositionImpl [pageNr=1, messageNr=24, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,810 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15036574592, ignoring message on position PagePositionImpl [pageNr=1, messageNr=25, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,810 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15036574622, ignoring message on position PagePositionImpl [pageNr=1, messageNr=26, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,810 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15036575735, ignoring message on position PagePositionImpl [pageNr=1, messageNr=27, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,810 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15036576778, ignoring message on position PagePositionImpl [pageNr=1, messageNr=28, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,810 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15036586153, ignoring message on position PagePositionImpl [pageNr=1, messageNr=29, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,810 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15036592050, ignoring message on position PagePositionImpl [pageNr=1, messageNr=30, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,810 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15036592800, ignoring message on position PagePositionImpl [pageNr=1, messageNr=31, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,810 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15036592863, ignoring message on position PagePositionImpl [pageNr=1, messageNr=32, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,810 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15036592969, ignoring message on position PagePositionImpl [pageNr=1, messageNr=33, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,820 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15037653786, ignoring message on position PagePositionImpl [pageNr=1, messageNr=34, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,820 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15037653794, ignoring message on position PagePositionImpl [pageNr=1, messageNr=35, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,820 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15037674517, ignoring message on position PagePositionImpl [pageNr=1, messageNr=36, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,820 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15044957735, ignoring message on position PagePositionImpl [pageNr=1, messageNr=37, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,820 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15044970604, ignoring message on position PagePositionImpl [pageNr=1, messageNr=38, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,820 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15044972011, ignoring message on position PagePositionImpl [pageNr=1, messageNr=39, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,820 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15045581674, ignoring message on position PagePositionImpl [pageNr=1, messageNr=40, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,820 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15046818591, ignoring message on position PagePositionImpl [pageNr=1, messageNr=41, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,820 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15047460845, ignoring message on position PagePositionImpl [pageNr=1, messageNr=42, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,820 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15047460849, ignoring message on position PagePositionImpl [pageNr=1, messageNr=43, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,830 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15047540676, ignoring message on position PagePositionImpl [pageNr=1, messageNr=44, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      10:54:49,830 WARN  [PageSubscriptionImpl] Couldn't locate page transaction 15050082253, ignoring message on position PagePositionImpl [pageNr=1, messageNr=45, recordID=0] on address=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi queue=jms.queue.studielink.delivery.STLK.to.IBG.group.1.kvi

      11:03:23,591 ERROR [OrderedExecutorFactory] Caught unexpected Throwable: java.lang.OutOfMemoryError: Java heap space

          at org.hornetq.core.buffers.impl.ChannelBufferWrapper.readSimpleStringInternal(ChannelBufferWrapper.java:83) [:]

          at org.hornetq.core.buffers.impl.ChannelBufferWrapper.readSimpleString(ChannelBufferWrapper.java:77) [:]

          at org.hornetq.utils.TypedProperties$StringValue.<init>(TypedProperties.java:1044) [:]

          at org.hornetq.utils.TypedProperties.decode(TypedProperties.java:547) [:]

          at org.hornetq.core.message.impl.MessageImpl.decodeHeadersAndProperties(MessageImpl.java:255) [:]

          at org.hornetq.core.message.impl.MessageImpl.decode(MessageImpl.java:935) [:]

          at org.hornetq.core.message.impl.MessageImpl.decode(MessageImpl.java:479) [:]

          at org.hornetq.core.paging.impl.PagedMessageImpl.decode(PagedMessageImpl.java:126) [:]

          at org.hornetq.core.paging.impl.PageImpl.read(PageImpl.java:147) [:]

          at org.hornetq.core.paging.cursor.impl.PageCursorProviderImpl.getPageCache(PageCursorProviderImpl.java:189) [:]

          at org.hornetq.core.paging.cursor.impl.PageCursorProviderImpl.getPageCache(PageCursorProviderImpl.java:140) [:]

          at org.hornetq.core.paging.cursor.impl.PageSubscriptionImpl.internalGetNext(PageSubscriptionImpl.java:339) [:]

          at org.hornetq.core.paging.cursor.impl.PageSubscriptionImpl.access$1500(PageSubscriptionImpl.java:65) [:]

          at org.hornetq.core.paging.cursor.impl.PageSubscriptionImpl$CursorIterator.moveNext(PageSubscriptionImpl.java:1177) [:]

          at org.hornetq.core.paging.cursor.impl.PageSubscriptionImpl$CursorIterator.next(PageSubscriptionImpl.java:1134) [:]

          at org.hornetq.core.paging.cursor.impl.PageSubscriptionImpl$CursorIterator.hasNext(PageSubscriptionImpl.java:1289) [:]

          at org.hornetq.core.server.impl.QueueImpl$5.run(QueueImpl.java:1249) [:]

          at org.hornetq.utils.OrderedExecutorFactory$OrderedExecutor$1.run(OrderedExecutorFactory.java:100) [:]

          at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) [:1.6.0_37]

          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) [:1.6.0_37]

          at java.lang.Thread.run(Thread.java:662) [:1.6.0_37]

       

       

      We did keep the hornet data that was created by the previous hornetversion 2.1.5!

       

       

       

      We have a printout of the journals (> 5 gb ) but I don''t know what to look for for errors in this journal.

       

      What we do see is that due to a delivery issue there have been logged a massive amount of rollbacks for 1 certain message due to an faulty  external receiver. This makes the journals that big. I fear that hornetq tries to read all the journalfiles into memory at once. If this is the case I would like to know whether this is really nessecary. I assume that Hornetq uses the journals to recreate the state of the in-memory parts or the queue's as it was left off when the server got down. Why should the memory usage grow that much when the journal actually just repeats the same action over and over again.

       

       

       

      Here's a snippit of these repeating rollback logging :

       

      operation@Update;recordID=15047461285;userRecordType=34;isUpdate=true;DeliveryCountUpdateEncoding [queueID=3829, count=4889945]

      operation@UpdateTX;txID=15052352289,recordID=15047461285;userRecordType=33;isUpdate=true;ACK;QueueEncoding [queueID=3829]

      operation@Rollback;txID=15052352289

      operation@Update;recordID=15047461285;userRecordType=34;isUpdate=true;DeliveryCountUpdateEncoding [queueID=3829, count=4889946]

      operation@UpdateTX;txID=15052352290,recordID=15047461285;userRecordType=33;isUpdate=true;ACK;QueueEncoding [queueID=3829]

      operation@Rollback;txID=15052352290

      operation@Update;recordID=15047461285;userRecordType=34;isUpdate=true;DeliveryCountUpdateEncoding [queueID=3829, count=4889947]

      operation@UpdateTX;txID=15052352291,recordID=15047461285;userRecordType=33;isUpdate=true;ACK;QueueEncoding [queueID=3829]

      operation@Rollback;txID=15052352291

      operation@Update;recordID=15047461285;userRecordType=34;isUpdate=true;DeliveryCountUpdateEncoding [queueID=3829, count=4889948]

      operation@UpdateTX;txID=15052352292,recordID=15047461285;userRecordType=33;isUpdate=true;ACK;QueueEncoding [queueID=3829]

      operation@Rollback;txID=15052352292

      operation@Update;recordID=15047461285;userRecordType=34;isUpdate=true;DeliveryCountUpdateEncoding [queueID=3829, count=4889949]

      operation@UpdateTX;txID=15052352293,recordID=15047461285;userRecordType=33;isUpdate=true;ACK;QueueEncoding [queueID=3829]

      operation@Rollback;txID=15052352293

      operation@Update;recordID=15047461285;userRecordType=34;isUpdate=true;DeliveryCountUpdateEncoding [queueID=3829, count=4889950]

      operation@UpdateTX;txID=15052352294,recordID=15047461285;userRecordType=33;isUpdate=true;ACK;QueueEncoding [queueID=3829]

      operation@Rollback;txID=15052352294

      operation@Update;recordID=15047461285;userRecordType=34;isUpdate=true;DeliveryCountUpdateEncoding [queueID=3829, count=4889951]

      operation@UpdateTX;txID=15052352295,recordID=15047461285;userRecordType=33;isUpdate=true;ACK;QueueEncoding [queueID=3829]

       

      My question is : why does this happen??

       

       

      -  Is it a bug in the 2.2.14 version?

      -  Did we have to do some kind of manual conversion of the hornetdata?

      -  Can the 2.2.14 version handle these large amounts of journal data?

      - How do we get this thing running again without loosing messages ????  (my main concern !!! since we have to do this also in a production   environment where we can't just discard the existing hornetdata upon a conversion)

       

      Question: Are the journalpages freed in memory iimidiatly after they have been processed?? (in that case we should not have this problem) 

       

       

      Question: Can someone give me a list of userRecordType codes and their meanings???????

       

       

      Any help is appreciated.

       

      Regards,  Jan van de Klok