1 2 Previous Next 23 Replies Latest reply on Mar 27, 2009 9:54 PM by jaikiran pai

    Low performance with JBoss AS 5.0.1 compared with 4.2.3

    Olivier Thierry Apprentice

      Hi,

      I have an EAR that I used to deploy on JBoss AS 4.2.3 and I now deploy it to JBoss AS 5.0.1. It took about 1 minute to startup with 4.2.3 version, now it takes close to 7 minutes with 5.0.1 !!! Once the application is started, performance using the application is bad too compared with the one on 4.2.3.

      I tried to set a lower level for debug (ERROR instead of INFO) but the gain was not significant. My app uses JPA, EJB3 and Seam. It looks like most of the startup time is used to deploy my EJB jars. What could explain such low performance ?

      Note I also have a lot of WARN messages like this one :

      10:06:32,213 WARN [Ejb3AnnotationHandler] JBMETA-4: did not find any bean meta data for annotation bean DecisionHandlerBean, will create some


      Or like this one :

      10:10:05,445 WARN [WebServiceDeployerEJB] Ingore ejb deployment with null classname: org.jboss.metadata.ejb.jboss.JBossSessionBeanMetaData@8eaa8cb5{OrganizationInternalServiceBean}
      


      What do these warnings mean ? Could they be the cause of low performance ?

      Thanks in advance for any help.

      Regards,

      Olivier

        • 1. Re: Low performance with JBoss AS 5.0.1 compared with 4.2.3
          Ales Justin Master

          Are you deploying outside deploy/ dir?

          As 7min is just strangely too much, our Seam examples deploy pretty fast,
          and they use all of the stuff you mentioned - JPA, EJB, ...

          • 2. Re: Low performance with JBoss AS 5.0.1 compared with 4.2.3
            jaikiran pai Master

            In addition to what Ales asked - how many EJBs does your application have? From the logs or some profiler are you able to find out where the time is being spent?

            • 3. Re: Low performance with JBoss AS 5.0.1 compared with 4.2.3
              Olivier Thierry Apprentice

              Thanks for your response.

              To deploy, I just copy my EAR file to deploy directory. Then I start JBoss from Eclipse via JBoss Tools, but I don't think it should be different.

              I add these VM arguments (most of them added by JBoss Tools) on server startup :

              -Dprogram.name="JBossTools JBoss 5.0.1 Runtime"
              -Xms256m
              -Xmx512m
              -XX:MaxPermSize=256m
              -Dsun.rmi.dgc.client.gcInterval=3600000
              -Dsun.rmi.dgc.server.gcInterval=3600000
              -Djava.endorsed.dirs="C:/t4-dev/jboss/jboss-5.0.1.GA/lib/endorsed"
              -Dhibernate.dialect=org.hibernate.dialect.HSQLDialect -Dhibernate.hbm2ddl.auto=update


              Here are JBoss AS startup logs :

              10:51:11,431 INFO [ServerImpl] Starting JBoss (Microcontainer)...
              10:51:11,446 INFO [ServerImpl] Release ID: JBoss [Morpheus] 5.0.1.GA (build: SVNTag=JBoss_5_0_1_GA date=200902232048)
              10:51:11,446 INFO [ServerImpl] Bootstrap URL: null
              10:51:11,446 INFO [ServerImpl] Home Dir: C:\t4-dev\jboss\jboss-5.0.1.GA
              10:51:11,446 INFO [ServerImpl] Home URL: file:/C:/t4-dev/jboss/jboss-5.0.1.GA/
              10:51:11,446 INFO [ServerImpl] Library URL: file:/C:/t4-dev/jboss/jboss-5.0.1.GA/lib/
              10:51:11,446 INFO [ServerImpl] Patch URL: null
              10:51:11,446 INFO [ServerImpl] Common Base URL: file:/C:/t4-dev/jboss/jboss-5.0.1.GA/common/
              10:51:11,446 INFO [ServerImpl] Common Library URL: file:/C:/t4-dev/jboss/jboss-5.0.1.GA/common/lib/
              10:51:11,446 INFO [ServerImpl] Server Name: default
              10:51:11,446 INFO [ServerImpl] Server Base Dir: C:\t4-dev\jboss\jboss-5.0.1.GA\server
              10:51:11,446 INFO [ServerImpl] Server Base URL: file:/C:/t4-dev/jboss/jboss-5.0.1.GA/server/
              10:51:11,446 INFO [ServerImpl] Server Config URL: file:/C:/t4-dev/jboss/jboss-5.0.1.GA/server/default/conf/
              10:51:11,446 INFO [ServerImpl] Server Home Dir: C:\t4-dev\jboss\jboss-5.0.1.GA\server\default
              10:51:11,446 INFO [ServerImpl] Server Home URL: file:/C:/t4-dev/jboss/jboss-5.0.1.GA/server/default/
              10:51:11,446 INFO [ServerImpl] Server Data Dir: C:\t4-dev\jboss\jboss-5.0.1.GA\server\default\data
              10:51:11,446 INFO [ServerImpl] Server Library URL: file:/C:/t4-dev/jboss/jboss-5.0.1.GA/server/default/lib/
              10:51:11,446 INFO [ServerImpl] Server Log Dir: C:\t4-dev\jboss\jboss-5.0.1.GA\server\default\log
              10:51:11,446 INFO [ServerImpl] Server Native Dir: C:\t4-dev\jboss\jboss-5.0.1.GA\server\default\tmp\native
              10:51:11,446 INFO [ServerImpl] Server Temp Dir: C:\t4-dev\jboss\jboss-5.0.1.GA\server\default\tmp
              10:51:11,446 INFO [ServerImpl] Server Temp Deploy Dir: C:\t4-dev\jboss\jboss-5.0.1.GA\server\default\tmp\deploy
              10:51:12,506 INFO [ServerImpl] Starting Microcontainer, bootstrapURL=file:/C:/t4-dev/jboss/jboss-5.0.1.GA/server/default/conf/bootstrap.xml
              10:51:13,394 INFO [VFSCacheFactory] Initializing VFSCache [org.jboss.virtual.plugins.cache.CombinedVFSCache]
              10:51:13,394 INFO [VFSCacheFactory] Using VFSCache [CombinedVFSCache[real-cache: null]]
              10:51:13,846 INFO [CopyMechanism] VFS temp dir: C:\t4-dev\jboss\jboss-5.0.1.GA\server\default\tmp
              10:51:13,846 INFO [ZipEntryContext] VFS force nested jars copy-mode is enabled.
              10:51:15,873 INFO [ServerInfo] Java version: 1.6.0_12,Sun Microsystems Inc.
              10:51:15,873 INFO [ServerInfo] Java Runtime: Java(TM) SE Runtime Environment (build 1.6.0_12-b04)
              10:51:15,873 INFO [ServerInfo] Java VM: Java HotSpot(TM) Client VM 11.2-b01,Sun Microsystems Inc.
              10:51:15,873 INFO [ServerInfo] OS-System: Windows XP 5.1,x86
              10:51:15,966 INFO [JMXKernel] Legacy JMX core initialized
              10:51:19,161 INFO [ProfileServiceImpl] Loading profile: default from: org.jboss.system.server.profileservice.repository.SerializableDeploymentRepository@a083f2(root=C:\t4-dev\jboss\jboss-5.0.1.GA\server, key=org.jboss.profileservice.spi.ProfileKey@143b82c3[domain=default,server=default,name=default])
              10:51:19,161 INFO [ProfileImpl] Using repository:org.jboss.system.server.profileservice.repository.SerializableDeploymentRepository@a083f2(root=C:\t4-dev\jboss\jboss-5.0.1.GA\server, key=org.jboss.profileservice.spi.ProfileKey@143b82c3[domain=default,server=default,name=default])
              10:51:19,161 INFO [ProfileServiceImpl] Loaded profile: ProfileImpl@c22978{key=org.jboss.profileservice.spi.ProfileKey@143b82c3[domain=default,server=default,name=default]}
              10:51:22,263 INFO [WebService] Using RMI server codebase: http://ws-r1-be03:8083/
              10:51:34,311 INFO [NativeServerConfig] JBoss Web Services - Stack Native Core
              10:51:34,311 INFO [NativeServerConfig] 3.0.5.GA


              And here are the first logs I have when starting the application :

              10:52:00,121 INFO [Ejb3DependenciesDeployer] Encountered deployment AbstractVFSDeploymentContext@9796844{vfszip:/C:/t4-dev/jboss/jboss-5.0.1.GA/server/default/deploy/t4-ihm-self-ear-1.0-SNAPSHOT.ear/jboss-seam-2.1.1.GA.jar/}
              10:52:00,121 INFO [Ejb3DependenciesDeployer] Encountered deployment AbstractVFSDeploymentContext@9796844{vfszip:/C:/t4-dev/jboss/jboss-5.0.1.GA/server/default/deploy/t4-ihm-self-ear-1.0-SNAPSHOT.ear/jboss-seam-2.1.1.GA.jar/}
              10:52:00,121 INFO [Ejb3DependenciesDeployer] Encountered deployment AbstractVFSDeploymentContext@19724733{vfszip:/C:/t4-dev/jboss/jboss-5.0.1.GA/server/default/deploy/t4-ihm-self-ear-1.0-SNAPSHOT.ear/t4-core-all-1.0-SNAPSHOT.jar/}
              10:52:00,121 INFO [Ejb3DependenciesDeployer] Encountered deployment AbstractVFSDeploymentContext@19724733{vfszip:/C:/t4-dev/jboss/jboss-5.0.1.GA/server/default/deploy/t4-ihm-self-ear-1.0-SNAPSHOT.ear/t4-core-all-1.0-SNAPSHOT.jar/}
              10:52:00,137 INFO [Ejb3DependenciesDeployer] Encountered deployment AbstractVFSDeploymentContext@19724733{vfszip:/C:/t4-dev/jboss/jboss-5.0.1.GA/server/default/deploy/t4-ihm-self-ear-1.0-SNAPSHOT.ear/t4-core-all-1.0-SNAPSHOT.jar/}
              10:52:00,137 INFO [Ejb3DependenciesDeployer] Encountered deployment AbstractVFSDeploymentContext@19724733{vfszip:/C:/t4-dev/jboss/jboss-5.0.1.GA/server/default/deploy/t4-ihm-self-ear-1.0-SNAPSHOT.ear/t4-core-all-1.0-SNAPSHOT.jar/}
              10:52:00,137 INFO [Ejb3DependenciesDeployer] Encountered deployment AbstractVFSDeploymentContext@29364986{vfszip:/C:/t4-dev/jboss/jboss-5.0.1.GA/server/default/deploy/t4-ihm-self-ear-1.0-SNAPSHOT.ear/t4-ihm-self-ejb-1.0-SNAPSHOT.jar/}
              10:52:00,137 INFO [Ejb3DependenciesDeployer] Encountered deployment AbstractVFSDeploymentContext@29364986{vfszip:/C:/t4-dev/jboss/jboss-5.0.1.GA/server/default/deploy/t4-ihm-self-ear-1.0-SNAPSHOT.ear/t4-ihm-self-ejb-1.0-SNAPSHOT.jar/}
              10:52:00,137 INFO [Ejb3DependenciesDeployer] Encountered deployment AbstractVFSDeploymentContext@29364986{vfszip:/C:/t4-dev/jboss/jboss-5.0.1.GA/server/default/deploy/t4-ihm-self-ear-1.0-SNAPSHOT.ear/t4-ihm-self-ejb-1.0-SNAPSHOT.jar/}
              10:52:00,137 INFO [Ejb3DependenciesDeployer] Encountered deployment AbstractVFSDeploymentContext@29364986{vfszip:/C:/t4-dev/jboss/jboss-5.0.1.GA/server/default/deploy/t4-ihm-self-ear-1.0-SNAPSHOT.ear/t4-ihm-self-ejb-1.0-SNAPSHOT.jar/}
              10:52:00,137 INFO [Ejb3DependenciesDeployer] Encountered deployment AbstractVFSDeploymentContext@18750094{vfszip:/C:/t4-dev/jboss/jboss-5.0.1.GA/server/default/deploy/t4-ihm-self-ear-1.0-SNAPSHOT.ear/t4-module-commons-core-1.0-SNAPSHOT.jar/}
              10:52:00,137 INFO [Ejb3DependenciesDeployer] Encountered deployment AbstractVFSDeploymentContext@18750094{vfszip:/C:/t4-dev/jboss/jboss-5.0.1.GA/server/default/deploy/t4-ihm-self-ear-1.0-SNAPSHOT.ear/t4-module-commons-core-1.0-SNAPSHOT.jar/}
              10:52:00,137 INFO [Ejb3DependenciesDeployer] Encountered deployment AbstractVFSDeploymentContext@18750094{vfszip:/C:/t4-dev/jboss/jboss-5.0.1.GA/server/default/deploy/t4-ihm-self-ear-1.0-SNAPSHOT.ear/t4-module-commons-core-1.0-SNAPSHOT.jar/}
              10:52:00,137 INFO [Ejb3DependenciesDeployer] Encountered deployment AbstractVFSDeploymentContext@18750094{vfszip:/C:/t4-dev/jboss/jboss-5.0.1.GA/server/default/deploy/t4-ihm-self-ear-1.0-SNAPSHOT.ear/t4-module-commons-core-1.0-SNAPSHOT.jar/}
              10:52:00,137 INFO [Ejb3DependenciesDeployer] Encountered deployment AbstractVFSDeploymentContext@23175637{vfszip:/C:/t4-dev/jboss/jboss-5.0.1.GA/server/default/deploy/t4-ihm-self-ear-1.0-SNAPSHOT.ear/t4-module-gt-core-1.0-SNAPSHOT.jar/}
              10:52:00,137 INFO [Ejb3DependenciesDeployer] Encountered deployment AbstractVFSDeploymentContext@23175637{vfszip:/C:/t4-dev/jboss/jboss-5.0.1.GA/server/default/deploy/t4-ihm-self-ear-1.0-SNAPSHOT.ear/t4-module-gt-core-1.0-SNAPSHOT.jar/}
              10:52:00,137 INFO [Ejb3DependenciesDeployer] Encountered deployment AbstractVFSDeploymentContext@23175637{vfszip:/C:/t4-dev/jboss/jboss-5.0.1.GA/server/default/deploy/t4-ihm-self-ear-1.0-SNAPSHOT.ear/t4-module-gt-core-1.0-SNAPSHOT.jar/}
              10:52:00,137 INFO [Ejb3DependenciesDeployer] Encountered deployment AbstractVFSDeploymentContext@23175637{vfszip:/C:/t4-dev/jboss/jboss-5.0.1.GA/server/default/deploy/t4-ihm-self-ear-1.0-SNAPSHOT.ear/t4-module-gt-core-1.0-SNAPSHOT.jar/}
              


              I don't know how I could find what causes these low performance :(

              • 4. Re: Low performance with JBoss AS 5.0.1 compared with 4.2.3
                Olivier Thierry Apprentice

                 

                "jaikiran" wrote:
                In addition to what Ales asked - how many EJBs does your application have?


                For the moment we have 365 EJB3 components, but we will have a lot more in the future.

                "jaikiran" wrote:
                From the logs or some profiler are you able to find out where the time is being spent?


                From the logs, I can see these phases in server / application startup :

                1 - AS startup : about 45 seconds

                2 - Application deployment : about 3 minutes

                I mean messages like this one :

                10:55:15,991 INFO [JBossASKernel] installing bean: jboss.j2ee:ear=t4-ihm-self-ear-1.0-SNAPSHOT.ear,jar=t4-module-gt-core-1.0-SNAPSHOT.jar,name=EmployeeServiceBean,service=EJB3
                10:55:15,991 INFO [JBossASKernel] with dependencies:
                10:55:15,991 INFO [JBossASKernel] and demands:
                10:55:16,006 INFO [JBossASKernel] jboss.ejb:service=EJBTimerService
                10:55:16,006 INFO [JBossASKernel] and supplies:
                10:55:16,006 INFO [JBossASKernel] Class:t4.module.commons.employee.EmployeeServiceLocal
                10:55:16,006 INFO [JBossASKernel] Added bean(jboss.j2ee:ear=t4-ihm-self-ear-1.0-SNAPSHOT.ear,jar=t4-module-gt-core-1.0-SNAPSHOT.jar,name=EmployeeServiceBean,service=EJB3) to KernelDeployment of: t4-module-gt-core-1.0-SNAPSHOT.jar
                


                3 - Hibernate / JPA startup and schema update : about 10 seconds

                4 - EJB3 startup : about 1 minute and 30 seconds

                10:56:13,441 INFO [SessionSpecContainer] Starting jboss.j2ee:ear=t4-ihm-self-ear-1.0-SNAPSHOT.ear,jar=t4-ihm-self-ejb-1.0-SNAPSHOT.jar,name=DictionaryFacadeServiceBean,service=EJB3
                10:56:13,441 INFO [EJBContainer] STARTED EJB: t4.core.utils.dictionary.facade.DictionaryFacadeServiceBean ejbName: DictionaryFacadeServiceBean
                10:56:13,441 INFO [JndiSessionRegistrarBase] Binding the following Entries in Global JNDI:
                


                5 - Seam startup : about 30 seconds

                So I think most of the time is consumed with application deployment.

                • 5. Re: Low performance with JBoss AS 5.0.1 compared with 4.2.3
                  jaikiran pai Master

                   

                  "chawax" wrote:

                  For the moment we have 365 EJB3 components, but we will have a lot more in the future.

                  I have seen some more users mentioning that the startup time isn't good (as compared to 4.x) when the number of EJBs in their application is many.

                  Thank you for breaking down the timings to explain what's happening. Any chance of making this application available to test out what's going on? If not, i'll try and come up with a sample application which tries to reproduce this.

                  • 6. Re: Low performance with JBoss AS 5.0.1 compared with 4.2.3
                    Olivier Thierry Apprentice

                    I am sorry I can't make the application available since it is confidential code :(

                    By the way, are there recommandations about memory configuration for JBoss ? If I don't affect enough memory to JBoss, is there a risk that garbage collector never stops working, causing performance problems ?

                    • 7. Re: Low performance with JBoss AS 5.0.1 compared with 4.2.3
                      Dimitris Andreadis Master

                      Try doubling the heap size to see if it makes any difference:

                      -Xmx1024m

                      • 8. Re: Low performance with JBoss AS 5.0.1 compared with 4.2.3
                        Olivier Thierry Apprentice

                        I just tried and it changed nothing, still about 7 minutes to startup.

                        • 9. Re: Low performance with JBoss AS 5.0.1 compared with 4.2.3
                          Peter Johnson Master

                          Regarding the garbage collection, which collector are you using? If you do not specify a collector, your application (JBoss AS + all deployed apps) stops while collection happens - so it will complete, it has to before the app can continue. If you use the CMS collector, the collection thread runs along with your app, so with CMS you could find yourself in continuous collection mode.

                          See my presentation for details: http://www.cecmg.de/doc/tagung_2007/agenda07/24-mai/2b3-peter-johnson/index.html

                          • 10. Re: Low performance with JBoss AS 5.0.1 compared with 4.2.3
                            Olivier Thierry Apprentice

                            I improved a lot startup performance. My JBOSS_HOME pointed to my old JBoss 4.2.3 installation. I changed it to point to JBoss 5.0.1 directory, it now takes 4 minutes and 45 seconds to startup compared to 7 minutes before I changed this. Anyway I think it's still too long, I really worry about how long it will be when my application will be complete with thousands of EJB3 session beans :(

                            • 11. Re: Low performance with JBoss AS 5.0.1 compared with 4.2.3
                              jaikiran pai Master

                               

                              "chawax" wrote:
                              I improved a lot startup performance. My JBOSS_HOME pointed to my old JBoss 4.2.3 installation. I changed it to point to JBoss 5.0.1 directory, it now takes 4 minutes and 45 seconds to startup compared to 7 minutes before I changed this.


                              I am not sure what the problem was. But you earlier logs did show that you were using 5.0.1 GA,

                              /C:/t4-dev/jboss/jboss-5.0.1.GA/


                              so i don't think the JBOSS_HOME was messing the startup time.

                              • 12. Re: Low performance with JBoss AS 5.0.1 compared with 4.2.3
                                Olivier Thierry Apprentice

                                I agree it is very strange, but this is what I noted ;) And that's the only thing I changed from wednesday, I changed nothing in the EAR !

                                • 13. Re: Low performance with JBoss AS 5.0.1 compared with 4.2.3
                                  Tony Mai Apprentice

                                  I too have experienced severe performance with JBoss 5.1.0Beta1. Our application also has several hundred EJB beans.

                                  A simple login page using Seam 2.1.1 used to take a few seconds (in 4.2.1GA) now takes minutes. I have not collected sufficient statistics like chawax but it was quite obvious that the AS takes a long time to load EJB related beans (session/entity).

                                  The performance will definitely hinder our upgrade as QA will not even entertain testing the ported app.

                                  As soon as the porting is relatively stable, I will put the app under a profiler. Will post if find anything relevant.

                                  Thanks
                                  -tony


                                  • 14. Re: Low performance with JBoss AS 5.0.1 compared with 4.2.3
                                    jaikiran pai Master

                                     

                                    "tonylmai" wrote:


                                    A simple login page using Seam 2.1.1 used to take a few seconds (in 4.2.1GA) now takes minutes.

                                    Hmmm, so its not pure EJB3. I remember there was extensive testing/discussion in the forums about Seam related web application performance in AS 5.x and from what i know they had been fixed.


                                    "tonylmai" wrote:

                                    As soon as the porting is relatively stable, I will put the app under a profiler. Will post if find anything relevant.


                                    Thanks, we would like to have that info. I'm also trying to get it reproduced locally, but do post your findings too. And please create a separate thread when you post those findings so that the discussions are not mixed up :)


                                    1 2 Previous Next