I came across : https://community.jboss.org/thread/155183?start=0&tstart=0

My file system is ext4 :

$ mount
/dev/mapper/VG_DATA-LV_JMS on /var/opt/jbossas7/standalone/data type ext4 (rw,noatime,nodiratime)

I notice that my journal-file-size is only 100K [ default value : 10485760 bytes (10MiB) ]. The method JournalImpl#readJournalFile use 1 maxIO and I have more than 4K files in /data/messagingjournal. I think that HornetQ will perform better will less but bigger files ?

I change the value to the default one but my boot time is still around a minute. New journal files are now 10MiB but the "old" ones are still there. Can I force HornetQ to compact thoses files ?

Guillaume.

Hi Mirek,

I take a CPU snapshot and a thread dump with jvisualvm : https://drive.google.com/a/april-waf.com/folderview?id=0B0iXZ7nwKNY2Sml2eFRMVDJJSUk&usp=sharing#

I also enable trace log on org.hornetq :

# Start reading page 1
11:12:28,790 TRACE [org.hornetq.core.paging.impl.PageImpl] (MSC service thread 1-5) Reading message PagedMessageImpl [queueIDs=[4367836744], transactionID=-1, message=ServerMessage[messageID=10824595403,priority=4, bodySize=12800,expiration=0, durable=true, address=jms.queue.EnregistrementEvenementQueue,properties=TypedProperties[{_HQ_SCHED_DELIVERY=1376478214738, dtdTraceTagInfo=FW1;-604156158;-1198233696;2285269;1242;-1198233696;2285269;3, runAs=26877@11, lienMetierId=176585, lienMetierType=SITUATION_CONTRAT, processusPlanifieType=SOUSCRIPTION_RELANCE_PIECE:EVT_TYPE_TACHE, dateDeclenchement=14/08/2013 01:03}]]@1222996095] on pageId=5 for address=jms.queue.EnregistrementEvenementQueue

# End reading page 1 ~ 2 seconds
11:12:30,020 DEBUG [org.hornetq.core.paging.impl.PageImpl] (MSC service thread 1-5) reading page 1 on address = jms.queue.DLQ


# Start reading page 1
11:12:59,760 DEBUG [org.hornetq.core.paging.impl.PageImpl] (Thread-16 (HornetQ-server-HornetQServerImpl::serverUUID=efceaea3-5033-11e2-ba42-005056ba6b6f-1228257582)) reading page 1 on address = jms.queue.EnregistrementEvenementQueue
11:12:59,774 TRACE [org.hornetq.core.paging.impl.PageImpl] (Thread-16 (HornetQ-server-HornetQServerImpl::serverUUID=efceaea3-5033-11e2-ba42-005056ba6b6f-1228257582)) Reading message PagedMessageImpl [queueIDs=[4367836744], transactionID=-1, message=ServerMessage[messageID=10818713242,priority=4, bodySize=12800,expiration=0, durable=true, address=jms.queue.EnregistrementEvenementQueue,properties=TypedProperties[{_HQ_SCHED_DELIVERY=1375544516520, dtdTraceTagInfo=FW1;-604156158;-224594837;152838;717;-224594837;152838;3, runAs=24708@11, lienMetierId=164825, lienMetierType=SITUATION_CONTRAT, processusPlanifieType=SOUSCRIPTION_ANNULATION_GARANTIES:EVT_TYPE_TACHE, dateDeclenchement=03/08/2013 05:41}]]@1075012607] on pageId=1 for address=jms.queue.EnregistrementEvenementQueue

#End reading page 1 ~ 5 seconds
11:13:04,140 TRACE [org.hornetq.core.paging.impl.PageImpl] (Thread-16 (HornetQ-server-HornetQServerImpl::serverUUID=efceaea3-5033-11e2-ba42-005056ba6b6f-1228257582)) Reading message PagedMessageImpl [queueIDs=[4367836744], transactionID=-1, message=ServerMessage[messageID=10820280962,priority=4, bodySize=25600,expiration=0, durable=true, address=jms.queue.EnregistrementEvenementQueue,properties=TypedProperties[{_HQ_SCHED_DELIVERY=1375863705854, dtdTraceTagInfo=FW1;-604156158;-1316744723;1236399;723;-1316744723;1236399;3, runAs=17255@11, lienMetierId=167093, lienMetierType=SITUATION_CONTRAT, processusPlanifieType=SOUSCRIPTION_ANNULATION_GARANTIES:EVT_TYPE_TACHE, dateDeclenchement=07/08/2013 10:21}]]@1167441869] on pageId=1 for address=jms.queue.EnregistrementEvenementQueue


# Start depage
11:13:04,143 TRACE [org.hornetq.core.server.impl.QueueImpl] (Thread-16 (HornetQ-server-HornetQServerImpl::serverUUID=efceaea3-5033-11e2-ba42-005056ba6b6f-1228257582)) Scheduling depage for queue jms.queue.EnregistrementEvenementQueue
11:13:04,144 TRACE [org.hornetq.core.server.impl.QueueImpl] (Thread-16 (HornetQ-server-HornetQServerImpl::serverUUID=efceaea3-5033-11e2-ba42-005056ba6b6f-1228257582)) QueueMemorySize before depage on queue=jms.queue.EnregistrementEvenementQueue is 0

# End depage ~ 1 second
11:13:05,144 DEBUG [org.hornetq.core.server.impl.QueueImpl] (Thread-16 (HornetQ-server-HornetQServerImpl::serverUUID=efceaea3-5033-11e2-ba42-005056ba6b6f-1228257582)) Queue Memory Size after depage on queue=jms.queue.EnregistrementEvenementQueue is 0 with maxSize = 10240. Depaged 285 messages, pendingDelivery=0, intermediateMessageReferences= 0, queueDelivering=0

# wait 7 seconds

# Start loading *.hq with org.hornetq.core.journal.impl.JournalImpl/org.hornetq.core.server.impl.QueueImpl
11:13:12,545 TRACE [org.hornetq.core.journal.impl.JournalImpl] (MSC service thread 1-5) Loading file hornetq-data-211549.hq
...
11:13:28,768 TRACE [org.hornetq.core.journal.impl.JournalImpl] (MSC service thread 1-5) Loading file hornetq-data-212984.hq
...
11:13:29,779 TRACE [org.hornetq.core.journal.impl.JournalImpl] (MSC service thread 1-5) Loading file hornetq-data-213052.hq
...
11:13:58,762 TRACE [org.hornetq.core.journal.impl.JournalImpl] (MSC service thread 1-5) Loading file hornetq-data-215255.hq
...
### Start reading page 2
11:13:59,337 DEBUG [org.hornetq.core.paging.impl.PageImpl] (Thread-11 (HornetQ-server-HornetQServerImpl::serverUUID=efceaea3-5033-11e2-ba42-005056ba6b6f-1228257582)) reading page 2 on address = jms.queue.EnregistrementEvenementQueue

### End reading page 2
11:14:00,216 TRACE [org.hornetq.core.paging.impl.PageImpl] (Thread-11 (HornetQ-server-HornetQServerImpl::serverUUID=efceaea3-5033-11e2-ba42-005056ba6b6f-1228257582)) Reading message PagedMessageImpl [queueIDs=[4367836744], transactionID=-1, message=ServerMessage[messageID=10821466186,priority=4, bodySize=25600,expiration=0, durable=true, address=jms.queue.EnregistrementEvenementQueue,properties=TypedProperties[{_HQ_SCHED_DELIVERY=1376225279578, dtdTraceTagInfo=FW1;-604156158;-1316744723;4181062;679;-1316744723;4181062;3, runAs=27472@11, lienMetierId=170446, lienMetierType=SITUATION_CONTRAT, processusPlanifieType=SOUSCRIPTION_ANNULATION_GARANTIES:EVT_TYPE_TACHE, dateDeclenchement=11/08/2013 02:47}]]@1506923986] on pageId=2 for address=jms.queue.EnregistrementEvenementQueue

11:14:00,231 TRACE [org.hornetq.core.journal.impl.JournalImpl] (MSC service thread 1-5) Loading file hornetq-data-215391.hq
...
11:14:03,456 TRACE [org.hornetq.core.journal.impl.JournalImpl] (MSC service thread 1-5) Loading file hornetq-data-215701.hq
...

### Start reclaimer
11:14:03,475 TRACE [org.hornetq.core.journal.impl.Reclaimer] (MSC service thread 1-5) posCount on JournalFileImpl: (hornetq-data-211549.hq id = 161944, recordID = 161944) = 66

### End reclaimer ~ 5seconds
11:14:08,773 TRACE [org.hornetq.core.journal.impl.Reclaimer] (MSC service thread 1-5) Negative from JournalFileImpl: (hornetq-data-215699.hq id = 215699, recordID = 215699) into JournalFileImpl: (hornetq-data-215699.hq id = 215699, recordID = 215699) = 328

### Start scheduling delivery
11:14:09,057 TRACE [org.hornetq.core.server.impl.ScheduledDeliveryHandlerImpl] (MSC service thread 1-5) Scheduling delivery for Reference[4371964733]:RELIABLE:ServerMessage[messageID=4371964733,priority=4, bodySize=25600,expiration=0, durable=true, address=jms.queue.EnregistrementEvenementQueue,properties=TypedProperties[{_HQ_SCHED_DELIVERY=1373700345372, dtdTraceTagInfo=FW1;-604156158;-291444260;1693342;711;-291444260;1693342;3, runAs=11058@11, lienMetierId=148116, lienMetierType=SITUATION_CONTRAT, processusPlanifieType=SOUSCRIPTION_ANNULATION_GARANTIES:EVT_TYPE_TACHE, dateDeclenchement=13/07/2013 09:25}]]@1903542212 to occur at 1373700345372

### End scheduling delivery ~ 3seconds
11:14:12,053 TRACE [org.hornetq.core.server.impl.ScheduledDeliveryHandlerImpl] (MSC service thread 1-5) Scheduling delivery for Reference[10818710104]:RELIABLE:ServerMessage[messageID=10818710104,priority=4, bodySize=25600,expiration=0, durable=true, address=jms.queue.EnregistrementEvenementQueue,properties=TypedProperties[{_HQ_SCHED_DELIVERY=1375112279529, dtdTraceTagInfo=FW1;-604156158;-224594837;145664;1216;-224594837;145664;3, runAs=18965@11, lienMetierId=164822, lienMetierType=SITUATION_CONTRAT, processusPlanifieType=SOUSCRIPTION_RELANCE_PIECE:EVT_TYPE_TACHE, dateDeclenchement=29/07/2013 05:37}]]@617000740 to occur at 1375112279529

# End ~ 1 minute
11:14:13,629 INFO  [org.jboss.as] (Controller Boot Thread) JBAS015874: JBoss AS 7.1.1.Final "Brontes" started in 107336ms - Started 172 of 280 services (106 services are passive or on-demand)

Thanks for your help,

Guillaume

Hi Mirek,

Thanks your for help.

I changed the journal-file-size attribute to 10Mib and removed some messages from the DLQ.

Somehow the server start removing "old" journal files :

WARN  [org.hornetq.core.journal.impl.JournalFilesRepository] (JournalImpl::FilesExecutor) Deleting JournalFileImpl: (hornetq-data-215380.hq id = 215380, recordID = 215380).. as it doesn't have the configured size

My boot time is now back to a few seconds !

I think that the AS7/HornetQ should make it clear that the AS7 default value for journal-file-size is really small for real usage. Maybe this issue is not relevant anymore with recent HornetQ version and the default value can now be back to 10Mib ?

Cheers,

Guillaume.

Hi Mirek,

I've checked attribute journal-file-size and it was already removed from standalone-full...xml in AS 7.2.0/EAP 6.1. It means that default value 10MB is used.

Great news !

Thanks again for your help

Guillaume.