[jboss-jira] [JBoss JIRA] (WFLY-9460) Sample application with 4999 CDI beans 19 seconds on initial scanning and only 2 seconds of WeldBootStrap
Nuno Godinho de Matos (JIRA)
issues at jboss.org
Wed Oct 25 02:57:00 EDT 2017
[ https://issues.jboss.org/browse/WFLY-9460?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13481502#comment-13481502 ]
Nuno Godinho de Matos commented on WFLY-9460:
---------------------------------------------
Hi Stuart,
Fantastic tunning!
I have git cloned the jandex main repository, since the pull request seems to already have been integrated.
i have swapped the jar file in the module.xml for jandex.
So here is the results of deploying the WAR file without a Jandex index within it in Wildfly:
{panel}
####2017-10-25 08:46:04,668 ThreadId:22 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-8>
---------------------------------------------
-- 9 Seconds - Jandex dance is here and it is now much faster (after this phase the dpeloyment is essentialy finished - weld bootsrap wil cost only 2 seconds.)
---------------------------------------------
####2017-10-25 08:46:13,814 ThreadId:20 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-6>
####2017-10-25 08:46:13,888 ThreadId:20 INFO [logger: org.hibernate.validator.internal.util.Version] - HV000001: Hibernate Validator 5.2.4.Final <LogContext:none> <MSC service thread 1-6>
####2017-10-25 08:46:13,949 ThreadId:20 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-6>
####2017-10-25 08:46:15,707 ThreadId:19 INFO [logger: org.jboss.weld.Version] - WELD-000900: 2.3.5 (Final) <LogContext:none> <MSC service thread 1-5>
----------------------
-- Weld bootstraping costing 2.2 seconds or so
------------------------
####2017-10-25 08:46:17,929 ThreadId:527 INFO [logger: startup.LogEjbStartupPhaseSingleton] -
DEPLOYMENT IS NOW INVOKING STARTUP EJBS.
<LogContext:none> <ServerService Thread Pool -- 358>
####2017-10-25 08:46:18,046 ThreadId:527 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 -- 358>
{panel}
In short, with this new version, the deployment is 3 seconds slower than when we already have the jadex index in the WAR, but 8 seconds faster then when we do not have the jandex index in the WAR and use the older version of the jandex library.
The improvement is quite massive here.
And since during development - which is when time wasted during dpeloyment is the most relevant - on the CI server nobody really cares that much - the projects open in eclipsed are "exploded copied" to the deployment folder so they will normally not carry over any jandex indexes. So if this process is faster, it will nicely boost deployment time during development.
Many thanks.
> Sample application with 4999 CDI beans 19 seconds on initial scanning and only 2 seconds of WeldBootStrap
> ---------------------------------------------------------------------------------------------------------
>
> Key: WFLY-9460
> URL: https://issues.jboss.org/browse/WFLY-9460
> Project: WildFly
> Issue Type: Enhancement
> Components: CDI / Weld
> Environment: Wildfly 10.1.0.final
> Reporter: Nuno Godinho de Matos
> Assignee: Martin Kouba
> Priority: Optional
>
> During the analsysis of an application depyloment, I ended up creating a sample application to demonstrate a small but important issue that Jersey causes to deployments in Weblogic echosystem, by expensively taking 2/3 of WeldBootsrap time during the "deployBeans()" phase.
> This application is a trivial WAR application composed 99% of CDI beans.
> In particularl it holds 4999 CDI beans automcatically generated via groovy.
> URL to sample app:
> https://github.com/99sono/wls-jsf-2-2-12-jersey-weldstartup-bottleneck
> Just mvn clean install. I has no data source dependencies, just CDI beans essentially.
> It should deploy in any application server without problems.
> While testing the same application deployment on Wildfly, I noticed that essentially:
> WeldBootstrap costs almost nothing in this case (2 seconds).
> But the time spent during deployment leading up to the WeldBootstrap phase is quite costly.
> In particular, we have about 19 seconds of deployment time.
> I will now quote the deployment time log:
> {panel}
> ####2017-10-20 13:16:50,196 ThreadId:17 INFO [logger: org.jboss.as.server.deployment] - WFLYSRV0027: Starting deployment of "wls-jsf-2-2-12-jersey-weldstartup-bottleneck-1.0.0-SANPSHOT.war" (runtime-name: "wls-jsf-2-2-12-jersey-weldstartup-bottleneck-1.0.0-SANPSHOT.war") <LogContext:none> <MSC service thread 1-3>
> ####2017-10-20 13:17:07,279 ThreadId:18 INFO [logger: org.jboss.weld.deployer] - WFLYWELD0003: Processing weld deployment wls-jsf-2-2-12-jersey-weldstartup-bottleneck-1.0.0-SANPSHOT.war <LogContext:none> <MSC service thread 1-4>
> ####2017-10-20 13:17:07,360 ThreadId:18 INFO [logger: org.hibernate.validator.internal.util.Version] - HV000001: Hibernate Validator 5.2.4.Final <LogContext:none> <MSC service thread 1-4>
> ####2017-10-20 13:17:07,408 ThreadId:18 INFO [logger: org.jboss.as.ejb3.deployment] - WFLYEJB0473: JNDI bindings for session bean named 'LogEjbStartupPhaseSingleton' in deployment unit 'deployment "wls-jsf-2-2-12-jersey-weldstartup-bottleneck-1.0.0-SANPSHOT.war"' are as follows:
> java:global/wls-jsf-2-2-12-jersey-weldstartup-bottleneck-1.0.0-SANPSHOT/LogEjbStartupPhaseSingleton!startup.LogEjbStartupPhaseSingleton
> java:app/wls-jsf-2-2-12-jersey-weldstartup-bottleneck-1.0.0-SANPSHOT/LogEjbStartupPhaseSingleton!startup.LogEjbStartupPhaseSingleton
> java:module/LogEjbStartupPhaseSingleton!startup.LogEjbStartupPhaseSingleton
> java:global/wls-jsf-2-2-12-jersey-weldstartup-bottleneck-1.0.0-SANPSHOT/LogEjbStartupPhaseSingleton
> java:app/wls-jsf-2-2-12-jersey-weldstartup-bottleneck-1.0.0-SANPSHOT/LogEjbStartupPhaseSingleton
> java:module/LogEjbStartupPhaseSingleton
> <LogContext:none> <MSC service thread 1-4>
> NOTE:
> This is when the WeldBootstrapt Actually starts.
> And compared to the time spent to come here, this step costs nothing 2 seconds. [09 seocnds to 11seconds]. But to get here, we spent 19 seconds of deployment time.
> Is it possible to lower the time to come here?
> ####2017-10-20 13:17:09,208 ThreadId:15 INFO [logger: org.jboss.weld.Version] - WELD-000900: 2.3.5 (Final) <LogContext:none> <MSC service thread 1-1>
> ####2017-10-20 13:17:11,388 ThreadId:528 INFO [logger: startup.LogEjbStartupPhaseSingleton] -
> DEPLOYMENT IS NOW INVOKING STARTUP EJBS.
> <LogContext:none> <ServerService Thread Pool -- 359>
> -- Now we have a very expensive and costly mojarra startup.
> -- For this we already have opened the issue: https://github.com/javaserverfaces/mojarra/issues/4298
> ####2017-10-20 13:17:11,499 ThreadId:528 INFO [logger: javax.enterprise.resource.webcontainer.jsf.config] - Initializing Mojarra 2.2.13.SP1 20160303-1204 for context '/wls-jsf-2-2-12-jersey-weldstartup-bottleneck-1.0.0-SANPSHOT' <LogContext:none> <ServerService Thread Pool -- 359>
> ####2017-10-20 13:17:12,768 ThreadId:528 FINE [logger: javax.enterprise.resource.webcontainer.jsf.timing] - [TIMING] - [62ms] : Parse jar:file:/C:/dev/appserver/wildfly/wildfly-10.1.0.Final/modules/system/layers/base/com/sun/jsf-impl/main/jsf-impl-2.2.13.SP1.jar!/com/sun/faces/jsf-ri-runtime.xml <LogContext:none> <ServerService Thread Pool -- 359>
> ####2017-10-20 13:17:12,768 ThreadId:528 FINE [logger: javax.enterprise.resource.webcontainer.jsf.timing] - [TIMING] - [0ms] : Parse vfs:/C:/dev/appserver/wildfly/wildfly-10.1.0.Final/user_projects/domains/powerhousejumpstartTrunkPostgres/bin/content/wls-jsf-2-2-12-jersey-weldstartup-bottleneck-1.0.0-SANPSHOT.war/WEB-INF/lib/primefaces-6.0.jar/META-INF/faces-config.xml <LogContext:none> <ServerService Thread Pool -- 359>
> ####2017-10-20 13:17:12,768 ThreadId:528 FINE [logger: javax.enterprise.resource.webcontainer.jsf.timing] - [TIMING] - [0ms] : Parse vfs:/C:/dev/appserver/wildfly/wildfly-10.1.0.Final/user_projects/domains/powerhousejumpstartTrunkPostgres/bin/content/wls-jsf-2-2-12-jersey-weldstartup-bottleneck-1.0.0-SANPSHOT.war/WEB-INF/lib/primefaces-extensions-6.0.0.jar/META-INF/faces-config.xml <LogContext:none> <ServerService Thread Pool -- 359>
> ####2017-10-20 13:17:12,768 ThreadId:528 FINE [logger: javax.enterprise.resource.webcontainer.jsf.timing] - [TIMING] - [0ms] : Parse jar:file:/C:/dev/appserver/wildfly/wildfly-10.1.0.Final/modules/system/layers/base/org/jboss/as/jsf-injection/main/wildfly-jsf-injection-10.1.0.Final.jar!/META-INF/faces-config.xml <LogContext:none> <ServerService Thread Pool -- 359>
> ####2017-10-20 13:17:12,783 ThreadId:528 FINE [logger: javax.enterprise.resource.webcontainer.jsf.timing] - [TIMING] - [15ms] : Parse file:/C:/dev/appserver/wildfly/wildfly-10.1.0.Final/user_projects/domains/powerhousejumpstartTrunkPostgres/tmp/vfs/temp/temp7406137a79d4ce52/content-9b229cec60054d8f/WEB-INF/faces-config.xml <LogContext:none> <ServerService Thread Pool -- 359>
> ####2017-10-20 13:17:12,783 ThreadId:528 FINE [logger: javax.enterprise.resource.webcontainer.jsf.timing] - [TIMING] - [0ms] : "faces-config" document sorting complete in 2. <LogContext:none> <ServerService Thread Pool -- 359>
> ####2017-10-20 13:17:12,799 ThreadId:528 FINE [logger: javax.enterprise.resource.webcontainer.jsf.timing] - [TIMING] - [0ms] : Configuration annotation scan complete. <LogContext:none> <ServerService Thread Pool -- 359>
> ####2017-10-20 13:17:14,158 ThreadId:528 FINE [logger: javax.enterprise.resource.webcontainer.jsf.timing] - [TIMING] - [0ms] : Parse jar:file:/C:/dev/appserver/wildfly/wildfly-10.1.0.Final/modules/system/layers/base/com/sun/jsf-impl/main/jsf-impl-2.2.13.SP1.jar!/META-INF/mojarra_ext.taglib.xml <LogContext:none> <ServerService Thread Pool -- 359>
> ####2017-10-20 13:17:14,158 ThreadId:528 FINE [logger: javax.enterprise.resource.webcontainer.jsf.timing] - [TIMING] - [0ms] : Parse vfs:/C:/dev/appserver/wildfly/wildfly-10.1.0.Final/user_projects/domains/powerhousejumpstartTrunkPostgres/bin/content/wls-jsf-2-2-12-jersey-weldstartup-bottleneck-1.0.0-SANPSHOT.war/WEB-INF/lib/primefaces-6.0.jar/META-INF/primefaces-pm.taglib.xml <LogContext:none> <ServerService Thread Pool -- 359>
> ####2017-10-20 13:17:14,174 ThreadId:528 FINE [logger: javax.enterprise.resource.webcontainer.jsf.timing] - [TIMING] - [16ms] : Parse vfs:/C:/dev/appserver/wildfly/wildfly-10.1.0.Final/user_projects/domains/powerhousejumpstartTrunkPostgres/bin/content/wls-jsf-2-2-12-jersey-weldstartup-bottleneck-1.0.0-SANPSHOT.war/WEB-INF/lib/primefaces-6.0.jar/META-INF/primefaces-p.taglib.xml <LogContext:none> <ServerService Thread Pool -- 359>
> ####2017-10-20 13:17:14,190 ThreadId:528 FINE [logger: javax.enterprise.resource.webcontainer.jsf.timing] - [TIMING] - [16ms] : Parse vfs:/C:/dev/appserver/wildfly/wildfly-10.1.0.Final/user_projects/domains/powerhousejumpstartTrunkPostgres/bin/content/wls-jsf-2-2-12-jersey-weldstartup-bottleneck-1.0.0-SANPSHOT.war/WEB-INF/lib/primefaces-extensions-6.0.0.jar/META-INF/primefaces-extensions.taglib.xml <LogContext:none> <ServerService Thread Pool -- 359>
> ####2017-10-20 13:17:14,190 ThreadId:528 FINE [logger: javax.enterprise.resource.webcontainer.jsf.timing] - [TIMING] - [0ms] : Parse jar:file:/C:/dev/appserver/wildfly/wildfly-10.1.0.Final/modules/system/layers/base/com/sun/jsf-impl/main/jsf-impl-2.2.13.SP1.jar!/META-INF/mojarra_ext.taglib.xml <LogContext:none> <ServerService Thread Pool -- 359>
> ####2017-10-20 13:17:14,274 ThreadId:528 INFO [logger: javax.enterprise.resource.webcontainer.jsf.config] - Monitoring file:/C:/dev/appserver/wildfly/wildfly-10.1.0.Final/user_projects/domains/powerhousejumpstartTrunkPostgres/tmp/vfs/temp/temp7406137a79d4ce52/content-9b229cec60054d8f/WEB-INF/faces-config.xml for modifications <LogContext:none> <ServerService Thread Pool -- 359>
> ####2017-10-20 13:17:14,362 ThreadId:528 INFO [logger: org.primefaces.webapp.PostConstructApplicationEventListener] - Running on PrimeFaces 6.0 <LogContext:none> <ServerService Thread Pool -- 359>
> ####2017-10-20 13:17:14,362 ThreadId:528 INFO [logger: org.primefaces.extensions.application.PostConstructApplicationEventListener] - Running on PrimeFaces Extensions 6.0.0 <LogContext:none> <ServerService Thread Pool -- 359>
> ####2017-10-20 13:17:14,362 ThreadId:528 FINE [logger: javax.enterprise.resource.webcontainer.jsf.timing] - [TIMING] - [2894ms] : Initialization of context /wls-jsf-2-2-12-jersey-weldstartup-bottleneck-1.0.0-SANPSHOT <LogContext:none> <ServerService Thread Pool -- 359>
> ####2017-10-20 13:17:14,658 ThreadId:528 INFO [logger: org.jboss.resteasy.resteasy_jaxrs.i18n] - RESTEASY002225: Deploying javax.ws.rs.core.Application: class rest.RestApplication$Proxy$_$$_WeldClientProxy <LogContext:none> <ServerService Thread Pool -- 359>
> ####2017-10-20 13:17:14,689 ThreadId:528 INFO [logger: org.wildfly.extension.undertow] - WFLYUT0021: Registered web context: /wls-jsf-2-2-12-jersey-weldstartup-bottleneck-1.0.0-SANPSHOT <LogContext:none> <ServerService Thread Pool -- 359>
> ####2017-10-20 13:17:14,748 ThreadId:507 INFO [logger: org.jboss.as.server] - WFLYSRV0010: Deployed "wls-jsf-2-2-12-jersey-weldstartup-bottleneck-1.0.0-SANPSHOT.war" (runtime-name : "wls-jsf-2-2-12-jersey-weldstartup-bottleneck-1.0.0-SANPSHOT.war") <LogContext:none> <External Management Request Threads -- 5>
> {panel}
> Would it possible for a CDI expert to try deploying the application and determine if the 19 seocnds that lead up to the first message: WELD-000900 2.3.5
> Is well justified, or if there is room optimizing this boostraping costs.
> To me 19 seonds to analyse 4999 CDI beans, that are all located uner WEB-INF/classes looks like an expensive cost.
> Is there any sort of static configuration that we could perhaps create to lower the annotation analysis cost or any other sort of trick.
> I would have hoped that this war file could deploy in under 5 seconds.
> Many thanks for any feedback on this.
--
This message was sent by Atlassian JIRA
(v7.5.0#75005)
More information about the jboss-jira
mailing list