Uploaded image for project: 'WildFly'
  1. WildFly
  2. WFLY-9460

Sample application with 4999 CDI beans 19 seconds on initial scanning and only 2 seconds of WeldBootStrap

    XMLWordPrintable

Details

    • Enhancement
    • Resolution: Won't Do
    • Optional
    • None
    • None
    • CDI / Weld
    • None

    Description

      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:

      ####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>

      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.

      Attachments

        Issue Links

          is related to

          Bug - A problem that impairs or prevents the functions of the product. JANDEX-42 Jandex attempts to internet fields and methods with annotations that will never match

          • Major - To be worked after higher priority work items are addressed. When the severity is high and the effort to change it is low to moderate, this term is chosen. Issues in this category likely have an existing workaround but implementation or execution may be non-trivial.
          • Resolved

          Activity

            People

              mkouba@redhat.com Martin Kouba
              nuno.godinhomatos NUNO GODINHO DE MATOS (Inactive)
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: