1 2 3 Previous Next 41 Replies Latest reply on Apr 11, 2012 12:08 PM by Scott Marlow

    Startup Goes Very Slow with Scanning Entity Classes from Different Jars

    Mostafa Far Newbie

      Hi,

       

      After resolving the issue (https://community.jboss.org/message/723709

      and apply it to the whole modules (over 80 modules) the deploying process goes very slow and finally failes after 10 minutes,

       

       

      More details:

      - The whole application(80+ modules), without correct loading of <jar-file> in their persistence.xml, is successfully deployed within 1 minute.

      - The whole application(80+ modules), with just around 20 modules with correct loading of <jar-file> in their persistence.xml, is successfully deployed withing around 1 minute and 30 seconds.

      - I also tested above condintion for different group of 20 modules of whole application, and it deploys succcessfully.

      - As the number of modules that icnludes correct <jar-file> in their persistence.xml goes higher the process of deployment goes down.

       

      - The same application in Jboss 4.3 takes around 4-5 minutes to be deployed.

       

       

      I also attached the Server Log.

       

      Thank you.

        • 1. Re: Startup Goes Very Slow with Scanning Entity Classes from Different Jars
          Stephen Coy Master

          Some of the deltas in the log file timestamps smell like garbage collection.

          17:35:00,812 WARN  [org.hibernate.mapping.RootClass] (MSC service thread 1-3) HHH000038: ...
          17:35:17,875 WARN  [org.hibernate.mapping.RootClass] (MSC service thread 1-3) HHH000039: ...

           

          Thats a 17 second pause. Are you sure that you have enough memory allocated?

           

          I would think that 80 modules would need a substantial slab of memory.

          • 2. Re: Startup Goes Very Slow with Scanning Entity Classes from Different Jars
            Scott Marlow Master

            If its not a memory issue, I think a few different possible ways of investigating could be:

             

            1.  Enable TRACE logging for org.hibernate, org.jboss.jpa, org.jboss.as.jpa and do further analysis of the log timestamps (as Stephen did above).

             

            2.  Sprinkle the code with more print statements to see where the most time is spent.

             

            3.  Profile the code in a Java profiler.

             

            4.  Something else that others might suggest...

             

            Depending on how much time and effort you can put into this, we can discuss the best path.  I think (1) is the easiest/quickest to try next.

             

            I hope Stephen is right, increasing memory and then investigating what is in memory, would be a good win. 

            • 3. Re: Startup Goes Very Slow with Scanning Entity Classes from Different Jars
              Mostafa Far Newbie

              Yup, seems its related to the Memory Issue and GC, I got this error this time i run the JBOSS:

               

              09:35:07,155 INFO  [org.hibernate.engine.transaction.internal.TransactionFactoryInitiator] (MSC service thread 1-3) HHH000268: Transaction strategy: org.hibernate.engine.transaction.internal.jta.CMTTransactionFactory
              09:35:07,155 INFO  [org.hibernate.hql.internal.ast.ASTQueryTranslatorFactory] (MSC service thread 1-3) HHH000397: Using ASTQueryTranslatorFactory
              09:36:51,421 INFO  [org.jboss.jpa] (MSC service thread 1-1) JBAS011402: Starting Persistence Unit Service 'icba10.ear/icba10-kern-overriding-ejb.jar#entityManager'
              09:36:51,421 INFO  [org.hibernate.ejb.Ejb3Configuration] (MSC service thread 1-1) HHH000204: Processing PersistenceUnitInfo [
              name: entityManager
              ...]
              09:39:11,436 ERROR [org.jboss.msc.service.fail] (MSC service thread 1-1) MSC00001: Failed to start service jboss.persistenceunit."icba10.ear/icba10-kern-overriding-ejb.jar#entityManager": org.jboss.msc.service.StartException in service jboss.persistenceunit."icba10.ear/icba10-kern-overriding-ejb.jar#entityManager": Failed to start service
              at org.jboss.msc.service.ServiceControllerImpl$StartTask.run(ServiceControllerImpl.java:1780) [jboss-msc-1.0.1.GA.jar:1.0.1.GA]
              at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) [:1.6.0_29]
              at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) [:1.6.0_29]
              at java.lang.Thread.run(Thread.java:662) [:1.6.0_29]
              Caused by: java.lang.OutOfMemoryError: GC overhead limit exceeded
              at java.beans.Introspector.decapitalize(Introspector.java:264) [:1.6.0_29]
              at org.hibernate.annotations.common.reflection.java.JavaXProperty.getName(JavaXProperty.java:56)
              at org.hibernate.cfg.PropertyInferredData.getPropertyName(PropertyInferredData.java:104)
              at org.hibernate.cfg.AnnotationBinder.fillComponent(AnnotationBinder.java:2332)
              at org.hibernate.cfg.AnnotationBinder.mapAsIdClass(AnnotationBinder.java:862)
              at org.hibernate.cfg.AnnotationBinder.bindClass(AnnotationBinder.java:669)
              at org.hibernate.cfg.Configuration$MetadataSourceQueue.processAnnotatedClassesQueue(Configuration.java:3406)
              at org.hibernate.cfg.Configuration$MetadataSourceQueue.processMetadata(Configuration.java:3360)
              at org.hibernate.cfg.Configuration.secondPassCompile(Configuration.java:1334)
              at org.hibernate.cfg.Configuration.buildSessionFactory(Configuration.java:1724)
              at org.hibernate.ejb.EntityManagerFactoryImpl.<init>(EntityManagerFactoryImpl.java:76)
              at org.hibernate.ejb.Ejb3Configuration.buildEntityManagerFactory(Ejb3Configuration.java:905)
              at org.hibernate.ejb.Ejb3Configuration.buildEntityManagerFactory(Ejb3Configuration.java:890)
              at org.hibernate.ejb.HibernatePersistence.createContainerEntityManagerFactory(HibernatePersistence.java:73)
              at org.jboss.as.jpa.service.PersistenceUnitServiceImpl.createContainerEntityManagerFactory(PersistenceUnitServiceImpl.java:149)
              at org.jboss.as.jpa.service.PersistenceUnitServiceImpl.start(PersistenceUnitServiceImpl.java:79)
              at org.jboss.msc.service.ServiceControllerImpl$StartTask.startService(ServiceControllerImpl.java:1824) [jboss-msc-1.0.1.GA.jar:1.0.1.GA]
              at org.jboss.msc.service.ServiceControllerImpl$StartTask.run(ServiceControllerImpl.java:1759) [jboss-msc-1.0.1.GA.jar:1.0.1.GA]
              ... 3 more
              09:39:11,436 INFO  [org.jboss.jpa] (MSC service thread 1-1) JBAS011402: Starting Persistence Unit Service 'icba10.ear/icba10-cbs-routing-ejb.jar#entityManager'
              09:39:11,452 INFO  [org.hibernate.ejb.Ejb3Configuration] (MSC service thread 1-1) HHH000204: Processing PersistenceUnitInfo [

               

              I run the JBoss with this JVM memory allocation Parameter:

               

              "JAVA_OPTS=-Xms512M -Xmx1024M -XX:MaxPermSize=256M"

               

              On my PC still there is around 1GB memory left untouched then why i am getting such error?

              • 4. Re: Startup Goes Very Slow with Scanning Entity Classes from Different Jars
                Mostafa Far Newbie

                I tried to run JBoss with follwoing JVM parameters in order to do further Garbage Collection analysis:

                 

                JAVA_OPTS=-Xms512M -Xmx1024M -XX:MaxPermSize=256M -Xloggc:gclogs.txt -XX:+PrintGCDetails"

                 

                Then, I could see the time is mainly taking up by the process of "Unloading class":

                 

                12:10:46,827 WARN  [org.hibernate.dialect.Oracle9Dialect] (MSC service thread 1-2) HHH000063:
                12:10:46,843 INFO  [org.hibernate.engine.transaction.internal.TransactionFactoryInitiator] (M
                12:10:46,843 INFO  [org.hibernate.hql.internal.ast.ASTQueryTranslatorFactory] (MSC service th
                [Unloading class sun.reflect.GeneratedConstructorAccessor6]
                [Unloading class sun.reflect.GeneratedConstructorAccessor20]
                [Unloading class sun.reflect.GeneratedConstructorAccessor24]
                [Unloading class sun.reflect.GeneratedConstructorAccessor7]
                [Unloading class sun.reflect.GeneratedConstructorAccessor23]
                [Unloading class sun.reflect.GeneratedConstructorAccessor25]
                [Unloading class sun.reflect.GeneratedConstructorAccessor27]
                [Unloading class sun.reflect.GeneratedConstructorAccessor26]
                [Unloading class sun.reflect.GeneratedConstructorAccessor88]
                [Unloading class sun.reflect.GeneratedMethodAccessor6]
                [Unloading class sun.reflect.GeneratedConstructorAccessor47]
                [Unloading class sun.reflect.GeneratedConstructorAccessor16]
                [Unloading class sun.reflect.GeneratedConstructorAccessor40]
                [Unloading class sun.reflect.GeneratedMethodAccessor14]
                ....
                12:12:50,709 INFO  [org.jboss.jpa] (MSC service thread 1-4) JBAS011402: Starting Persistence
                12:12:50,709 INFO  [org.hibernate.ejb.Ejb3Configuration] (MSC service thread 1-4) HHH000204:

                 

                I also have GC log generated with the help of parameters (-Xloggc:gclogs.txt -XX:+PrintGCDetails) which is attached here.

                • 5. Re: Startup Goes Very Slow with Scanning Entity Classes from Different Jars
                  Stephen Coy Master

                  What happens if you double the memory?

                   

                  I suspect that the "[Unloading class ..." messages are side effect of garbage collection btw.

                  • 6. Re: Startup Goes Very Slow with Scanning Entity Classes from Different Jars
                    Mostafa Far Newbie

                    I have 3,5 GB Memory on my pc, and when the JBOSS is run still 1GB is left untouched. However, i am looking for another system here around wth higher memory to test the deployment.

                     

                    Anyway, I like you know that I deploy and run the same application on the same system with JBoss 4.3.

                     

                    Thanks for your help.

                    • 7. Re: Startup Goes Very Slow with Scanning Entity Classes from Different Jars
                      Tomaz Cerar Master

                      what if you add/change settings for PermGen

                      to:

                      -XX:PermSize=256M -XX:MaxPermSize=512M

                       

                      --

                      tomaz

                      • 8. Re: Startup Goes Very Slow with Scanning Entity Classes from Different Jars
                        Mostafa Far Newbie

                        I tested it with: -XX:MaxPermSize=512M

                         

                        The result is the same: Slow and Error is: Caused by: java.lang.OutOfMemoryError: GC overhead limit exceeded

                         

                        • 9. Re: Startup Goes Very Slow with Scanning Entity Classes from Different Jars
                          Stephen Coy Master

                          The gclog indicated that permgen space was not an issue.

                           

                          How many ejb's in each module?

                          • 10. Re: Startup Goes Very Slow with Scanning Entity Classes from Different Jars
                            Tomaz Cerar Master

                            did you try with also with -XX:PermSize=256M

                            this will prevent full gc before expanding PermGen to limits defined by MaxPermSize

                            • 11. Re: Startup Goes Very Slow with Scanning Entity Classes from Different Jars
                              Scott Marlow Master

                              If you guys get stuck, perhaps it would help to look at what is in memory by capturing a heap dump (or a few dump files), that could be looked at with the Eclipse Memory Analyzer tool.  I would capture the heap dump when you know that deployment is thrashing on memory (or at least you think it is). 

                               

                              1. Get the list of java processes with command "jps -l"

                               

                              look for the output line containing jboss-modules.jar (e.g. ProcessID jboss-as-7.1.2.Final-SNAPSHOT/jboss-modules.jar)

                               

                              2. Generate the heap dump(s)

                              jmap -dump:live,format=b,file=heapdump.hprof ProcessID

                               

                              3.  Run MAT tool on the heap dump and see what the memory hog(s) are.  You probably cannot upload the heapdump files because they could contain your app data.  But you could attach some screen shots.

                               

                              Scott

                              • 12. Re: Startup Goes Very Slow with Scanning Entity Classes from Different Jars
                                Mostafa Far Newbie

                                Stephan, at the current stage of the application, numbers of ejbs inside modules varies from 1 to around 15 EJBs. Depends on the type of the modules. and most of the ejbs have less than 5 ejbs.

                                 

                                Tomaz, yes, i tried running JBoss with  -XX:PermSize=256M, same problem there but there is slight diffierence on error message:

                                 

                                Caused by: java.lang.OutOfMemoryError: Java heap space

                                Scott, I have not experience on capturing heap dump, i try to do what you said and share with you what i got.

                                 

                                It's great of you guys helping us here. I really appreciate it.

                                • 13. Re: Startup Goes Very Slow with Scanning Entity Classes from Different Jars
                                  Mostafa Far Newbie

                                  I played with this parameter several times, and following is the best out come i got.

                                  set "JAVA_OPTS=-Xms512M -Xmx1384M -XX:PermSize=128M -XX:MaxPermSize=128M

                                   

                                  application got deployed successfully whithin 7mints .. still Lower than Jboss 4.3.

                                  • 14. Re: Startup Goes Very Slow with Scanning Entity Classes from Different Jars
                                    Stephen Coy Master

                                    I think you may need to consider almalgamating some of your EJB modules.

                                     

                                    This is the effect that you would have had in JBoss 4.3 and it's "big ball of mud" classloader.

                                     

                                    How many different persistence units are there?

                                     

                                    I think each EJB module will be loading it's own copy...

                                    1 2 3 Previous Next