[jboss-jira] [JBoss JIRA] (WFLY-9460) Sample application with 4999 CDI beans 19 seconds on initial scanning and only 2 seconds of WeldBootStrap
Nuno Godinho de Matos (JIRA)
issues at jboss.org
Sat Oct 21 04:48:00 EDT 2017
[ https://issues.jboss.org/browse/WFLY-9460?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13480178#comment-13480178 ]
Nuno Godinho de Matos edited comment on WFLY-9460 at 10/21/17 4:47 AM:
-----------------------------------------------------------------------
Hi,
Thank you for all the insights on this.
it is in fact the case that this artificially created application with 4999 beans is quite small in relation to the application whose deployment time I am trying to reduce.
And it is also quite trivial, interns of where the source code is to be found.
- The WEB-INF/lib folder of this sample app is almost empty
- on the application I am looking at:
WEB-INF/classes is 100% empty, the WAR is just a packaging element for all of the software components that are in the WEB-INF/lib.
In short, there is a lot more of a variety of JEE elements.
>From CDI, to Mdbs, to EJBs etc...
But in any case, one trend is the same, I would say that the source code distribution is most likely 70 to 80% logic written in CDI components.
And the rest:
EJBs, Mdbs and such are a small layer to manage either JTA transaction context or defining app entrypoints. In short, CDI is king, and the rest is small talk.
I suspect that in this case, it is of benefit to have WEB-INF/lib/whateverComponent.jar/META-INF/holdingJandex.idx.
One thing I would like to understand better, it is not quite clear to me, is how much of the WeldBootstrap performance is in the hands of the AppServer integrator?
I have the feeling that it is still quite a little bit.
Let me explain my impression, and you can correct me if am wrong.
1. Every app server, regardless of who implements it, is doomed - it would appear - on a very initial phase of its startup logic, to loop over the classes on that package that is being deployed.
Without knowing any better, I would call this a Greedy bootstrapping of War application class loader.
Would say that this is correct?
In short:
The more classes you have in there, the more it will cost to initiate this class loader.
Analysis:
For the sample application the first few seconds of "log silence". In the case of our sample application with Jandex index, this costs about 6 seconds and without it, about 17 seconds where the cost of creating the index is not so insignificant.
But the point is also, the cost payed to have a Jandex index will on further phases of deployment pay for itself. Its metadata will allow the next processes to be faster.
And perhaps more than one process (Weld, Jersey, whoever) will want to ask the same questions and therefore it is better to build a dictionary of answers to all of these guys.
So these first few seconds of deployment are critical step of metadata acquisition to lower the runtime cost of the Class instances that will start to execute next.
2. Different application servers can manifest a significantly different performance on their first moment of log silence.
- You would say this is correct?
Some may want to have Jandex index, others may want to invent their own competing optimisations.
3. At some point, the class loader that gives the appropriate isolation for the web application is ready and other software components can start running.
One of these will be Weld.
- Correct?
4. WeldBoostraping logic starts, it has many queries that it needs to have answered, such as:
What Deployments units (e.g jars) exists in the context of this web application.
For each deployment unit what classes are in there that should be treated as CDI beans, etc...
And here I would like to understand:
4.1 How much of this cost will depend from AppServer to AppServer - and what are the main attributes that bring this cost variance:
- Is it Class Loader performance?
4.2 Is Jandex transparently used by Weld Or explicitly used by Weld?
The question is? If I search the source code of Weld for references to Jandex do I find any reference to It or not?
If the answer to this question is: NO you find none.
- Then I would say Jandex is an optimisation that is transparent for the software writer. It is somehow encoded into the class loader and other APIs performance that one may want to use, that get in the background optimised by the gander metadata.
If the answer is Yes: references to Jandex will be found.
- This means software writer must explicitly want to use its metadata. There aren't really any APIs (class loader, Reflection queries over a class, etc...) that get in back stage tuned via Jandex to be more reactive. One needs to want to use it, to actually feel its benefit.
So which of the two approaches is taking place?
4.3 If one must explicitly want to use Jandex, then depending on the Weld version available on a given AppServer, the WeldBoostraping cost should be fairly similar.
Is this correct?
NOTE:
- On this question, I am under the impression that the WeldBoostrap performance differed from app server to app server significantly.
In the case of the application I am analysing it is 6 seconds Wildfly against 19 seconds on a third party app server.
That is a big difference.
- I know that on Wildfly the hunt for the classes in each deployment unit is taking 2 seconds
- On the third party app server this hunt was taking 6 seconds and could be lowered to 4 seconds by putting to with the ConcurrentDeployer (so here just bad configuration)
- I know that the deployBeans() phase on Wildly is taking about 2 seconds, and on the third PartyServer this is taking more than 7 seconds where the main guilty member seems to be Jersey
So all in all, I have the impression that at least WeldBoostrap, is supposed to have a somewhat fairly equal cost across AppServers - if the code is not tuned to run like Coach instead of a Ferrari, and depending what other code is there (e.g. Jersey) to throttle the performance.
But again - I am no idea of how much of the code is in the hands of "transparent" optimisations in the hand of the AppServer, but perhaps there are some none negligible elements to it.
5.
For this sample application, WeldBoostrap cost in this application be ridiculously low (e.g. 2 seconds of 4999 CDI beans). How much of this is in the hands of what happened before WeldBoostrap.start() call?
- I think this is the same question as above, where I want to know how much depends on transparent none obvious optimisations.
- How much of these first 8 seconds of deployment can be attributed to:
- CDI nature of the application
- Simple Linearly increasing cost of Creating a class loader over an increasing number of classes
(e.g 4999 classes - will always have a minimum class loading cost, regardless of what type of component it is)
By comparison, the WeldBoostrap() cost is nothing.
Many thanks for helping me understand a little bit better how much CDI nature, Weld Boostrap, ClassLoading and AppServer specific optimisations are playing a role on the deployment cost of an application such as this sample application.
Kindest regards.
was (Author: nuno.godinhomatos):
Hi,
Thank you for all the insights on this.
it is in fact the case that this artificially created application with 4999 beans is quite small in relation to the application whose deployment time I am trying to reduce.
And it is also quite trivial, interns of where the source code is to be found.
- The WEB-INF/lib folder of this sample app is almost empty
- on the application I am looking at:
WEB-INF/classes is 100% empty, the WAR is just a packaging element for all of the software components that are in the WEB-INF/lib.
In short, there is a lot more of a variety of JEE elements.
>From CDI, to Mdbs, to EJBs etc...
But in any case, one trend is the same, I would say that the source code distribution is most likely 70 to 80% logic written in CDI components.
And the rest:
EJBs, Mdbs and such are a small layer to manage either JTA transaction context or defining app entrypoints. In short, CDI is king, and the rest is small talk.
I suspect that in this case, it is of benefit to have WEB-INF/lib/whateverComponent.jar/META-INF/holdingJandex.idx.
One thing I would like to understand better, it is not quite clear to me, is how much of the WeldBootstrap performance is in the hands of the AppServer integrator?
I have the feeling that it is still quite a little bit.
Let me explain my impression, and you can correct me if am wrong.
1. Every app server, regardless of who implements it, is doomed - it would appear - on a very initial phase of its startup logic, to loop over the classes on that package that is being deployed.
Without knowing any better, I would call this a Greedy bootstrapping of War application class loader.
Would say that this is correct?
In short:
The more classes you have in there, the more it will cost to initiate this class loader.
Analysis:
For the sample application the first few seconds of "log silence". In the case of our sample application with Jandex index, this costs about 6 seconds and without it, about 17 seconds where the cost of creating the index is not so insignificant.
But the point is also, the cost payed to have a Jandex index will on further phases of deployment pay for itself. Its metadata will allow the next processes to be faster.
And perhaps more than one process (Weld, Jersey, whoever) will want to ask the same questions and therefore it is better to build a dictionary of answers to all of these guys.
So these first few seconds of deployment are critical step of metadata acquisition to lower the runtime cost of the Class instances that will start to execute next.
2. Different application servers can manifest a significantly different performance on their first moment of log silence.
- You would say this is correct?
Some may want to have Jandex index, others may want to invent their own competing optimisations.
3. At some point, the class loader that gives the appropriate isolation for the web application is ready and other software components can start running.
One of these will be Weld.
- Correct?
4. WeldBoostraping logic starts, it has many queries that it needs to have answered, such as:
What Deployments units (e.g jars) exists in the context of this web application.
For each deployment unit what classes are in there that should be treated as CDI beans, etc...
And here I would like to understand:
4.1 How much of this cost will depend from AppServer to AppServer - and what are the main attributes that bring this cost variance:
- Is it Class Loader performance?
4.2 Is Jandex transparently used by Weld Or explicitly used by Weld?
The question is? If I search the source code of Weld for references to Jandex do I find any reference to It or not?
If the answer to this question is: NO you find none.
- Then I would say Jandex is an optimisation that is transparent for the software writer. It is somehow encoded into the class loader and other APIs performance that one may want to use, that get in the background optimised by the gander metadata.
If the answer is Yes: references to Jandex will be found.
- This means software writer must explicitly want to use its metadata. There aren't really any APIs (class loader, Reflection queries over a class, etc...) that get in back stage tuned via Jandex to be more reactive. One needs to want to use it, to actually feel its benefit.
So which of the two approaches is taking place?
4.3 If one must explicitly want to use Jandex, then depending on the Weld version available on a given AppServer, the WeldBoostraping cost should be fairly similar.
Is this correct?
NOTE:
- On this question, I am under the impression that the WeldBoostrap performance differed from app server to app server significantly.
In the case of the application I am analysing it is 6 seconds Wildfly against 19 seconds on a third party app server.
That is a big difference.
- I know that on Wildfly the hunt for the classes in each deployment unit is taking 2 seconds
- On the third party app server this hunt was taking 6 seconds and could be lowered to 4 seconds by putting to with the ConcurrentDeployer (so here just bad configuration)
- I know that the deployBeans() phase on Wildly is taking about 2 seconds, and on the third PartyServer this is taking more than 7 seconds where the main guilty member seems to be Jersey
So all in all, I have the impression that at least WeldBoostrap, is supposed to have a somewhat fairly equal cost across AppServers - if the code is not tuned to run like Coach instead of a Ferrari, and depending what other code is there (e.g. Jersey) to throttle the performance.
But again - I am no idea of how much of the code is in the hands of "transparent" optimisations in the hand of the AppServer, but perhaps there are some none negligible elements to it.
5.
For this sample application, WeldBoostrap cost in this application be ridiculously low (e.g. 2 seconds of 4999 CDI beans). How much of this is in the hands of what happened before WeldBoostrap.start() call?
- I think this is the same question as above, where I want to know how much depends on transparent none obvious optimisations.
Many thanks for helping me understand a little bit better how much the Weld performance is limited/otpimized by the integrator himself.
Kindest regards.
> Sample application with 4999 CDI beans 19 seconds on initial scanning and only 2 seconds of WeldBootStrap
> ---------------------------------------------------------------------------------------------------------
>
> Key: WFLY-9460
> URL: https://issues.jboss.org/browse/WFLY-9460
> Project: WildFly
> Issue Type: Enhancement
> Components: CDI / Weld
> Environment: Wildfly 10.1.0.final
> Reporter: Nuno Godinho de Matos
> Assignee: Martin Kouba
> Priority: Optional
>
> During the analsysis of an application depyloment, I ended up creating a sample application to demonstrate a small but important issue that Jersey causes to deployments in Weblogic echosystem, by expensively taking 2/3 of WeldBootsrap time during the "deployBeans()" phase.
> This application is a trivial WAR application composed 99% of CDI beans.
> In particularl it holds 4999 CDI beans automcatically generated via groovy.
> URL to sample app:
> https://github.com/99sono/wls-jsf-2-2-12-jersey-weldstartup-bottleneck
> Just mvn clean install. I has no data source dependencies, just CDI beans essentially.
> It should deploy in any application server without problems.
> While testing the same application deployment on Wildfly, I noticed that essentially:
> WeldBootstrap costs almost nothing in this case (2 seconds).
> But the time spent during deployment leading up to the WeldBootstrap phase is quite costly.
> In particular, we have about 19 seconds of deployment time.
> I will now quote the deployment time log:
> {panel}
> ####2017-10-20 13:16:50,196 ThreadId:17 INFO [logger: org.jboss.as.server.deployment] - WFLYSRV0027: Starting deployment of "wls-jsf-2-2-12-jersey-weldstartup-bottleneck-1.0.0-SANPSHOT.war" (runtime-name: "wls-jsf-2-2-12-jersey-weldstartup-bottleneck-1.0.0-SANPSHOT.war") <LogContext:none> <MSC service thread 1-3>
> ####2017-10-20 13:17:07,279 ThreadId:18 INFO [logger: org.jboss.weld.deployer] - WFLYWELD0003: Processing weld deployment wls-jsf-2-2-12-jersey-weldstartup-bottleneck-1.0.0-SANPSHOT.war <LogContext:none> <MSC service thread 1-4>
> ####2017-10-20 13:17:07,360 ThreadId:18 INFO [logger: org.hibernate.validator.internal.util.Version] - HV000001: Hibernate Validator 5.2.4.Final <LogContext:none> <MSC service thread 1-4>
> ####2017-10-20 13:17:07,408 ThreadId:18 INFO [logger: org.jboss.as.ejb3.deployment] - WFLYEJB0473: JNDI bindings for session bean named 'LogEjbStartupPhaseSingleton' in deployment unit 'deployment "wls-jsf-2-2-12-jersey-weldstartup-bottleneck-1.0.0-SANPSHOT.war"' are as follows:
> java:global/wls-jsf-2-2-12-jersey-weldstartup-bottleneck-1.0.0-SANPSHOT/LogEjbStartupPhaseSingleton!startup.LogEjbStartupPhaseSingleton
> java:app/wls-jsf-2-2-12-jersey-weldstartup-bottleneck-1.0.0-SANPSHOT/LogEjbStartupPhaseSingleton!startup.LogEjbStartupPhaseSingleton
> java:module/LogEjbStartupPhaseSingleton!startup.LogEjbStartupPhaseSingleton
> java:global/wls-jsf-2-2-12-jersey-weldstartup-bottleneck-1.0.0-SANPSHOT/LogEjbStartupPhaseSingleton
> java:app/wls-jsf-2-2-12-jersey-weldstartup-bottleneck-1.0.0-SANPSHOT/LogEjbStartupPhaseSingleton
> java:module/LogEjbStartupPhaseSingleton
> <LogContext:none> <MSC service thread 1-4>
> NOTE:
> This is when the WeldBootstrapt Actually starts.
> And compared to the time spent to come here, this step costs nothing 2 seconds. [09 seocnds to 11seconds]. But to get here, we spent 19 seconds of deployment time.
> Is it possible to lower the time to come here?
> ####2017-10-20 13:17:09,208 ThreadId:15 INFO [logger: org.jboss.weld.Version] - WELD-000900: 2.3.5 (Final) <LogContext:none> <MSC service thread 1-1>
> ####2017-10-20 13:17:11,388 ThreadId:528 INFO [logger: startup.LogEjbStartupPhaseSingleton] -
> DEPLOYMENT IS NOW INVOKING STARTUP EJBS.
> <LogContext:none> <ServerService Thread Pool -- 359>
> -- Now we have a very expensive and costly mojarra startup.
> -- For this we already have opened the issue: https://github.com/javaserverfaces/mojarra/issues/4298
> ####2017-10-20 13:17:11,499 ThreadId:528 INFO [logger: javax.enterprise.resource.webcontainer.jsf.config] - Initializing Mojarra 2.2.13.SP1 20160303-1204 for context '/wls-jsf-2-2-12-jersey-weldstartup-bottleneck-1.0.0-SANPSHOT' <LogContext:none> <ServerService Thread Pool -- 359>
> ####2017-10-20 13:17:12,768 ThreadId:528 FINE [logger: javax.enterprise.resource.webcontainer.jsf.timing] - [TIMING] - [62ms] : Parse jar:file:/C:/dev/appserver/wildfly/wildfly-10.1.0.Final/modules/system/layers/base/com/sun/jsf-impl/main/jsf-impl-2.2.13.SP1.jar!/com/sun/faces/jsf-ri-runtime.xml <LogContext:none> <ServerService Thread Pool -- 359>
> ####2017-10-20 13:17:12,768 ThreadId:528 FINE [logger: javax.enterprise.resource.webcontainer.jsf.timing] - [TIMING] - [0ms] : Parse vfs:/C:/dev/appserver/wildfly/wildfly-10.1.0.Final/user_projects/domains/powerhousejumpstartTrunkPostgres/bin/content/wls-jsf-2-2-12-jersey-weldstartup-bottleneck-1.0.0-SANPSHOT.war/WEB-INF/lib/primefaces-6.0.jar/META-INF/faces-config.xml <LogContext:none> <ServerService Thread Pool -- 359>
> ####2017-10-20 13:17:12,768 ThreadId:528 FINE [logger: javax.enterprise.resource.webcontainer.jsf.timing] - [TIMING] - [0ms] : Parse vfs:/C:/dev/appserver/wildfly/wildfly-10.1.0.Final/user_projects/domains/powerhousejumpstartTrunkPostgres/bin/content/wls-jsf-2-2-12-jersey-weldstartup-bottleneck-1.0.0-SANPSHOT.war/WEB-INF/lib/primefaces-extensions-6.0.0.jar/META-INF/faces-config.xml <LogContext:none> <ServerService Thread Pool -- 359>
> ####2017-10-20 13:17:12,768 ThreadId:528 FINE [logger: javax.enterprise.resource.webcontainer.jsf.timing] - [TIMING] - [0ms] : Parse jar:file:/C:/dev/appserver/wildfly/wildfly-10.1.0.Final/modules/system/layers/base/org/jboss/as/jsf-injection/main/wildfly-jsf-injection-10.1.0.Final.jar!/META-INF/faces-config.xml <LogContext:none> <ServerService Thread Pool -- 359>
> ####2017-10-20 13:17:12,783 ThreadId:528 FINE [logger: javax.enterprise.resource.webcontainer.jsf.timing] - [TIMING] - [15ms] : Parse file:/C:/dev/appserver/wildfly/wildfly-10.1.0.Final/user_projects/domains/powerhousejumpstartTrunkPostgres/tmp/vfs/temp/temp7406137a79d4ce52/content-9b229cec60054d8f/WEB-INF/faces-config.xml <LogContext:none> <ServerService Thread Pool -- 359>
> ####2017-10-20 13:17:12,783 ThreadId:528 FINE [logger: javax.enterprise.resource.webcontainer.jsf.timing] - [TIMING] - [0ms] : "faces-config" document sorting complete in 2. <LogContext:none> <ServerService Thread Pool -- 359>
> ####2017-10-20 13:17:12,799 ThreadId:528 FINE [logger: javax.enterprise.resource.webcontainer.jsf.timing] - [TIMING] - [0ms] : Configuration annotation scan complete. <LogContext:none> <ServerService Thread Pool -- 359>
> ####2017-10-20 13:17:14,158 ThreadId:528 FINE [logger: javax.enterprise.resource.webcontainer.jsf.timing] - [TIMING] - [0ms] : Parse jar:file:/C:/dev/appserver/wildfly/wildfly-10.1.0.Final/modules/system/layers/base/com/sun/jsf-impl/main/jsf-impl-2.2.13.SP1.jar!/META-INF/mojarra_ext.taglib.xml <LogContext:none> <ServerService Thread Pool -- 359>
> ####2017-10-20 13:17:14,158 ThreadId:528 FINE [logger: javax.enterprise.resource.webcontainer.jsf.timing] - [TIMING] - [0ms] : Parse vfs:/C:/dev/appserver/wildfly/wildfly-10.1.0.Final/user_projects/domains/powerhousejumpstartTrunkPostgres/bin/content/wls-jsf-2-2-12-jersey-weldstartup-bottleneck-1.0.0-SANPSHOT.war/WEB-INF/lib/primefaces-6.0.jar/META-INF/primefaces-pm.taglib.xml <LogContext:none> <ServerService Thread Pool -- 359>
> ####2017-10-20 13:17:14,174 ThreadId:528 FINE [logger: javax.enterprise.resource.webcontainer.jsf.timing] - [TIMING] - [16ms] : Parse vfs:/C:/dev/appserver/wildfly/wildfly-10.1.0.Final/user_projects/domains/powerhousejumpstartTrunkPostgres/bin/content/wls-jsf-2-2-12-jersey-weldstartup-bottleneck-1.0.0-SANPSHOT.war/WEB-INF/lib/primefaces-6.0.jar/META-INF/primefaces-p.taglib.xml <LogContext:none> <ServerService Thread Pool -- 359>
> ####2017-10-20 13:17:14,190 ThreadId:528 FINE [logger: javax.enterprise.resource.webcontainer.jsf.timing] - [TIMING] - [16ms] : Parse vfs:/C:/dev/appserver/wildfly/wildfly-10.1.0.Final/user_projects/domains/powerhousejumpstartTrunkPostgres/bin/content/wls-jsf-2-2-12-jersey-weldstartup-bottleneck-1.0.0-SANPSHOT.war/WEB-INF/lib/primefaces-extensions-6.0.0.jar/META-INF/primefaces-extensions.taglib.xml <LogContext:none> <ServerService Thread Pool -- 359>
> ####2017-10-20 13:17:14,190 ThreadId:528 FINE [logger: javax.enterprise.resource.webcontainer.jsf.timing] - [TIMING] - [0ms] : Parse jar:file:/C:/dev/appserver/wildfly/wildfly-10.1.0.Final/modules/system/layers/base/com/sun/jsf-impl/main/jsf-impl-2.2.13.SP1.jar!/META-INF/mojarra_ext.taglib.xml <LogContext:none> <ServerService Thread Pool -- 359>
> ####2017-10-20 13:17:14,274 ThreadId:528 INFO [logger: javax.enterprise.resource.webcontainer.jsf.config] - Monitoring file:/C:/dev/appserver/wildfly/wildfly-10.1.0.Final/user_projects/domains/powerhousejumpstartTrunkPostgres/tmp/vfs/temp/temp7406137a79d4ce52/content-9b229cec60054d8f/WEB-INF/faces-config.xml for modifications <LogContext:none> <ServerService Thread Pool -- 359>
> ####2017-10-20 13:17:14,362 ThreadId:528 INFO [logger: org.primefaces.webapp.PostConstructApplicationEventListener] - Running on PrimeFaces 6.0 <LogContext:none> <ServerService Thread Pool -- 359>
> ####2017-10-20 13:17:14,362 ThreadId:528 INFO [logger: org.primefaces.extensions.application.PostConstructApplicationEventListener] - Running on PrimeFaces Extensions 6.0.0 <LogContext:none> <ServerService Thread Pool -- 359>
> ####2017-10-20 13:17:14,362 ThreadId:528 FINE [logger: javax.enterprise.resource.webcontainer.jsf.timing] - [TIMING] - [2894ms] : Initialization of context /wls-jsf-2-2-12-jersey-weldstartup-bottleneck-1.0.0-SANPSHOT <LogContext:none> <ServerService Thread Pool -- 359>
> ####2017-10-20 13:17:14,658 ThreadId:528 INFO [logger: org.jboss.resteasy.resteasy_jaxrs.i18n] - RESTEASY002225: Deploying javax.ws.rs.core.Application: class rest.RestApplication$Proxy$_$$_WeldClientProxy <LogContext:none> <ServerService Thread Pool -- 359>
> ####2017-10-20 13:17:14,689 ThreadId:528 INFO [logger: org.wildfly.extension.undertow] - WFLYUT0021: Registered web context: /wls-jsf-2-2-12-jersey-weldstartup-bottleneck-1.0.0-SANPSHOT <LogContext:none> <ServerService Thread Pool -- 359>
> ####2017-10-20 13:17:14,748 ThreadId:507 INFO [logger: org.jboss.as.server] - WFLYSRV0010: Deployed "wls-jsf-2-2-12-jersey-weldstartup-bottleneck-1.0.0-SANPSHOT.war" (runtime-name : "wls-jsf-2-2-12-jersey-weldstartup-bottleneck-1.0.0-SANPSHOT.war") <LogContext:none> <External Management Request Threads -- 5>
> {panel}
> Would it possible for a CDI expert to try deploying the application and determine if the 19 seocnds that lead up to the first message: WELD-000900 2.3.5
> Is well justified, or if there is room optimizing this boostraping costs.
> To me 19 seonds to analyse 4999 CDI beans, that are all located uner WEB-INF/classes looks like an expensive cost.
> Is there any sort of static configuration that we could perhaps create to lower the annotation analysis cost or any other sort of trick.
> I would have hoped that this war file could deploy in under 5 seconds.
> Many thanks for any feedback on this.
--
This message was sent by Atlassian JIRA
(v7.5.0#75005)
More information about the jboss-jira
mailing list