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

Wildfly 10 - The cost of creating the first eclipselink EntityManager during deployment is extremelly high due to MBeanServer.getMbeanCount() cost

    XMLWordPrintable

Details

    • Workaround Exists
    • Hide

      Remove the expose-expression-model and expose-resolved-model settings from the JMX subsystem config.

              <subsystem xmlns="urn:jboss:domain:jmx:1.3">
            <expose-resolved-model/>
            <expose-expression-model/>
            <remoting-connector/>
        </subsystem>
      Show
      Remove the expose-expression-model and expose-resolved-model settings from the JMX subsystem config. <subsystem xmlns= "urn:jboss:domain:jmx:1.3" > <expose-resolved-model/> <expose-expression-model/> <remoting-connector/> </subsystem>

    Description

      I have been trying to reduce the deployment of a WAR application.

      One of the greate bottlenecks on the deployment is the cost of getting the first EntityManager instance of eclipselink.
      To try to reduce cost of startup I found myself forced to during @Startup fire a CDI event observed by an @Asynchronous ejb whose only task is to do a dummy entityManager.flush().

      The results I had for the execution time of this observer could go as high as 13 seconds.

      On top of that, I had already noticed while writting an arquillian system test for eclipselink on:
      https://issues.jboss.org/browse/WFLY-8954

      that the cost of starting up elcipselink under wildfly was much much higher than that of Hibernate and OpenJPA.

      With this introduction done let us go to the facts, and they are quite ridiculous.

      I have sampled the deployment of an application from begging to end with a sampling script that took a thread dump every second to analyse where the app is spending deployment time generically.
      Eventually, I reached the eclipselink deployment.
      And I had entries on the log such as:
      DatabaseEntityManagerStarter] - <- StartupDatabaseEntityManagerStarter.observeApplicationReadyLoadEntityManagerEvent

      {5948 ms}

      <EJB aync-ejb-thread-pool - 1>

      While sampling why this was happening I got more than 7 straight thread dump samples (more than 7 seconds) where the following stack trace was present:

      at java.security.AccessController.getContext(Unknown Source)
      at org.jboss.as.controller.SecurityActions.getCaller(SecurityActions.java:47)
      at org.jboss.as.controller.AbstractOperationContext.getCaller(AbstractOperationContext.java:1138)
      at org.jboss.as.controller.OperationContextImpl.authorizeResource(OperationContextImpl.java:1306)
      at org.jboss.as.controller.OperationContextImpl.authorizeResource(OperationContextImpl.java:128)
      at org.jboss.as.controller.operations.global.ReadResourceDescriptionHandler$CheckResourceAccessHandler.execute(ReadResourceDescriptionHandler.java:429)
      at org.jboss.as.controller.AbstractOperationContext.executeStep(AbstractOperationContext.java:890)
      at org.jboss.as.controller.AbstractOperationContext.processStages(AbstractOperationContext.java:659)
      at org.jboss.as.controller.AbstractOperationContext.executeOperation(AbstractOperationContext.java:370)
      at org.jboss.as.controller.OperationContextImpl.executeOperation(OperationContextImpl.java:1329)
      at org.jboss.as.controller.ModelControllerImpl.internalExecute(ModelControllerImpl.java:400)
      at org.jboss.as.controller.ModelControllerImpl.execute(ModelControllerImpl.java:208)
      at org.jboss.as.jmx.model.ResourceAccessControlUtil.getResourceAccess(ResourceAccessControlUtil.java:85)
      at org.jboss.as.jmx.model.RootResourceIterator.doIterate(RootResourceIterator.java:51)
      at org.jboss.as.jmx.model.RootResourceIterator.doIterate(RootResourceIterator.java:61)
      at org.jboss.as.jmx.model.RootResourceIterator.doIterate(RootResourceIterator.java:61)
      at org.jboss.as.jmx.model.RootResourceIterator.doIterate(RootResourceIterator.java:61)
      at org.jboss.as.jmx.model.RootResourceIterator.doIterate(RootResourceIterator.java:61)
      at org.jboss.as.jmx.model.RootResourceIterator.doIterate(RootResourceIterator.java:61)
      at org.jboss.as.jmx.model.RootResourceIterator.doIterate(RootResourceIterator.java:61)
      at org.jboss.as.jmx.model.RootResourceIterator.iterate(RootResourceIterator.java:43)
      at org.jboss.as.jmx.model.ModelControllerMBeanHelper.getMBeanCount(ModelControllerMBeanHelper.java:125)
      at org.jboss.as.jmx.model.ModelControllerMBeanServerPlugin.getMBeanCount(ModelControllerMBeanServerPlugin.java:161)
      at org.jboss.as.jmx.PluggableMBeanServerImpl.getMBeanCount(PluggableMBeanServerImpl.java:545)

      ----- Because of the mBeanServer.getMBeanCount():
      getAbstractSession().log(SessionLog.FINER, SessionLog.SERVER,
      "jmx_mbean_runtime_services_registration_mbeanserver_print",
      new Object[]

      Unknown macro: {mBeanServer, mBeanServer.getMBeanCount(), mBeanServer.getDefaultDomain(), 0}

      );

      at org.eclipse.persistence.platform.server.JMXServerPlatformBase.getMBeanServer(JMXServerPlatformBase.java:271)
      at org.eclipse.persistence.platform.server.JMXServerPlatformBase.serverSpecificRegisterMBean(JMXServerPlatformBase.java:297)
      ---- Will register Managed beans under the prefix: TopLink:Name="

      at org.eclipse.persistence.platform.server.jboss.JBossPlatform.serverSpecificRegisterMBean(JBossPlatform.java:147)
      at org.eclipse.persistence.platform.server.ServerPlatformBase.registerMBean(ServerPlatformBase.java:581)

      ------- this.serverSpecificRegisterMBean();

      at org.eclipse.persistence.internal.sessions.DatabaseSessionImpl.postConnectDatasource(DatabaseSessionImpl.java:857)
      at org.eclipse.persistence.internal.sessions.DatabaseSessionImpl.loginAndDetectDatasource(DatabaseSessionImpl.java:762)
      at org.eclipse.persistence.internal.jpa.EntityManagerFactoryProvider.login(EntityManagerFactoryProvider.java:265)
      at org.eclipse.persistence.internal.jpa.EntityManagerSetupImpl.deploy(EntityManagerSetupImpl.java:731)
      at org.eclipse.persistence.internal.jpa.EntityManagerFactoryDelegate.getAbstractSession(EntityManagerFactoryDelegate.java:205)

      • locked [0x00000000a90d1210] (a org.eclipse.persistence.internal.jpa.EntityManagerFactoryDelegate)

      at org.eclipse.persistence.internal.jpa.EntityManagerFactoryDelegate.createEntityManagerImpl(EntityManagerFactoryDelegate.java:305)

      After chekcing the eclipselink source code associated to line:

      at org.eclipse.persistence.platform.server.JMXServerPlatformBase.getMBeanServer(JMXServerPlatformBase.java:271)

      I found the following source code - which I could hardly believe would explain this deployment bottleneck:

      } else {
      // Only a single MBeanServer instance was found
      getAbstractSession().log(SessionLog.FINER, SessionLog.SERVER,
      "jmx_mbean_runtime_services_registration_mbeanserver_print",
      new Object[]

      Unknown macro: {mBeanServer, mBeanServer.getMBeanCount(), mBeanServer.getDefaultDomain(), 0}

      );
      }

      In short, the first eclipselink entity manager cost of creation is a never ending task under wildfly because of how expensive the above log statement is:

      mBeanServer.getMBeanCount()

      I do not know how to interpret this.
      Is the problem that the API should cost ms and it literally takes several seconds to calculate - and the problem is the cost of the API under wildfly.
      Or is it that eclipselink should never have written such a log statement on the first place?

      To address the issue, I have hacked up my local:
      org.jipijapa.eclipselink.WildFlyServerPlatform

      In this class, I have override the getMeabServer API from the base class.
      I Have created a hacked constant:

      /**

      • During deployment, when the first entity manager is created, the
      • application deployment becomes extremelty slow due to the
      • MbeanServer.getbeanCount() access done by eclipselink. This access is on
      • top of all things done only for logging purposes. We completely kill the
      • call to the api.
        */
        private static final int MBEAN_SERVER_COUNT_DUMMY_VALUE = -999;

      And finally I added an overriden method:

      @Override
      public MBeanServer getMBeanServer() {
      /**

      • This function will attempt to get the MBeanServer via the
      • findMBeanServer spec call. 1) If the return list is null we attempt
      • to retrieve the PlatformMBeanServer (if it exists or is enabled in
      • this security context). 2) If the list of MBeanServers returned is
      • more than one we get the lowest indexed MBeanServer that does not on
      • a null default domain. 3) 333336: we need to wrap JMX calls in
      • doPrivileged blocks 4) fail-fast: if there are any issues with JMX -
      • continue - don't block the deploy()
        */
        // lazy initialize the MBeanServer reference
        if (null == mBeanServer) {
        List<MBeanServer> mBeanServerList = null;
        try {
        if (PrivilegedAccessHelper.shouldUsePrivilegedAccess()) {
        try {
        mBeanServerList = (List<MBeanServer>) AccessController
        .doPrivileged(new PrivilegedExceptionAction()
        Unknown macro: { @Override public List<MBeanServer> run()
        Unknown macro: { return MBeanServerFactory.findMBeanServer(null); }
        }

        );
        } catch (PrivilegedActionException pae)

        Unknown macro: { getAbstractSession().log(SessionLog.WARNING, SessionLog.SERVER, "failed_to_find_mbean_server", "null or empty List returned from privileged MBeanServerFactory.findMBeanServer(null)"); Context initialContext = null; try
        Unknown macro: { initialContext = new InitialContext(); // the // context // should be // cached mBeanServer = (MBeanServer) initialContext.lookup(JMX_JNDI_RUNTIME_REGISTER); }
        catch (NamingException ne)
        Unknown macro: { getAbstractSession().log(SessionLog.WARNING, SessionLog.SERVER, "failed_to_find_mbean_server", ne); }
        }

        } else

        Unknown macro: { mBeanServerList = MBeanServerFactory.findMBeanServer(null); }

        // Attempt to get the first MBeanServer we find - usually there
        // is only one - when agentId == null we return a List of them
        if (null == mBeanServer && (null == mBeanServerList || mBeanServerList.isEmpty())) {
        // Unable to acquire a JMX specification List of MBeanServer
        // instances
        getAbstractSession().log(SessionLog.WARNING, SessionLog.SERVER, "failed_to_find_mbean_server",
        "null or empty List returned from MBeanServerFactory.findMBeanServer(null)");
        // Try alternate static method
        if (!PrivilegedAccessHelper.shouldUsePrivilegedAccess()) {
        mBeanServer = ManagementFactory.getPlatformMBeanServer();
        if (null == mBeanServer)

        Unknown macro: { getAbstractSession().log(SessionLog.WARNING, SessionLog.SERVER, "failed_to_find_mbean_server", "null returned from ManagementFactory.getPlatformMBeanServer()"); }

        else

        Unknown macro: { getAbstractSession().log(SessionLog.FINER, SessionLog.SERVER, "jmx_mbean_runtime_services_registration_mbeanserver_print", new Object[]
        Unknown macro: { mBeanServer, MBEAN_SERVER_COUNT_DUMMY_VALUE, mBeanServer.getDefaultDomain(), 0 }
        ); }

        }
        } else {
        // Use the first MBeanServer by default - there may be
        // multiple domains each with their own MBeanServer
        mBeanServer = mBeanServerList.get(JMX_MBEANSERVER_INDEX_DEFAULT_FOR_MULTIPLE_SERVERS);
        if (mBeanServerList.size() > 1) {
        // There are multiple MBeanServerInstances (usually only
        // JBoss)
        // 328006: WebLogic may also return multiple instances
        // (we need to register the one containing the com.bea
        // tree)
        getAbstractSession().log(SessionLog.WARNING, SessionLog.SERVER,
        "jmx_mbean_runtime_services_registration_encountered_multiple_mbeanserver_instances",
        mBeanServerList.size(), JMX_MBEANSERVER_INDEX_DEFAULT_FOR_MULTIPLE_SERVERS,
        mBeanServer);
        // IE: for JBoss we need to verify we are using the
        // correct MBean server of the two (default, null)
        // Check the domain if it is non-null - avoid using this
        // server
        int index = 0;
        for (MBeanServer anMBeanServer : mBeanServerList)

        Unknown macro: { getAbstractSession().log(SessionLog.FINER, SessionLog.SERVER, "jmx_mbean_runtime_services_registration_mbeanserver_print", new Object[]
        Unknown macro: { anMBeanServer, MBEAN_SERVER_COUNT_DUMMY_VALUE, anMBeanServer.getDefaultDomain(), index }
        ); if (null != anMBeanServer.getDefaultDomain())
        Unknown macro: { mBeanServer = anMBeanServer; getAbstractSession().log(SessionLog.WARNING, SessionLog.SERVER, "jmx_mbean_runtime_services_switching_to_alternate_mbeanserver", mBeanServer, index); }
        index++; }

        } else

        Unknown macro: { // Only a single MBeanServer instance was found // mBeanServer.getMBeanCount() - This is very slow on // wildfly // we are disabling this statemnt getAbstractSession().log(SessionLog.FINER, SessionLog.SERVER, "jmx_mbean_runtime_services_registration_mbeanserver_print", new Object[]
        Unknown macro: { mBeanServer, MBEAN_SERVER_COUNT_DUMMY_VALUE, mBeanServer.getDefaultDomain(), 0 }
        ); }

        }
        } catch (Exception e)

        Unknown macro: { // TODO}

        }
        return mBeanServer;
        }

      The above code looks extremelly complex to me just to get a MBeanserver in an application server.
      I find it hard to believe that this operation should ever have a code with this many lines of code behind it, but ok.
      As you can see in the code I am pasting the only trick I am putting in place to address the deployment time on my machine is to replace every single mebanserver.getMbeanCoundt() by a "dumb" reference to the constant: MBEAN_SERVER_COUNT_DUMMY_VALUE.

      Would it possible that the wildflt server platform be tuned to address this issue?
      I think it would be a good Idea if you revise the getMbeanServer api to be as simple as possible for JBOSS/Wildfly - the base eclipselink code make slittle since in my oppinion.
      But you will know best.

      It is also interesting that now when i run the test suite project from wildfly eclipselink actualy manages to be few ms faster than hibernate:

      Running org.jboss.as.test.compat.jpa.eclipselink.EclipseLinkSharedModuleProviderTestCase
      Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.662 sec - in org.jboss.as.test.compat.jpa.eclipselink.EclipseLinkSharedModuleProviderTestCase

      This eclipselink test is actually now faster than

      Running org.jboss.as.test.compat.jpa.eclipselink.wildfly8954.PersistenceXmlHelperTest
      Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.354 sec - in org.jboss.as.test.compat.jpa.eclipselink.wildfly8954.PersistenceXmlHelperTest
      Running org.jboss.as.test.compat.jpa.eclipselink.wildfly8954.WFLY8954BaseTest
      Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.685 sec - in org.jboss.as.test.compat.jpa.eclipselink.wildfly8954.WFLY8954BaseTest
      Running org.jboss.as.test.compat.jpa.hibernate.HibernateJarsInDeploymentTestCase
      Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.714 sec - in

      The hibernate test here loses to the eclipselink test above.

      org.jboss.as.test.compat.jpa.hibernate.HibernateJarsInDeploymentTestCase
      Running org.jboss.as.test.compat.jpa.openjpa.OpenJPASharedModuleProviderTestCase
      Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.218 sec - in org.jboss.as.test.compat.jpa.openjpa.OpenJPASharedModuleProviderTestCase

      Attachments

        Issue Links

          is related to

          Enhancement - An enhancement to or refactoring of existing functionality that is not configurable by an end user (typically a change made by an internal team that affects users) WFCORE-3415 Cut the time to execute MBeanServerConnection.getMBeanCount()

          • 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

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

              Dates

                Created:
                Updated:
                Resolved: