7 Replies Latest reply on Jul 18, 2013 1:36 PM by Guillaume Grossetie

    HornetQ server takes more than a minute to boot ?

    Guillaume Grossetie Newbie

      Hi,

       

      I use JBoss AS 7.1.1.Final and my boot time is now up to a minute or two. The server spend time between those two lines :

       

      08:20:59,811 INFO  [org.jboss.as.connector.subsystems.datasources] (MSC service thread 1-5) JBAS010400: Bound data source [java:/GedDS]
      08:21:43,927 INFO  [org.hornetq.core.remoting.impl.netty.NettyAcceptor] (MSC service thread 1-4) Started Netty Acceptor version 3.2.5.Final-a96d88c 0.0.0.0:5455 for CORE protocol
      

       

      I guess that the problem is relative to HornetQ server initialization ?

       

      On development server, the boot time is around 5 seconds.

      The only difference I spot is the size of the /data. On this server I have 10K messages on queues :

       

       

      $ pwd
      ${JBOSS_HOME}/standalone/data
      
      $ du -sh *4.1M messagingbindings
      369M messagingjournal
      4.0K messaginglargemessages
      42M messagingpaging
      
      

       

      My HornetQ configuration :

       

      <hornetq-server>
        <persistence-enabled>true</persistence-enabled>
        <jmx-management-enabled>true</jmx-management-enabled>
        <journal-file-size>102400</journal-file-size>
        <journal-min-files>2</journal-min-files>
      
        <!-- ... -->
      
      
        <address-settings>
          <address-setting match="#">
            <dead-letter-address>jms.queue.DLQ</dead-letter-address>
            <expiry-address>jms.queue.ExpiryQueue</expiry-address>
            <redelivery-delay>0</redelivery-delay>
            <max-delivery-attempts>1</max-delivery-attempts>
            <max-size-bytes>104857600</max-size-bytes>
            <page-size-bytes>10485760</page-size-bytes>
            <address-full-policy>PAGE</address-full-policy>
            <message-counter-history-day-limit>10</message-counter-history-day-limit>
          </address-setting>
        </address-settings>
      
      

       

      Am I doing something wrong ? Is the server suppose to take a minute to boot with 10K messages on queues ?

       

      Thanks for your help.

      Guillaume.

        • 1. Re: HornetQ server takes more than a minute to boot ?
          Guillaume Grossetie Newbie

          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.

          • 2. Re: HornetQ server takes more than a minute to boot ?
            Miroslav Novak Master

            Hi,

             

            could you provide a thread dump taken between the two lines you mentioned, please? (type ctrl^c)

             

            Also could you try to start server on different hardware or on different disk drive?

             

            Thanks,

             

            Mirek

            • 3. Re: HornetQ server takes more than a minute to boot ?
              Guillaume Grossetie Newbie

              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

              • 4. Re: HornetQ server takes more than a minute to boot ?
                Miroslav Novak Master

                Hi Guillaume,

                 

                you seem to be right with journal-file-size attribute. There is over 3000 journal files to read in messagingjournal directory which takes some time to read. I'm not sure about the way how to compact them but there is utility which can export the whole journal to xml file. Then it's possible to import them again:

                http://docs.jboss.org/hornetq/2.3.0.Final/docs/user-manual/html_single/index.html#persistence.importexport

                 

                HornetQ journal has ~400MB. I believe there would be necessary to use profiler to get good overview where some optimization can be done.

                 

                Cheers,

                 

                Mirek

                1 of 1 people found this helpful
                • 5. Re: HornetQ server takes more than a minute to boot ?
                  Guillaume Grossetie Newbie

                  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.

                  • 6. Re: HornetQ server takes more than a minute to boot ?
                    Miroslav Novak Master

                    Hi Guillaume,

                     

                    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.

                     

                    I'm happy that you managed to fix it. :-)

                     

                    Cheers,

                     

                    Mirek

                    1 of 1 people found this helpful
                    • 7. Re: HornetQ server takes more than a minute to boot ?
                      Guillaume Grossetie Newbie

                      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.