Wildfly 10 - The cost of creating the first eclipselink EntityManager during deployment is extremelly high due to MBeanServer.getMbeanCount() cost -------------------------------------------------------------------------------------------------------------------------------------------------- Key: WFLY-9408 URL: https://issues.jboss.org/browse/WFLY-9408 Project: WildFly Issue Type: Bug Components: JPA / Hibernate Affects Versions: 10.1.0.Final Reporter: Nuno Godinho de Matos Assignee: Scott Marlow Fix For: 11.0.0.Final 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: {panel} 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[]{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) {panel} After chekcing the eclipselink source code associated to line: {panel} at org.eclipse.persistence.platform.server.JMXServerPlatformBase.getMBeanServer(JMXServerPlatformBase.java:271) {panel} I found the following source code - which I could hardly believe would explain this deployment bottleneck: {panel} } else { // Only a single MBeanServer instance was found getAbstractSession().log(SessionLog.FINER, SessionLog.SERVER, "jmx_mbean_runtime_services_registration_mbeanserver_print", new Object[]{mBeanServer, mBeanServer.getMBeanCount(), mBeanServer.getDefaultDomain(), 0}); } {panel} 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: {panel} mBeanServer.getMBeanCount() {panel} 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: {panel} /** * 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; {panel} And finally I added an overriden method: {panel} @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() { @Override public List<MBeanServer> run() { return MBeanServerFactory.findMBeanServer(null); } }); } catch (PrivilegedActionException pae) { 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 { initialContext = new InitialContext(); // the // context // should be // cached mBeanServer = (MBeanServer) initialContext.lookup(JMX_JNDI_RUNTIME_REGISTER); } catch (NamingException ne) { getAbstractSession().log(SessionLog.WARNING, SessionLog.SERVER, "failed_to_find_mbean_server", ne); } } } else { 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) { getAbstractSession().log(SessionLog.WARNING, SessionLog.SERVER, "failed_to_find_mbean_server", "null returned from ManagementFactory.getPlatformMBeanServer()"); } else { getAbstractSession().log(SessionLog.FINER, SessionLog.SERVER, "jmx_mbean_runtime_services_registration_mbeanserver_print", new Object[] { 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) { getAbstractSession().log(SessionLog.FINER, SessionLog.SERVER, "jmx_mbean_runtime_services_registration_mbeanserver_print", new Object[] { anMBeanServer, MBEAN_SERVER_COUNT_DUMMY_VALUE, anMBeanServer.getDefaultDomain(), index }); if (null != anMBeanServer.getDefaultDomain()) { mBeanServer = anMBeanServer; getAbstractSession().log(SessionLog.WARNING, SessionLog.SERVER, "jmx_mbean_runtime_services_switching_to_alternate_mbeanserver", mBeanServer, index); } index++; } } else { // 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[] { mBeanServer, MBEAN_SERVER_COUNT_DUMMY_VALUE, mBeanServer.getDefaultDomain(), 0 }); } } } catch (Exception e) { // TODO: Warning required e.printStackTrace(); } } return mBeanServer; } {panel} 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: {panel} 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 {panel}