Help Needed: Deadlock in JNDI binding (trying to migrate from JBoss AS 6.2 to Wildfly 8.2)

[snargleplax]

I'm trying to upgrade a large legacy application from JBoss AS 6.2 to Wildfly 8.2.  Unfortunately, I'm getting a deadlock when trying to deploy my application EAR.  I'm pretty new to tweaking JBoss mechanics and would really appreciate some help (including identifying what additional information might be helpful to post).

Here's what I'm seeing.  Most of my MSC threads are waiting to acquire a lock:

"MSC service thread 1-7" #21 prio=5 os_prio=0 tid=0x00007fb8cc66a800 nid=0x11c1 waiting for monitor entry [0x00007fb8af6e7000]

   java.lang.Thread.State: BLOCKED (on object monitor)

  at org.jboss.util.naming.NonSerializableFactory.rebind(NonSerializableFactory.java:200)

  - waiting to lock <0x00000000f8929370> (a java.lang.Class for org.jboss.util.naming.NonSerializableFactory)

  at com.mycompany.delegates.RemoteServiceDelegateFactory.rebind(RemoteServiceDelegateFactory.java:89)

  at com.mycompany.delegates.RemoteServiceDelegateFactory.start(RemoteServiceDelegateFactory.java:28)

  at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

  at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)

  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

  at java.lang.reflect.Method.invoke(Method.java:483)

  at org.jboss.as.service.AbstractService.invokeLifecycleMethod(AbstractService.java:71)

  at org.jboss.as.service.StartStopService.start(StartStopService.java:56)

  at org.jboss.msc.service.ServiceControllerImpl$StartTask.startService(ServiceControllerImpl.java:1948)

  at org.jboss.msc.service.ServiceControllerImpl$StartTask.run(ServiceControllerImpl.java:1881)

  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)

  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)

  at java.lang.Thread.run(Thread.java:745)

One MSC thread holds that lock, but is stuck in a call to StabilityMonitor.awaitStability:

"MSC service thread 1-5" #19 prio=5 os_prio=0 tid=0x00007fb86c002000 nid=0x11bf in Object.wait() [0x00007fb8af8e9000]

   java.lang.Thread.State: WAITING (on object monitor)

  at java.lang.Object.wait(Native Method)

  at java.lang.Object.wait(Object.java:502)

  at org.jboss.msc.service.StabilityMonitor.awaitStability(StabilityMonitor.java:306)

  - locked <0x00000000f87edf00> (a java.lang.Object)

  at org.jboss.msc.service.StabilityMonitor.awaitStability(StabilityMonitor.java:221)

  at org.jboss.as.naming.WritableServiceBasedNamingStore.bind(WritableServiceBasedNamingStore.java:90)

  at org.jboss.as.naming.WritableServiceBasedNamingStore.rebind(WritableServiceBasedNamingStore.java:114)

  at org.jboss.as.naming.NamingContext.rebind(NamingContext.java:274)

  at org.jboss.as.naming.InitialContext$DefaultInitialContext.rebind(InitialContext.java:269)

  at org.jboss.as.naming.NamingContext.rebind(NamingContext.java:282)

  at javax.naming.InitialContext.rebind(InitialContext.java:433)

  at javax.naming.InitialContext.rebind(InitialContext.java:433)

  at org.jboss.util.naming.NonSerializableFactory.rebind(NonSerializableFactory.java:166)

  - locked <0x00000000f8929370> (a java.lang.Class for org.jboss.util.naming.NonSerializableFactory)

  at org.jboss.util.naming.NonSerializableFactory.rebind(NonSerializableFactory.java:207)

  - locked <0x00000000f8929370> (a java.lang.Class for org.jboss.util.naming.NonSerializableFactory)

  at com.mycompany.delegates.LocalServiceDelegateFactory.rebind(LocalServiceDelegateFactory.java:104)

  at com.mycompany.delegates.LocalServiceDelegateFactory.start(LocalServiceDelegateFactory.java:39)

  at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

  at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)

  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

  at java.lang.reflect.Method.invoke(Method.java:483)

  at org.jboss.as.service.AbstractService.invokeLifecycleMethod(AbstractService.java:71)

  at org.jboss.as.service.StartStopService.start(StartStopService.java:56)

  at org.jboss.msc.service.ServiceControllerImpl$StartTask.startService(ServiceControllerImpl.java:1948)

  at org.jboss.msc.service.ServiceControllerImpl$StartTask.run(ServiceControllerImpl.java:1881)

  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)

  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)

  at java.lang.Thread.run(Thread.java:745)

I also see a "management handler" thread doing the same wait:

"management-handler-thread - 18" #173 prio=5 os_prio=0 tid=0x00007fb858330800 nid=0x138a in Object.wait() [0x00007fb8a71f0000]

   java.lang.Thread.State: WAITING (on object monitor)

  at java.lang.Object.wait(Native Method)

  at java.lang.Object.wait(Object.java:502)

  at org.jboss.msc.service.StabilityMonitor.awaitStability(StabilityMonitor.java:306)

  - locked <0x00000000e051fab8> (a java.lang.Object)

  at org.jboss.msc.service.StabilityMonitor.awaitStability(StabilityMonitor.java:273)

  at org.jboss.as.controller.ContainerStateMonitor.awaitContainerStateChangeReport(ContainerStateMonitor.java:102)

  at org.jboss.as.controller.ModelControllerImpl.awaitContainerStateChangeReport(ModelControllerImpl.java:633)

  at org.jboss.as.controller.OperationContextImpl.awaitModelControllerContainerMonitor(OperationContextImpl.java:207)

  at org.jboss.as.controller.AbstractOperationContext.doCompleteStep(AbstractOperationContext.java:475)

  at org.jboss.as.controller.AbstractOperationContext.completeStepInternal(AbstractOperationContext.java:298)

  at org.jboss.as.controller.AbstractOperationContext.executeOperation(AbstractOperationContext.java:293)

  at org.jboss.as.controller.ModelControllerImpl.internalExecute(ModelControllerImpl.java:276)

  at org.jboss.as.controller.ModelControllerImpl.execute(ModelControllerImpl.java:150)

  at org.jboss.as.controller.remote.ModelControllerClientOperationHandler$ExecuteRequestHandler.doExecute(ModelControllerClientOperationHandler.java:199)

  at org.jboss.as.controller.remote.ModelControllerClientOperationHandler$ExecuteRequestHandler.access$300(ModelControllerClientOperationHandler.java:130)

  at org.jboss.as.controller.remote.ModelControllerClientOperationHandler$ExecuteRequestHandler$1$1.run(ModelControllerClientOperationHandler.java:150)

  at org.jboss.as.controller.remote.ModelControllerClientOperationHandler$ExecuteRequestHandler$1$1.run(ModelControllerClientOperationHandler.java:146)

  at java.security.AccessController.doPrivileged(Native Method)

  at javax.security.auth.Subject.doAs(Subject.java:422)

  at org.jboss.as.controller.AccessAuditContext.doAs(AccessAuditContext.java:94)

  at org.jboss.as.controller.remote.ModelControllerClientOperationHandler$ExecuteRequestHandler$1.execute(ModelControllerClientOperationHandler.java:146)

  at org.jboss.as.protocol.mgmt.AbstractMessageHandler$2$1.doExecute(AbstractMessageHandler.java:283)

  at org.jboss.as.protocol.mgmt.AbstractMessageHandler$AsyncTaskRunner.run(AbstractMessageHandler.java:504)

  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)

  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)

  at java.lang.Thread.run(Thread.java:745)

  at org.jboss.threads.JBossThread.run(JBossThread.java:122)

I did find this old issue that mentions similar symptoms:

[LIVEOAK-290] LiveOak on WildFly deadlocks starting up in some environments - JBoss Issue Tracker

However, the recommended workaround there is not to call StabilityMonitor at all, or at least not from MSC threads.  I don't see how to apply that in this case, since all those calls are happening within JBoss code.  I have noticed that the problem seems to crop up when I hit a certain critical number of MBeans trying to register themselves with JNDI, which seems consistent with Marko's comment there about auto-sizing of MSC thread pools.  I've got a quad-core and the problem starts when I hit 8 mbeans (doesn't seem to matter much which ones), so with hyperthreading that seems to add up.

Please advise.  I'm happy to provide any additional information that could help.  My deployment consists of an EAR archive that contains a single SAR; the SAR uses a jboss-service.xml to specify the MBeans it wants (if I understand right, this is the "old way" but is supposed to work -- please correct me if I'm misunderstanding that).  There are no MBean interdependencies or anything that I can see.  I've got a working deployment of a smaller service that's set up along similar lines, so I think my general approach is sound apart from this deadlock issue.

Thanks in advance for any help.

[jameslivingston]

From our chat on IRC, I believe the problem is that all the MSC threads are waiting for a task to complete, but that task never does because there are no threads left in the pool to run on. That sounds similar to [AS7-5523] WritableServiceBasedNamingStore (jndi) installs a new msc service and waits for it, which could cause deadloc…, and adding  -Dorg.jboss.server.bootstrap.maxThreads=32 made the problem go away.

[snargleplax]

Agreed, though of course (as we also noted on IRC) it only goes away until I enable lots more MBeans and hit the limit again.

[jameslivingston]

This is easily reproducible on WF and EAP. If you deploy a SAR containing a single MBean whose start() method binds to JNDI and use -Dorg.jboss.server.bootstrap.maxThreads=1 it will always hang because the executing task is waiting on a queued task to complete. wildfly/WritableServiceBasedNamingStore.java at master · wildfly/wildfly · GitHub blocks waiting for stability in bind()/unbind() since it's expected that the changes are made before the method returns.

I think there are two parts to this. In AS7-5523/AS7-3804, the solution was to move the component start out of the MSC threads to the server threads - should SAR MBean initialisation do the same? Second, is there a way for the MSC to detect that executing tasks are waiting on queued tasks and add more threads to the pool to handle it? The problem of pool thread starvation due to inter-dependant tasks seems to be a more general issue.

[snargleplax]

Since you're able to repro, should this be submitted to the Wildfly issue tracker?

[emmartins]

The bind() op has to block, there is no workaround there unless MSC allows the binder service to be synchronous. If there was no blocking then a lookup() after the bind() could fail to find the JNDI entry, and that breaks the JNDI API. IMHO you should focus on an alternative to the usage of NonSerializableFactory, or increase MSC threads and look for issues with respect to the other blocked threads.

[snargleplax]

Okay, thanks for that information.  As I mentioned, I'm somewhat new to fiddling with these mechanics.  What alternative(s) should I be considering?

[emmartins]

I have no idea what that code is doing

[snargleplax]

I mostly don't know either; much of this code is coming from a legacy JAR that I may not be able to make source changes to and rebuild.  Basically the pattern is, as mentioned, that I've got MBeans described in the jboss-service.xml file for a SAR, and they're trying to do JNDI binding for themselves inside of start().  This pattern worked fine under JBoss AS 6.2.  If that pattern doesn't work for Wildfly, how can I accomplish the same thing -- namely, making sure that my MBeans get instantiated and are registered with JNDI when I need them?  Am I doing something in an old-fashioned way that should be updated?  Is there any possibility of getting this working without changing that legacy code?  We really want to get off of JBoss AS 6.2 because it's evidently not compatible with Java 8, but this is blocking us.

[jaikiran]

This actually is a bug in the implementation of wildfly/StartStopService.java at master · wildfly/wildfly · GitHub since it violates the lifecycle methods of a Service jboss-msc/Service.java at master · jboss-msc/jboss-msc · GitHub

* When writing MSC service implementations, your {@link #start(StartContext)} and {@link #stop(StopContext)}

* methods must never block. This means these methods must not:

* <ul>

* <li>Use network connections</li>

* <li>Wait for network connections</li>

* <li>Sleep</li>

* <li>Wait on a condition</li>

* <li>Wait on a count down latch</li>

* <li>Call any method which may do any of the above</li>

* <li>Wait for termination of a thread pool or other service</li>

* <li>Wait for another service to change state</li>

* </ul>

*

* If your service start/stop does any of these things, you must use the asynchronous start/stop mechanism

* ({@link LifecycleContext#asynchronous()}) and do one of the following:

*

* <ul>

* <li>Initiate your task in start()/stop(), and utilize a callback (NIO, ThreadPoolExecutor.terminated(), etc.) to call

* {@link LifecycleContext#complete()} when your start/stop completes instead of blocking</li>

* <li>Delegate your blocking task to a thread pool ({@code Executor}) which calls {@link LifecycleContext#complete()}

* when done</li>

* <li>Use proper dependencies instead of explicitly waiting for services in your start/stop</li>

* </ul>

* <p>

* Note that using {@link LifecycleContext#execute(Runnable)} to execute the blocking task is also not permissible.

I think you should file a JIRA for this here https://issues.jboss.org/browse/WFLY

[jaikiran]

A pull request containing a fix has been submitted https://github.com/wildfly/wildfly/pull/7055

[snargleplax]

That's awesome, thank you so much!

[emmartins]

Thanks jaikiran.jai_forums2005.yahoo.co.in, I created [WFLY-4211] MBean implementation lifecycle methods in MSC threads - JBoss Issue Tracker for this bug and attached your PR.