1 2 3 Previous Next 43 Replies Latest reply on Nov 6, 2008 5:59 PM by starksm64

    JBAS-6104; slow Seam deployments

    alesj

      Moving the https://jira.jboss.org/jira/browse/JBAS-6104 discussion here.

      Instructions to re-produce error:

      "Jozef Hartinger" wrote:

      I have encountered strange behaviour of AS when testing Seam 2.0.3.CR1 recently. To reproduce follow these steps:
      a) deploy Seam booking example
      b) some interaction is needed so book some hotel
      c) undeploy Seam booking example
      d) deploy Seam drools example
      example starts to deploy but at some point it hangs and looks like nothing is happening - no messages being appended in log not even debug messages however I noticed heavy disk usage. Usualy after waiting more than 10 minutes second example is still not deployed. It happens in both Seam 2.0.3.CR1 and Seam 2.1.0.CR1. Same situation with registration and itext example. Issue may be caused by problem with undeploying the first example. in some cases second example gets deployed after several minutes.


      Stan is able to re-produce it with different set of Seam examples:
      "Stan Silvert" wrote:

      I took a look at this. I used numberguess instead of drools, but followed the same steps above.
      What I found was that numberguess does eventually get deployed and will work properly if you wait about 5 minutes after step d).

      I guess something needs to time out. It's definitely weird behavior.


      Shane's investigation begins. :-)
      "Shane Bryzak" wrote:

      Not much progress on this so far, I got to step c, undeploying the booking example which worked however threw some exceptions during undeployment. I then tried to deploy the drools example, which cause the app server to just sit there grinding the hard disk for at least 30 minutes (with no successful deploy).

      I'm currently building the latest trunk of JBossAS so that I have something a little more recent to test against.


      "Shane Bryzak" wrote:

      Ok not looking much better on latest trunk either.. the HotDeployFilter bug is still happening (every single request is resulting in a full redeploy) and it's generally running dog slow. I'll spent some time profiling to try and nail down some more specific details.


        • 1. Re: JBAS-6104; slow Seam deployments
          alesj

           

          "Shane Bryzak" wrote:

          the HotDeployFilter bug is still happening (every single request is resulting in a full redeploy)

          I need to update Seam-int with Pete's update on VFSScanner::getTimestamp.
          I'll do it today and let you know when it's included in AS_trunk.

          • 2. Re: JBAS-6104; slow Seam deployments
            alesj

             

            "alesj" wrote:

            I need to update Seam-int with Pete's update on VFSScanner::getTimestamp.
            I'll do it today and let you know when it's included in AS_trunk.

            AS_trunk is now updated to use jboss-seam-int_5.0.0.CR4.

            VFSScanner now implements getTimestamp,
            SeamIntegration deployer now also understands WEB-INF/classes/seam.properties and WEB-INF/classes/META-INF/components.xml.
            And I think I also (finally) ported over Shane's TopicConnection change.

            • 3. Re: JBAS-6104; slow Seam deployments
              alesj

               

              "Jay Balunas" wrote:

              Here is the console logging related to this. You'll notice that the time goes from "08:56:37,914" to "09:06:05,790". This 10 minutes saw a large amount of disk usage and and memory consumption. I will also attach a subset of the server.log that corresponds to this time.


              08:56:37,314 INFO [EJBContainer] STOPPED EJB: com.jboss.dvd.seam.AuthenticatorAction ejbName: AuthenticatorAction
              08:56:37,381 INFO [SessionSpecContainer] Stopping jboss.j2ee:ear=jboss-seam-dvd.ear,jar=jboss-seam-dvd.jar,name=AcceptAction,service=EJB3
              08:56:37,381 INFO [EJBContainer] STOPPED EJB: com.jboss.dvd.seam.AcceptAction ejbName: AcceptAction
              08:56:37,453 INFO [PersistenceUnitDeployment] Stopping persistence unit persistence.unit:unitName=jboss-seam-dvd.ear/jboss-seam-dvd.jar#dvdDatabase
              08:56:37,454 INFO [SessionFactoryImpl] closing
              08:56:37,454 INFO [SchemaExport] Running hbm2ddl schema export
              08:56:37,510 INFO [SchemaExport] exporting generated schema to database
              08:56:37,513 INFO [SchemaExport] schema export complete
              08:56:37,513 INFO [SessionFactoryObjectFactory] Unbinding factory from JNDI name: persistence.unit:unitName=jboss-seam-dvd.ear/jboss-seam-dvd.jar#dvdDatabase
              08:56:37,513 INFO [NamingHelper] JNDI InitialContext properties:{}
              08:56:37,513 INFO [SessionFactoryObjectFactory] Unbound factory from JNDI name: persistence.unit:unitName=jboss-seam-dvd.ear/jboss-seam-dvd.jar#dvdDatabase
              08:56:37,914 WARN [HackClassloaderMetaDataDeployer] FIXME Using loader repository config: seam.jboss.org:loader=seam-dvd for vfszip:/jboss/projects/seam/2.1.0.GA/jboss-5.0.0.CR2/server/default/deploy/jboss-seam-dvd.ear use classloading metadata not loader repository config
              09:06:05,790 WARN [EjbMetadataJndiPolicyDecoratorDeployer] Defaulting to DefaultJndiBindingPolicy of "org.jboss.metadata.ejb.jboss.jndipolicy.plugins.BasicJndiBindingPolicy" for Session Bean ShowOrdersAction
              09:06:05,790 WARN [EjbMetadataJndiPolicyDecoratorDeployer] Defaulting to DefaultJndiBindingPolicy of "org.jboss.metadata.ejb.jboss.jndipolicy.plugins.BasicJndiBindingPolicy" for Session Bean AuthenticatorAction
              09:06:05,790 WARN [EjbMetadataJndiPolicyDecoratorDeployer] Defaulting to DefaultJndiBindingPolicy of "org.jboss.metadata.ejb.jboss.jndipolicy.plugins.BasicJndiBindingPolicy" for Session Bean CheckoutAction
              09:06:05,790 WARN [EjbMetadataJndiPolicyDecoratorDeployer] Defaulting to DefaultJndiBindingPolicy of "org.jboss.metadata.ejb.jboss.jndipolicy.plugins.BasicJndiBindingPolicy" for Session Bean FullTextSearchAction
              09:06:05,791 WARN [EjbMetadataJndiPolicyDecoratorDeployer] Defaulting to DefaultJndiBindingPolicy of "org.jboss.metadata.ejb.jboss.jndipolicy.plugins.BasicJndiBindingPolicy" for Session Bean EditCustomerAction
              09:06:05,791 WARN [EjbMetadataJndiPolicyDecoratorDeployer] Defaulting to DefaultJndiBindingPolicy of "org.jboss.metadata.ejb.jboss.jndipolicy.plugins.BasicJndiBindingPolicy" for Session Bean ShoppingCartBean
              09:06:05,791 WARN [EjbMetadataJndiPolicyDecoratorDeployer] Defaulting to DefaultJndiBindingPolicy of "org.jboss.metadata.ejb.jboss.jndipolicy.plugins.BasicJndiBindingPolicy" for Session Bean AcceptAction


              • 4. Re: JBAS-6104; slow Seam deployments
                jbalunas

                one more thing that I found. This no only effects redeploying the same application, it effect deploying any other seam application.

                Without restarting I undeployed an application and deployed a different one with the same result.

                • 5. Re: JBAS-6104; slow Seam deployments
                  shane.bryzak

                  The HotDeployFilter fix has improved the performance marginally, however there are still some severe performance issues. I've been doing some profiling during session initialisation of a Seam application and a large chunk of time is spent in org.jboss.virtual.plugins.context.zip.ZipEntrycontext.initEntries(). This method is invoked 480 times, for a total cpu time of 161 seconds. I think someone needs to review this method to see if it can be optimised somehow.

                  • 6. Re: JBAS-6104; slow Seam deployments
                    alesj

                     

                    "shane.bryzak@jboss.com" wrote:
                    I've been doing some profiling during session initialisation of a Seam application and a large chunk of time is spent in org.jboss.virtual.plugins.context.zip.ZipEntrycontext.initEntries(). This method is invoked 480 times, for a total cpu time of 161 seconds. I think someone needs to review this method to see if it can be optimised somehow.

                    Looks like Seam is doing most of the resource lookup work based on URLs.
                    And with no URL/VFS/resource/etc caching, VFS needs to re-create the whole structure over and over again,
                    hence unpacking nested stuff, re-initializing it on every unpack.
                    This should go away with better Seam+MC+AS integration.
                    But yeah, meanwhile I'll have a look what can be done.

                    • 7. Re: JBAS-6104; slow Seam deployments
                      mstruk

                      I'll take a closer look into this (since it's mostly my code there ;) and report when I discover something ...

                      - marko

                      • 8. Re: JBAS-6104; slow Seam deployments
                        shane.bryzak

                        It does get called a lot from javax.faces.application.ViewHandler.renderView() - there are 524 invocations of org.jboss.virtual.plugins.vfs.VirtualFileURLConnection.getInputStream().

                        • 9. Re: JBAS-6104; slow Seam deployments
                          alesj

                          Marko found the issue - it was my poor impl of CL's ResourceContext.
                          I already fixed it - JBCL-50 - and should be included with next JBoss-Classloading release.

                          • 10. Re: JBAS-6104; slow Seam deployments
                            shane.bryzak

                            Excellent - can you please let me know when this makes it into jbossas trunk and I'll do some more performance testing.

                            • 11. Re: JBAS-6104; slow Seam deployments
                              alesj

                               

                              "shane.bryzak@jboss.com" wrote:
                              can you please let me know when this makes it into jbossas trunk and I'll do some more performance testing.

                              The changes are in the trunk. ;-)

                              • 12. Re: JBAS-6104; slow Seam deployments
                                shane.bryzak

                                Ok I've done a clean build with latest trunk and I'm afraid to say there hasn't been much of an improvement. I've included part of the call tree in case it's some help.

                                53.0% - 152 s - 1 inv. org.ajax4jsf.application.AjaxViewHandler.renderView
                                50.3% - 144 s - 1 inv. org.ajax4jsf.application.ViewHandlerWrapper.renderView
                                50.3% - 144 s - 1 inv. javax.faces.application.ViewHandler.renderView
                                42.4% - 122 s - 527 inv. org.jboss.virtual.plugins.vfs.VirtualFileURLConnection.getInputStream
                                41.5% - 119 s - 527 inv. org.jboss.virtual.plugins.vfs.VirtualFileURLConnection.getVirtualFile
                                41.5% - 119 s - 527 inv. org.jboss.virtual.plugins.vfs.VirtualFileURLConnection.resolveVirtualFile
                                41.3% - 118 s - 527 inv. org.jboss.virtual.VFS.findChild
                                41.3% - 118 s - 527 inv. org.jboss.virtual.plugins.context.AbstractVFSContext.getChild
                                41.2% - 118 s - 373 inv. org.jboss.virtual.plugins.context.DelegatingHandler.getChild
                                41.2% - 118 s - 373 inv. org.jboss.virtual.plugins.context.zip.ZipEntryHandler.getChild
                                41.2% - 118 s - 373 inv. org.jboss.virtual.plugins.context.AbstractVirtualFileHandler.structuredFindChild
                                24.9% - 71,681 ms - 536 inv. org.jboss.virtual.plugins.context.zip.ZipEntryHandler.createChildHandler
                                16.2% - 46,689 ms - 60 inv. org.jboss.virtual.plugins.context.DelegatingHandler.getChild

                                • 13. Re: JBAS-6104; slow Seam deployments
                                  alesj

                                   

                                  "shane.bryzak@jboss.com" wrote:
                                  there hasn't been much of an improvement

                                  The fix is probably fixing the problem at re-deploy.
                                  Or is that what you tested?

                                  As long as there's gonna be a lot of URL usage, VFS is gonna be slow.
                                  Since VFS URL doesn't know that there's already an un-packed version of that resource somewhere.

                                  Need to see what can be done ...

                                  • 14. Re: JBAS-6104; slow Seam deployments
                                    pmuir

                                    Yeah, you fixed the redeploy - works great now (in fact AS5 is approaching AS 4.2 speeds on my machine for startup and deployment :-).

                                    I think Shane and you/Marko got your wires crossed, and his latter comments are regarding runtime not deployment performance.

                                    From:

                                    It does get called a lot from javax.faces.application.ViewHandler.renderView() - there are 524 invocations of org.jboss.virtual.plugins.vfs.VirtualFileURLConnection.getInputStream().


                                    Shane is talking about runtime performance (when rendering a view) NOT about deployment :-)

                                    1 2 3 Previous Next