[jboss-jira] [JBoss JIRA] (WFLY-9460) Sample application with 4999 CDI beans 19 seconds on initial scanning and only 2 seconds of WeldBootStrap
Martin Kouba (JIRA)
issues at jboss.org
Fri Oct 20 09:50:00 EDT 2017
[ https://issues.jboss.org/browse/WFLY-9460?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13479963#comment-13479963 ]
Martin Kouba commented on WFLY-9460:
------------------------------------
Thanks for the report Nuno. At first glance it can be [Jandex|https://github.com/wildfly/jandex]. In WildFly for each deployment a Jandex index is generated so that various Java EE implementations could optimize the annotation analysis. I've tried to generate the index beforehand (during build, using [jandex-maven-plugin|https://github.com/wildfly/jandex-maven-plugin]) and the whole deployment took about five seconds on my machine. [~nuno.godinhomatos] It would be great if you could verify my findings.
> 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