1 2 3 Previous Next 43 Replies Latest reply: Nov 6, 2008 5:59 PM by Scott Stark RSS

JBAS-6104; slow Seam deployments

Ales Justin Master

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
    Ales Justin Master

     

    "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
    Ales Justin Master

     

    "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
    Ales Justin Master

     

    "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
    Jay Balunas Master

    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 Master

    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
    Ales Justin Master

     

    "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
    Marko Strukelj Master

    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 Master

    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
    Ales Justin Master

    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 Master

    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
    Ales Justin Master

     

    "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 Master

    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
    Ales Justin Master

     

    "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
    Pete Muir Master

    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