[JBoss JIRA] (WFLY-9460) Sample application with 4999 CDI beans 19 seconds on initial scanning and only 2 seconds of WeldBootStrap
by Nuno Godinho de Matos (JIRA)
[ https://issues.jboss.org/browse/WFLY-9460?page=com.atlassian.jira.plugin.... ]
Nuno Godinho de Matos edited comment on WFLY-9460 at 10/21/17 4:34 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 because the software writer must explicitly want to use its metadata.
Then its usage is not transparent, and the WeldBoostraping cost should be fairly similar across different application servers, if the Jandex information is available on all of them.
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.
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.
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 because the software writer must explicitly want to use its metadata.
Then its usage is not transparent, and the WeldBoostraping cost should be fairly similar across different application servers, if the Jandex information is available on all of them.
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)
8 years, 9 months
- 1
- 0
[JBoss JIRA] (WFLY-9460) Sample application with 4999 CDI beans 19 seconds on initial scanning and only 2 seconds of WeldBootStrap
by Nuno Godinho de Matos (JIRA)
[ https://issues.jboss.org/browse/WFLY-9460?page=com.atlassian.jira.plugin.... ]
Nuno Godinho de Matos edited comment on WFLY-9460 at 10/21/17 4:30 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.
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 because the software writer must explicitly want to use its metadata.
Then its usage is not transparent, and the WeldBoostraping cost should be fairly similar across different application servers, if the Jandex information is available on all of them.
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.
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.
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 because the software writer must explicitly want to use its metadata.
Then its usage is not transparent, and the WeldBoostraping cost should be fairly similar across different application servers, if the Jandex information is available on all of them.
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 am not sure how much to attribute to "transparent" optimisations and how much to attribute to just bad configuration
5.
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)
8 years, 9 months
- 1
- 0
[JBoss JIRA] (WFLY-9460) Sample application with 4999 CDI beans 19 seconds on initial scanning and only 2 seconds of WeldBootStrap
by Nuno Godinho de Matos (JIRA)
[ https://issues.jboss.org/browse/WFLY-9460?page=com.atlassian.jira.plugin.... ]
Nuno Godinho de Matos edited comment on WFLY-9460 at 10/21/17 4:21 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.
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 because the software writer must explicitly want to use its metadata.
Then its usage is not transparent, and the WeldBoostraping cost should be fairly similar across different application servers, if the Jandex information is available on all of them.
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 am not sure how much to attribute to "transparent" optimisations and how much to attribute to just bad configuration
5.
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.
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.
> 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)
8 years, 9 months
- 1
- 0
[JBoss JIRA] (WFLY-9460) Sample application with 4999 CDI beans 19 seconds on initial scanning and only 2 seconds of WeldBootStrap
by Nuno Godinho de Matos (JIRA)
[ https://issues.jboss.org/browse/WFLY-9460?page=com.atlassian.jira.plugin.... ]
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)
8 years, 9 months
- 1
- 0
[JBoss JIRA] (WFLY-9460) Sample application with 4999 CDI beans 19 seconds on initial scanning and only 2 seconds of WeldBootStrap
by Nuno Godinho de Matos (JIRA)
[ https://issues.jboss.org/browse/WFLY-9460?page=com.atlassian.jira.plugin.... ]
Nuno Godinho de Matos commented on WFLY-9460:
---------------------------------------------
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)
8 years, 9 months
- 1
- 0
[JBoss JIRA] (WFLY-9460) Sample application with 4999 CDI beans 19 seconds on initial scanning and only 2 seconds of WeldBootStrap
by Martin Kouba (JIRA)
[ https://issues.jboss.org/browse/WFLY-9460?page=com.atlassian.jira.plugin.... ]
Martin Kouba commented on WFLY-9460:
------------------------------------
Ok, that's great. In fact, I did also comment on the stack overflow question - https://stackoverflow.com/questions/45995249/cdi-and-jandex-and-deploymen... ;-) Anyway, I'm not sure from which version WildFly supports a pregenerated Jandex index (I would guess WF 10+). In any case, I would only go this way (i.e. generating Jandex indexes) for a very large deployments (similar to your test app) and NOT by default.
> 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)
8 years, 9 months
- 1
- 0
[JBoss JIRA] (WFLY-9460) Sample application with 4999 CDI beans 19 seconds on initial scanning and only 2 seconds of WeldBootStrap
by Martin Kouba (JIRA)
[ https://issues.jboss.org/browse/WFLY-9460?page=com.atlassian.jira.plugin.... ]
Martin Kouba commented on WFLY-9460:
------------------------------------
[~swd847] Good point!
> 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)
8 years, 9 months
- 1
- 0
[JBoss JIRA] (WFLY-9460) Sample application with 4999 CDI beans 19 seconds on initial scanning and only 2 seconds of WeldBootStrap
by Stuart Douglas (JIRA)
[ https://issues.jboss.org/browse/WFLY-9460?page=com.atlassian.jira.plugin.... ]
Stuart Douglas commented on WFLY-9460:
--------------------------------------
Looks like a lot of the time is spent in the Jandex intern pool due to hash collisions. Although we can improve this it is mostly a result of the application being auto generated with all the beans being basically the same, a real application is unlikely to have the same collsitions issue.
> 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)
8 years, 9 months
- 1
- 0
[JBoss JIRA] (WFLY-9460) Sample application with 4999 CDI beans 19 seconds on initial scanning and only 2 seconds of WeldBootStrap
by Nuno Godinho de Matos (JIRA)
[ https://issues.jboss.org/browse/WFLY-9460?page=com.atlassian.jira.plugin.... ]
Nuno Godinho de Matos commented on WFLY-9460:
---------------------------------------------
Hi Martin Kouba,
Yes, you are completely right.
Adding jandex to the pom, and having in WEB-INF/classes/META-INF/jandex.idx makes a big difference.
Essentially we have the following.
Without jandex:
PHASE1 :
{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>
NOTE:
--- Here we have 17 seconds
####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>
{panel}
The deployment then goes a bit further and binds the singleton ejb to the jndi tree.
And then we have the WeldBootstrap phase:
{panel}
####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>
NOTE:
-- Here we have 2 seconds
####2017-10-20 13:17:11,388 ThreadId:528 INFO [logger: startup.LogEjbStartupPhaseSingleton] -
{panel}
On the other hand, if deploy the WAR file with the Jandex in there what I have is:
PHASE 1:
{panel}
####2017-10-20 16:28:14,570 ThreadId:20 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-6>
--- Here we have 6 seconds (it means we have gained 11 seconds on the initial wildfly JAR/WAR scanning phase)
####2017-10-20 16:28:20,612 ThreadId:16 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-2>
{panel}
And then on PHASE 2, things remain unchanged:
{panel}
####2017-10-20 16:28:23,485 ThreadId:16 INFO [logger: org.jboss.weld.Version] - WELD-000900: 2.3.5 (Final) <LogContext:none> <MSC service thread 1-2>
-- Here we have 2 seconds
####2017-10-20 16:28:25,592 ThreadId:526 INFO [logger: startup.LogEjbStartupPhaseSingleton] -
{panel}
I take it that the stack overflow reply that i got was not correct.
If a WEB-INF/lib/someLib.jar/META-INF/jandeix.idx index exists, it will save some computation time on the deployment.
To deploy on wildfly, it is always better if the JAR is already assembled with jandex I take it.
The improvement in this sample application is fantastic.
Thanks a lot!
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)
8 years, 9 months
- 1
- 0
[JBoss JIRA] (WFLY-9460) Sample application with 4999 CDI beans 19 seconds on initial scanning and only 2 seconds of WeldBootStrap
by Nuno Godinho de Matos (JIRA)
[ https://issues.jboss.org/browse/WFLY-9460?page=com.atlassian.jira.plugin.... ]
Nuno Godinho de Matos commented on WFLY-9460:
---------------------------------------------
Hi Martin, many thanks for your help on this.
I will try to do as suggested to verify.
NOTE:
I was under the impression that even if Jandex indexes were created beforehand, that this would not help because wildfly would always create Jandex indexes on deployment.
I had once on stack overflow posted a question on if anyone would have an idea why creating jandex indexes seemed not to improve my deployment time:
https://stackoverflow.com/questions/45995249/cdi-and-jandex-and-deploymen...
The reply I got was that jandex is at the heart of optimizations used by wildfly to lower deployment cost and that it is always done by the container. Regardless of whether we put the index in there or not.
I will reportback soon.
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)
8 years, 9 months
- 1
- 0