[jboss-jira] [JBoss JIRA] (WFLY-9408) Wildfly 10 - The cost of creating the first eclipselink EntityManager during deployment is extremelly high due to MBeanServer.getMbeanCount() cost
Brian Stansberry (JIRA)
issues at jboss.org
Tue Oct 3 15:48:00 EDT 2017
[ https://issues.jboss.org/browse/WFLY-9408?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13471770#comment-13471770 ]
Brian Stansberry commented on WFLY-9408:
----------------------------------------
[~smarlow] Overriding eclipse link's JMXServerPlatformBase.getMBeanServer() is the right thing to do here. I don't believe the jsr77 module is involved.
The getMBeanCount() call may be more performant in WF 11, but regardless calling that just to do some trace logging is silly.
A similar thing to https://github.com/wildfly/wildfly/pull/10558 is at
https://github.com/wildfly/wildfly/compare/master...bstansberry:WFLY-9408
ManagementFactory.getPlatformMBeanServer() would get you the mbean server. But since the Eclipse link code we're replacing tried a call to MBeanServerFactory.findMBeanServer(null) first and since in a security manager environment those two call can require different permissions, to avoid breaking apps by needing different permissions I use MBeanServerFactory.findMBeanServer(null) as well. That returns a list so we have to iterate over the list to find the right mbean server. The Eclipse link code for that was written against old JBoss AS < 7 code, so it was looking for an mbean server whose getDefaultDomain() != null. That's wrong with AS 7 or later, so instead I look for getDefaultDomain() == null.
I just dropped the trace logging involving the mbean count.
I'll post a workaround in a second.
> 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}
--
This message was sent by Atlassian JIRA
(v7.2.3#72005)
More information about the jboss-jira
mailing list