[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:09: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:08 AM:
-----------------------------------------------------------------------
Hi,
Thank you for all the insights on this.
In the case of this application whose deployment time I am trying to reduce, it is in fact the case that this artificially created application with 4999 beans is quite small by comparison. And it is also quite trivial, interns of where the source code is to be found.
The WEB-INF/lib folder of this ware is almost empty, while 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.
So then, yes, there is a lot more of a variety of JEE elements.
>From CDI, to Mdbs, to EJBs etc...
But in any case, I would say that even there the code distribution is most likely 70 to 80% logic written in CDI components.
And the rest EJBs and such are a small layer to manage the JTA transaction context. So it is primarily a CDI, but of course a much less trivial package.
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.
The more classes you have in there, the more it will cost to initiate this class loader.
And this 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.
So this point number 1, where different application servers can manifest a significantly different performance on their first moment of log silence.
2. 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.
And when 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 again, I am not 100% sure, but I am under the impression that many of the APIs that Weld will make use of (e.g. class loader related dependencies) will have a significant performance difference from App server to App server.
Even if WeldBoostrap can run like a Ferrari, if the layer beneath these class loaders is slow, does not cache etc... the bootstrapping cost will simply be high.
At least this is the impression that I have.
3. I have the impression that wildly tries make the jandex optimisation available to any tool that may need enquiry about reflection metadata.
It comes to mind the Jersey obverser issue on Weblogic, where jersey alone trying to answer the question: is this CDI bean somehow related to JAX-RS is costing more time that the hole weld bootstrapping logic.
Such queries, I suspect, could theoretically have their cost significantly reduced either by explicit usage of metadata on jandex, if it is available, or transparently have its cost reduced if somehow the AppServer developer can offer APIs that answer these very same questions extremely quickly by hiding away the fact that Jandex is there and is being used to return the result of some API calls....
IN this sense, I am not sure how Jandex fits into this picture.
If Jandex gives metadata that accelerates the ClassLoading layer (transparency for the guy that writes code that needs reflection data), and therefore its usage would be transparent to WeldBoostrap.
That is, Weld itself has no idea about jandex nor does it need to have because it can just leave for the Class loader implementer the responsibility of implementing all possible optimisation of using this type of metadata.
Or if Jandex metadata is proactively used by WeldBoostrap to reduce its bootstrapping cost.
And likewise, in the Jersey case weblogic, If they would have to try to reduce the cost whatever algorithm they are doing there by assuming that they cannot depend on the AppServer to be fast and that they need to support some metadata that the container make available to answer such questions quickly by putting a Jandex index available in the class path and if you use it or not is your choice.
That is something that I would like to understand.
4. If the answer is, the usage of Jandex is not transparent. The guy wanting to search for metadata about a class either explicitly supports or not, then Jandex should be able to optimize the WeldBoostraping cost on weblogic as well.
On the other hand, if it is used transparently, then having a Jandex index available in Weblogic should bring no benefit because it is an optimisation they do not use. Perhaps they have different optimisations.
How much of the software layers that make the WeldBoostrap cost in this application be ridiculously low (e.g. 2 seconds of 4999 CDI beans) are actually in the hands of what happened before of we even getting to WeldBoostrap.start() call?
Many thanks for helping me understand a little bit better how much the Weld performance is limited/otpimized by the integrator himself.
Kindest regards.
was (Author: nuno.godinhomatos):
Hi,
Thank you for all the insights on this.
In the case of this application whose deployment time I am trying to reduce, it is in fact the case that this artificially created application with 4999 beans is quite small by comparison. And it is also quite trivial, interns of where the source code is to be found.
The WEB-INF/lib folder of this ware is almost empty, while 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.
So then, yes, there is a lot more of a variety of JEE elements.
>From CDI, to Mdbs, to EJBs etc...
But in any case, I would say that even there the code distribution is most likely 70 to 80% logic written in CDI components.
And the rest EJBs and such are a small layer to manage the JTA transaction context. So it is primarily a CDI, but of course a much less trivial package.
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.
The more classes you have in there, the more it will cost to initiate this class loader.
And this 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.
So this point number 1, where different application servers can manifest a significantly different performance on their first moment of log silence.
2. 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.
And when 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 again, I am not 100% sure, but I am under the impression that many of the APIs that Weld will make use of (e.g. class loader related dependencies) will have a significant performance difference from App server to App server.
Even if WeldBoostrap can run like a Ferrari, if the layer beneath these class loaders is slow, does not cache etc... the bootstrapping cost will simply be high.
At least this is the impression that I have.
I am not sure how Jandex fits into this picture.
If Jandex gives metadata that accelerates the ClassLoading layer, and therefore its usage is transparent to WeldBoostrap.
That is, Weld itself has no idea about jandex and leaves for the Class loader implementer the optimisation of using it.
Or if Jandex metadata is proactively used by WeldBoostrap to reduce its bootstrapping cost.
That is something that I would like to understand.
How much of the software layers that make the WeldBoostrap cost in this application be ridiculously low (e.g. 2 seconds of 4999 CDI beans) are actually in the hands of what happened before of we even getting to WeldBoostrap.start() call?
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