AbstractUnitController Deadlock, again :(

DivineThreepwood commented 5 years ago

Found one Java-level deadlock:
=============================
"jersey-client-async-executor-177":
  waiting to lock monitor 0x0000000001ae2278 (object 0x00000000c4bf51a8, a org.openbase.jul.schedule.SyncObject),
  which is held by "pool-2-thread-3"
"pool-2-thread-3":
  waiting for ownable synchronizer 0x00000000c4bf2308, (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync),
  which is held by "jersey-client-async-executor-177"

Java stack information for the threads listed above:
===================================================
"jersey-client-async-executor-177":
        at org.openbase.bco.dal.control.layer.unit.AbstractUnitController.applyDataUpdate(AbstractUnitController.java:1092)
        - waiting to lock <0x00000000c4bf51a8> (a org.openbase.jul.schedule.SyncObject)
        at org.openbase.bco.device.openhab.manager.CommandExecutor.applyStateUpdate(CommandExecutor.java:108)
        at org.openbase.bco.device.openhab.manager.CommandExecutor.update(CommandExecutor.java:81)
        at org.openbase.bco.device.openhab.manager.CommandExecutor.update(CommandExecutor.java:56)
        at org.openbase.jul.pattern.AbstractObservable.notifyObservers(AbstractObservable.java:257)
        - locked <0x00000000c457a8d0> (a org.openbase.jul.pattern.AbstractObservable$2)
        at org.openbase.jul.pattern.AbstractObservable.notifyObservers(AbstractObservable.java:189)
        at org.openbase.bco.device.openhab.OpenHABRestCommunicator.lambda$addSSEObserver$0(OpenHABRestCommunicator.java:186)
        at org.openbase.bco.device.openhab.OpenHABRestCommunicator$$Lambda$177/1566775190.accept(Unknown Source)
        at org.glassfish.jersey.media.sse.internal.JerseySseEventSource$1.onNext(JerseySseEventSource.java:169)
        at org.glassfish.jersey.media.sse.internal.JerseySseEventSource$1.onNext(JerseySseEventSource.java:151)
        at org.glassfish.jersey.internal.util.JerseyPublisher$SubscriberWrapper.onNext(JerseyPublisher.java:415)
        at org.glassfish.jersey.internal.jsr166.SubmissionPublisher$BufferedSubscription.consume(SubmissionPublisher.java:1500)
        at org.glassfish.jersey.internal.jsr166.SubmissionPublisher$ConsumerTask.run(SubmissionPublisher.java:953)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
"pool-2-thread-3":
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000c4bf2308> (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
        at java.util.concurrent.locks.ReentrantReadWriteLock$WriteLock.lock(ReentrantReadWriteLock.java:943)
        at org.openbase.jul.extension.rsb.com.AbstractControllerServer.setDataField(AbstractControllerServer.java:704)
        at org.openbase.jul.extension.rsb.com.AbstractControllerServer.updateTransactionId(AbstractControllerServer.java:1001)
        - locked <0x00000000c4bf2268> (a org.openbase.jul.schedule.SyncObject)
        at org.openbase.bco.dal.control.layer.unit.AbstractUnitController.reschedule(AbstractUnitController.java:843)
        - locked <0x00000000c4bf51a8> (a org.openbase.jul.schedule.SyncObject)
        at org.openbase.bco.dal.control.layer.unit.AbstractUnitController.reschedule(AbstractUnitController.java:691)
        at org.openbase.bco.dal.control.layer.unit.AbstractUnitController$3.expired(AbstractUnitController.java:234)
        at org.openbase.jul.schedule.Timeout.lambda$internal_start$0(Timeout.java:183)
        at org.openbase.jul.schedule.Timeout$$Lambda$53/737272344.call(Unknown Source)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)

Found 1 deadlock.

Heap
 PSYoungGen      total 109056K, used 86700K [0x00000000eba00000, 0x00000000fa800000, 0x0000000100000000)
  eden space 107520K, 79% used [0x00000000eba00000,0x00000000f0d43040,0x00000000f2300000)
  from space 1536K, 93% used [0x00000000fa680000,0x00000000fa7e8000,0x00000000fa800000)
  to   space 5632K, 0% used [0x00000000f9d00000,0x00000000f9d00000,0x00000000fa280000)
 ParOldGen       total 59904K, used 34770K [0x00000000c2e00000, 0x00000000c6880000, 0x00000000eba00000)
  object space 59904K, 58% used [0x00000000c2e00000,0x00000000c4ff4ae8,0x00000000c6880000)
 Metaspace       used 41821K, capacity 45409K, committed 45696K, reserved 1089536K
  class space    used 4593K, capacity 5172K, committed 5248K, reserved 1048576K

DivineThreepwood commented 5 years ago

Because there seem to be some lines missing in the previously post, here another log:

Found one Java-level deadlock:
=============================
"pool-1-thread-109":
  waiting for ownable synchronizer 0x00000000c440e210, (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync),
  which is held by "jersey-client-async-executor-23"
"jersey-client-async-executor-23":
  waiting to lock monitor 0x00000000010953f8 (object 0x00000000c440f038, a org.openbase.jul.schedule.SyncObject),
  which is held by "pool-2-thread-4"
"pool-2-thread-4":
  waiting for ownable synchronizer 0x00000000c440e210, (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync),
  which is held by "jersey-client-async-executor-23"

Java stack information for the threads listed above:
===================================================
"pool-1-thread-109":
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000c440e210> (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireShared(AbstractQueuedSynchronizer.java:967)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireShared(AbstractQueuedSynchronizer.java:1283)
        at java.util.concurrent.locks.ReentrantReadWriteLock$ReadLock.lock(ReentrantReadWriteLock.java:727)
        at org.openbase.jul.extension.rsb.com.AbstractControllerServer.cloneDataBuilder(AbstractControllerServer.java:543)
        at org.openbase.bco.authentication.lib.com.AbstractAuthenticatedConfigurableController.requestStatus(AbstractAuthenticatedConfigurableController.java:80)
        at org.openbase.bco.authentication.lib.com.AbstractAuthenticatedConfigurableController.requestStatus(AbstractAuthenticatedConfigurableController.java:49)
        at sun.reflect.GeneratedMethodAccessor815.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.openbase.jul.extension.rsb.com.RPCHelper.lambda$null$0(RPCHelper.java:133)
        at org.openbase.jul.extension.rsb.com.RPCHelper$$Lambda$208/627533917.call(Unknown Source)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
"jersey-client-async-executor-23":
        at org.openbase.bco.dal.control.layer.unit.AbstractUnitController.applyDataUpdate(AbstractUnitController.java:1092)
        - waiting to lock <0x00000000c440f038> (a org.openbase.jul.schedule.SyncObject)
        at org.openbase.bco.device.openhab.manager.CommandExecutor.applyStateUpdate(CommandExecutor.java:108)
        at org.openbase.bco.device.openhab.manager.CommandExecutor.update(CommandExecutor.java:81)
        at org.openbase.bco.device.openhab.manager.CommandExecutor.update(CommandExecutor.java:56)
        at org.openbase.jul.pattern.AbstractObservable.notifyObservers(AbstractObservable.java:257)
        - locked <0x00000000c45bc568> (a org.openbase.jul.pattern.AbstractObservable$2)
        at org.openbase.jul.pattern.AbstractObservable.notifyObservers(AbstractObservable.java:189)
        at org.openbase.bco.device.openhab.OpenHABRestCommunicator.lambda$addSSEObserver$0(OpenHABRestCommunicator.java:186)
        at org.openbase.bco.device.openhab.OpenHABRestCommunicator$$Lambda$192/1909110760.accept(Unknown Source)
        at org.glassfish.jersey.media.sse.internal.JerseySseEventSource$1.onNext(JerseySseEventSource.java:169)
        at org.glassfish.jersey.media.sse.internal.JerseySseEventSource$1.onNext(JerseySseEventSource.java:151)
        at org.glassfish.jersey.internal.util.JerseyPublisher$SubscriberWrapper.onNext(JerseyPublisher.java:415)
        at org.glassfish.jersey.internal.jsr166.SubmissionPublisher$BufferedSubscription.consume(SubmissionPublisher.java:1500)
        at org.glassfish.jersey.internal.jsr166.SubmissionPublisher$ConsumerTask.run(SubmissionPublisher.java:953)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
"pool-2-thread-4":
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000c440e210> (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
        at java.util.concurrent.locks.ReentrantReadWriteLock$WriteLock.lock(ReentrantReadWriteLock.java:943)
        at org.openbase.jul.extension.rsb.com.AbstractControllerServer.setDataField(AbstractControllerServer.java:704)
        at org.openbase.jul.extension.rsb.com.AbstractControllerServer.updateTransactionId(AbstractControllerServer.java:1001)
        - locked <0x00000000c440e170> (a org.openbase.jul.schedule.SyncObject)
        at org.openbase.bco.dal.control.layer.unit.AbstractUnitController.reschedule(AbstractUnitController.java:843)
        - locked <0x00000000c440f038> (a org.openbase.jul.schedule.SyncObject)
        at org.openbase.bco.dal.control.layer.unit.AbstractUnitController.reschedule(AbstractUnitController.java:691)
        at org.openbase.bco.dal.control.layer.unit.AbstractUnitController$3.expired(AbstractUnitController.java:234)
        at org.openbase.jul.schedule.Timeout.lambda$internal_start$0(Timeout.java:183)
        at org.openbase.jul.schedule.Timeout$$Lambda$61/832045601.call(Unknown Source)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)

Found 1 deadlock.

Heap
 PSYoungGen      total 320512K, used 306768K [0x00000000eba00000, 0x00000000ffe80000, 0x0000000100000000)
  eden space 308224K, 97% used [0x00000000eba00000,0x00000000fdf643e0,0x00000000fe700000)
  from space 12288K, 51% used [0x00000000ff280000,0x00000000ff8b0010,0x00000000ffe80000)
  to   space 11776K, 0% used [0x00000000fe700000,0x00000000fe700000,0x00000000ff280000)
 ParOldGen       total 78848K, used 53268K [0x00000000c2e00000, 0x00000000c7b00000, 0x00000000eba00000)
  object space 78848K, 67% used [0x00000000c2e00000,0x00000000c6205180,0x00000000c7b00000)
 Metaspace       used 41797K, capacity 45367K, committed 45696K, reserved 1089536K
  class space    used 4587K, capacity 5139K, committed 5248K, reserved 1048576K

DivineThreepwood commented 5 years ago

@pLeminoq do you have any idea where the jersey-client-async-executor locks the ReentrantReadWriteLock$NonfairSync. This is not a part of the stack trace.

When the issue occurs, no further openhab updates are handled (e.g. MotionState Updates). And currently it occurs really often.

pLeminoq commented 5 years ago

Locking the ReentrantReadWriteLock is part of the call to applyDataUpdate (AbstractUnitController:1002). This is the lock which is required when accessing the data builder. This deadlock is introduced because updates from openHAB are now scheduled as actions. As I see it one thread triggers a reschedule because either an action is finished or an action in a finishing state can be removed from the list. Therefore, this thread locks the scheduledActionListLock. After rescheduling the transaction id is updated and a notification is performed. Both require the data builder lock. The other thread receives an update from openHAB and thus performs a data update which locks the data builder lock. With the recent change this triggers a reschedule which requires the scheduledActionListLock.

A solution that comes to my mind is to get rid of the scheduledActionListLock and lock all changes to the action list with the data builder lock. I think this is fine because changes to the action list need to be synchronized into the data builder and notified anyway.

DivineThreepwood commented 5 years ago

A solution that comes to my mind is to get rid of the scheduledActionListLock and lock all changes to >the action list with the data builder lock. I think this is fine because changes to the action list need to >be synchronized into the data builder and notified anyway.

I thought about the same resolution strategy. But than the scheduling needs to be really fast and should never block for a longer term to not block the builder longer than the lock timeout. But this is at least detected. Okay, I will remove the lock. Thanks for your support.

DivineThreepwood commented 5 years ago

hmm, after using the builder sync setup 4 more deadlock occured:

Found one Java-level deadlock:
=============================
"pool-2-thread-1":
  waiting for ownable synchronizer 0x00000007823c9338, (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync),
  which is held by "pool-1-thread-277"
"pool-1-thread-277":
  waiting to lock monitor 0x00007fadfda1c300 (object 0x00000007823c9260, a org.openbase.jul.schedule.SyncObject),
  which is held by "pool-1-thread-262"
"pool-1-thread-262":
  waiting for ownable synchronizer 0x00000007823c9338, (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync),
  which is held by "pool-1-thread-277"

Java stack information for the threads listed above:
===================================================
"pool-2-thread-1":
    at jdk.internal.misc.Unsafe.park(java.base@11.0.1/Native Method)
    - parking to wait for  <0x00000007823c9338> (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)
    at java.util.concurrent.locks.LockSupport.park(java.base@11.0.1/LockSupport.java:194)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(java.base@11.0.1/AbstractQueuedSynchronizer.java:885)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(java.base@11.0.1/AbstractQueuedSynchronizer.java:917)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(java.base@11.0.1/AbstractQueuedSynchronizer.java:1240)
    at java.util.concurrent.locks.ReentrantReadWriteLock$WriteLock.lock(java.base@11.0.1/ReentrantReadWriteLock.java:959)
    at org.openbase.jul.extension.protobuf.BuilderSyncSetup.lockWrite(BuilderSyncSetup.java:146)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController.reschedule(AbstractUnitController.java:719)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController.reschedule(AbstractUnitController.java:706)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController$3.expired(AbstractUnitController.java:242)
    at org.openbase.jul.schedule.Timeout.lambda$internal_start$0(Timeout.java:183)
    at org.openbase.jul.schedule.Timeout$$Lambda$116/0x000000080032ec40.call(Unknown Source)
    at java.util.concurrent.FutureTask.run(java.base@11.0.1/FutureTask.java:264)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(java.base@11.0.1/ScheduledThreadPoolExecutor.java:304)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.1/ThreadPoolExecutor.java:1128)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.1/ThreadPoolExecutor.java:628)
    at java.lang.Thread.run(java.base@11.0.1/Thread.java:834)
"pool-1-thread-277":
    at org.openbase.jul.extension.rsb.com.AbstractControllerServer.notifyChange(AbstractControllerServer.java:611)
    - waiting to lock <0x00000007823c9260> (a org.openbase.jul.schedule.SyncObject)
    at org.openbase.jul.extension.protobuf.BuilderSyncSetup.unlockWrite(BuilderSyncSetup.java:193)
    at org.openbase.jul.extension.protobuf.ClosableDataBuilder.close(ClosableDataBuilder.java:52)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController.notifyScheduledActionListUnlocked(AbstractUnitController.java:890)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController.notifyScheduledActionList(AbstractUnitController.java:905)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController.reschedule(AbstractUnitController.java:864)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController.scheduleAction(AbstractUnitController.java:675)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController.applyAction(AbstractUnitController.java:578)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController.internalApplyActionAuthenticated(AbstractUnitController.java:951)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController.lambda$applyActionAuthenticated$4(AbstractUnitController.java:932)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController$$Lambda$273/0x00000008006c0040.process(Unknown Source)
    at org.openbase.bco.authentication.lib.AuthenticatedServiceProcessor.authenticatedAction(AuthenticatedServiceProcessor.java:107)
    at org.openbase.bco.authentication.lib.AuthenticatedServiceProcessor.authenticatedAction(AuthenticatedServiceProcessor.java:67)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController.lambda$applyActionAuthenticated$5(AbstractUnitController.java:910)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController$$Lambda$272/0x00000008006ae440.call(Unknown Source)
    at java.util.concurrent.FutureTask.run(java.base@11.0.1/FutureTask.java:264)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.1/ThreadPoolExecutor.java:1128)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.1/ThreadPoolExecutor.java:628)
    at java.lang.Thread.run(java.base@11.0.1/Thread.java:834)
"pool-1-thread-262":
    at jdk.internal.misc.Unsafe.park(java.base@11.0.1/Native Method)
    - parking to wait for  <0x00000007823c9338> (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)
    at java.util.concurrent.locks.LockSupport.park(java.base@11.0.1/LockSupport.java:194)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(java.base@11.0.1/AbstractQueuedSynchronizer.java:885)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireShared(java.base@11.0.1/AbstractQueuedSynchronizer.java:1009)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireShared(java.base@11.0.1/AbstractQueuedSynchronizer.java:1324)
    at java.util.concurrent.locks.ReentrantReadWriteLock$ReadLock.lock(java.base@11.0.1/ReentrantReadWriteLock.java:738)
    at org.openbase.jul.extension.rsb.com.AbstractControllerServer.cloneDataBuilder(AbstractControllerServer.java:543)
    at org.openbase.jul.extension.rsb.com.AbstractControllerServer.notifyChange(AbstractControllerServer.java:623)
    - locked <0x00000007823c9260> (a org.openbase.jul.schedule.SyncObject)
    at org.openbase.jul.extension.protobuf.BuilderSyncSetup.unlockWrite(BuilderSyncSetup.java:193)
    at org.openbase.jul.extension.protobuf.ClosableDataBuilder.close(ClosableDataBuilder.java:52)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController.applyDataUpdate(AbstractUnitController.java:1192)
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@11.0.1/Native Method)
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@11.0.1/NativeMethodAccessorImpl.java:62)
    at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@11.0.1/DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(java.base@11.0.1/Method.java:566)
    at org.openbase.bco.dal.lib.layer.service.mock.OperationServiceFactoryMock.update(OperationServiceFactoryMock.java:239)
    at org.openbase.bco.dal.lib.layer.service.mock.OperationServiceFactoryMock.access$000(OperationServiceFactoryMock.java:56)
    at org.openbase.bco.dal.lib.layer.service.mock.OperationServiceFactoryMock$PowerStateOperationServiceMock.setPowerState(OperationServiceFactoryMock.java:154)
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@11.0.1/Native Method)
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@11.0.1/NativeMethodAccessorImpl.java:62)
    at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@11.0.1/DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(java.base@11.0.1/Method.java:566)
    at org.openbase.bco.dal.lib.layer.service.Services.invokeServiceMethod(Services.java:412)
    at org.openbase.bco.dal.lib.layer.service.Services.invokeServiceMethod(Services.java:407)
    at org.openbase.bco.dal.lib.layer.service.Services.invokeOperationServiceMethod(Services.java:435)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController.performOperationService(AbstractUnitController.java:1471)
    at org.openbase.bco.dal.control.action.ActionImpl.lambda$execute$0(ActionImpl.java:178)
    at org.openbase.bco.dal.control.action.ActionImpl$$Lambda$275/0x00000008006c0840.call(Unknown Source)
    at java.util.concurrent.FutureTask.run(java.base@11.0.1/FutureTask.java:264)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.1/ThreadPoolExecutor.java:1128)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.1/ThreadPoolExecutor.java:628)
    at java.lang.Thread.run(java.base@11.0.1/Thread.java:834)

Found one Java-level deadlock:
=============================
"pool-2-thread-2":
  waiting to lock monitor 0x00007fadfd96d300 (object 0x000000078149d8f8, a org.openbase.jul.schedule.SyncObject),
  which is held by "pool-2-thread-9"
"pool-2-thread-9":
  waiting for ownable synchronizer 0x000000078149d9d0, (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync),
  which is held by "pool-2-thread-2"

Java stack information for the threads listed above:
===================================================
"pool-2-thread-2":
    at org.openbase.jul.extension.rsb.com.AbstractControllerServer.notifyChange(AbstractControllerServer.java:611)
    - waiting to lock <0x000000078149d8f8> (a org.openbase.jul.schedule.SyncObject)
    at org.openbase.jul.extension.protobuf.BuilderSyncSetup.unlockWrite(BuilderSyncSetup.java:193)
    at org.openbase.jul.extension.protobuf.ClosableDataBuilder.close(ClosableDataBuilder.java:52)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController.notifyScheduledActionListUnlocked(AbstractUnitController.java:890)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController.notifyScheduledActionList(AbstractUnitController.java:905)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController.reschedule(AbstractUnitController.java:864)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController.reschedule(AbstractUnitController.java:706)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController$3.expired(AbstractUnitController.java:242)
    at org.openbase.jul.schedule.Timeout.lambda$internal_start$0(Timeout.java:183)
    at org.openbase.jul.schedule.Timeout$$Lambda$116/0x000000080032ec40.call(Unknown Source)
    at java.util.concurrent.FutureTask.run(java.base@11.0.1/FutureTask.java:264)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(java.base@11.0.1/ScheduledThreadPoolExecutor.java:304)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.1/ThreadPoolExecutor.java:1128)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.1/ThreadPoolExecutor.java:628)
    at java.lang.Thread.run(java.base@11.0.1/Thread.java:834)
"pool-2-thread-9":
    at jdk.internal.misc.Unsafe.park(java.base@11.0.1/Native Method)
    - parking to wait for  <0x000000078149d9d0> (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)
    at java.util.concurrent.locks.LockSupport.park(java.base@11.0.1/LockSupport.java:194)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(java.base@11.0.1/AbstractQueuedSynchronizer.java:885)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireShared(java.base@11.0.1/AbstractQueuedSynchronizer.java:1009)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireShared(java.base@11.0.1/AbstractQueuedSynchronizer.java:1324)
    at java.util.concurrent.locks.ReentrantReadWriteLock$ReadLock.lock(java.base@11.0.1/ReentrantReadWriteLock.java:738)
    at org.openbase.jul.extension.rsb.com.AbstractControllerServer.cloneDataBuilder(AbstractControllerServer.java:543)
    at org.openbase.jul.extension.rsb.com.AbstractControllerServer.notifyChange(AbstractControllerServer.java:623)
    - locked <0x000000078149d8f8> (a org.openbase.jul.schedule.SyncObject)
    at org.openbase.jul.extension.protobuf.BuilderSyncSetup.unlockWrite(BuilderSyncSetup.java:193)
    at org.openbase.jul.extension.protobuf.ClosableDataBuilder.close(ClosableDataBuilder.java:52)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController.applyDataUpdate(AbstractUnitController.java:1192)
    at org.openbase.bco.dal.lib.simulation.service.AbstractScheduledServiceSimulator.lambda$new$0(AbstractScheduledServiceSimulator.java:118)
    at org.openbase.bco.dal.lib.simulation.service.AbstractScheduledServiceSimulator$$Lambda$202/0x00000008004b2c40.run(Unknown Source)
    at java.util.concurrent.Executors$RunnableAdapter.call(java.base@11.0.1/Executors.java:515)
    at java.util.concurrent.FutureTask.runAndReset(java.base@11.0.1/FutureTask.java:305)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(java.base@11.0.1/ScheduledThreadPoolExecutor.java:305)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.1/ThreadPoolExecutor.java:1128)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.1/ThreadPoolExecutor.java:628)
    at java.lang.Thread.run(java.base@11.0.1/Thread.java:834)

Found one Java-level deadlock:
=============================
"pool-1-thread-5":
  waiting to lock monitor 0x00007fadfb9b1d00 (object 0x0000000781926e68, a org.openbase.jul.schedule.SyncObject),
  which is held by "pool-1-thread-186"
"pool-1-thread-186":
  waiting for ownable synchronizer 0x0000000781926f40, (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync),
  which is held by "pool-1-thread-15"
"pool-1-thread-15":
  waiting to lock monitor 0x00007fadfb9b1d00 (object 0x0000000781926e68, a org.openbase.jul.schedule.SyncObject),
  which is held by "pool-1-thread-186"

Java stack information for the threads listed above:
===================================================
"pool-1-thread-5":
    at org.openbase.jul.extension.rsb.com.AbstractControllerServer.validateInitialization(AbstractControllerServer.java:801)
    - waiting to lock <0x0000000781926e68> (a org.openbase.jul.schedule.SyncObject)
    at org.openbase.jul.extension.rsb.com.AbstractControllerServer.isActive(AbstractControllerServer.java:434)
    at org.openbase.jul.extension.rsb.com.AbstractControllerServer.validateActivation(AbstractControllerServer.java:814)
    at org.openbase.jul.extension.rsb.com.AbstractControllerServer.validateMiddleware(AbstractControllerServer.java:820)
    at org.openbase.jul.extension.rsb.com.AbstractControllerServer.ping(AbstractControllerServer.java:846)
    at jdk.internal.reflect.GeneratedMethodAccessor614.invoke(Unknown Source)
    at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@11.0.1/DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(java.base@11.0.1/Method.java:566)
    at org.openbase.jul.extension.rsb.com.RPCHelper.lambda$registerMethod$0(RPCHelper.java:135)
    at org.openbase.jul.extension.rsb.com.RPCHelper$$Lambda$144/0x0000000800448440.call(Unknown Source)
    at java.util.concurrent.FutureTask.run(java.base@11.0.1/FutureTask.java:264)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.1/ThreadPoolExecutor.java:1128)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.1/ThreadPoolExecutor.java:628)
    at java.lang.Thread.run(java.base@11.0.1/Thread.java:834)
"pool-1-thread-186":
    at jdk.internal.misc.Unsafe.park(java.base@11.0.1/Native Method)
    - parking to wait for  <0x0000000781926f40> (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)
    at java.util.concurrent.locks.LockSupport.park(java.base@11.0.1/LockSupport.java:194)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(java.base@11.0.1/AbstractQueuedSynchronizer.java:885)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireShared(java.base@11.0.1/AbstractQueuedSynchronizer.java:1009)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireShared(java.base@11.0.1/AbstractQueuedSynchronizer.java:1324)
    at java.util.concurrent.locks.ReentrantReadWriteLock$ReadLock.lock(java.base@11.0.1/ReentrantReadWriteLock.java:738)
    at org.openbase.jul.extension.rsb.com.AbstractControllerServer.cloneDataBuilder(AbstractControllerServer.java:543)
    at org.openbase.jul.extension.rsb.com.AbstractControllerServer.notifyChange(AbstractControllerServer.java:623)
    - locked <0x0000000781926e68> (a org.openbase.jul.schedule.SyncObject)
    at org.openbase.jul.extension.protobuf.BuilderSyncSetup.unlockWrite(BuilderSyncSetup.java:193)
    at org.openbase.jul.extension.protobuf.ClosableDataBuilder.close(ClosableDataBuilder.java:52)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController.notifyScheduledActionListUnlocked(AbstractUnitController.java:890)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController.notifyScheduledActionList(AbstractUnitController.java:905)
    at org.openbase.bco.dal.control.action.ActionImpl.updateActionState(ActionImpl.java:345)
    at org.openbase.bco.dal.control.action.ActionImpl.lambda$execute$0(ActionImpl.java:166)
    at org.openbase.bco.dal.control.action.ActionImpl$$Lambda$275/0x00000008006c0840.call(Unknown Source)
    at java.util.concurrent.FutureTask.run(java.base@11.0.1/FutureTask.java:264)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.1/ThreadPoolExecutor.java:1128)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.1/ThreadPoolExecutor.java:628)
    at java.lang.Thread.run(java.base@11.0.1/Thread.java:834)
"pool-1-thread-15":
    at org.openbase.jul.extension.rsb.com.AbstractControllerServer.notifyChange(AbstractControllerServer.java:611)
    - waiting to lock <0x0000000781926e68> (a org.openbase.jul.schedule.SyncObject)
    at org.openbase.jul.extension.protobuf.BuilderSyncSetup.unlockWrite(BuilderSyncSetup.java:193)
    at org.openbase.jul.extension.protobuf.ClosableDataBuilder.close(ClosableDataBuilder.java:52)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController.notifyScheduledActionListUnlocked(AbstractUnitController.java:890)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController.notifyScheduledActionList(AbstractUnitController.java:905)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController.reschedule(AbstractUnitController.java:864)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController.scheduleAction(AbstractUnitController.java:675)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController.applyAction(AbstractUnitController.java:578)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController.internalApplyActionAuthenticated(AbstractUnitController.java:951)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController.lambda$applyActionAuthenticated$4(AbstractUnitController.java:932)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController$$Lambda$273/0x00000008006c0040.process(Unknown Source)
    at org.openbase.bco.authentication.lib.AuthenticatedServiceProcessor.authenticatedAction(AuthenticatedServiceProcessor.java:107)
    at org.openbase.bco.authentication.lib.AuthenticatedServiceProcessor.authenticatedAction(AuthenticatedServiceProcessor.java:67)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController.lambda$applyActionAuthenticated$5(AbstractUnitController.java:910)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController$$Lambda$272/0x00000008006ae440.call(Unknown Source)
    at java.util.concurrent.FutureTask.run(java.base@11.0.1/FutureTask.java:264)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.1/ThreadPoolExecutor.java:1128)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.1/ThreadPoolExecutor.java:628)
    at java.lang.Thread.run(java.base@11.0.1/Thread.java:834)

Found one Java-level deadlock:
=============================
"pool-2-thread-3":
  waiting to lock monitor 0x00007fadffe2e900 (object 0x0000000781b4bc18, a org.openbase.jul.schedule.SyncObject),
  which is held by "pool-2-thread-8"
"pool-2-thread-8":
  waiting for ownable synchronizer 0x0000000781b4bcf0, (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync),
  which is held by "pool-2-thread-3"

Java stack information for the threads listed above:
===================================================
"pool-2-thread-3":
    at org.openbase.jul.extension.rsb.com.AbstractControllerServer.notifyChange(AbstractControllerServer.java:611)
    - waiting to lock <0x0000000781b4bc18> (a org.openbase.jul.schedule.SyncObject)
    at org.openbase.jul.extension.protobuf.BuilderSyncSetup.unlockWrite(BuilderSyncSetup.java:193)
    at org.openbase.jul.extension.protobuf.ClosableDataBuilder.close(ClosableDataBuilder.java:52)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController.notifyScheduledActionListUnlocked(AbstractUnitController.java:890)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController.notifyScheduledActionList(AbstractUnitController.java:905)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController.reschedule(AbstractUnitController.java:864)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController.reschedule(AbstractUnitController.java:706)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController$3.expired(AbstractUnitController.java:242)
    at org.openbase.jul.schedule.Timeout.lambda$internal_start$0(Timeout.java:183)
    at org.openbase.jul.schedule.Timeout$$Lambda$116/0x000000080032ec40.call(Unknown Source)
    at java.util.concurrent.FutureTask.run(java.base@11.0.1/FutureTask.java:264)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(java.base@11.0.1/ScheduledThreadPoolExecutor.java:304)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.1/ThreadPoolExecutor.java:1128)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.1/ThreadPoolExecutor.java:628)
    at java.lang.Thread.run(java.base@11.0.1/Thread.java:834)
"pool-2-thread-8":
    at jdk.internal.misc.Unsafe.park(java.base@11.0.1/Native Method)
    - parking to wait for  <0x0000000781b4bcf0> (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)
    at java.util.concurrent.locks.LockSupport.park(java.base@11.0.1/LockSupport.java:194)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(java.base@11.0.1/AbstractQueuedSynchronizer.java:885)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireShared(java.base@11.0.1/AbstractQueuedSynchronizer.java:1009)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireShared(java.base@11.0.1/AbstractQueuedSynchronizer.java:1324)
    at java.util.concurrent.locks.ReentrantReadWriteLock$ReadLock.lock(java.base@11.0.1/ReentrantReadWriteLock.java:738)
    at org.openbase.jul.extension.rsb.com.AbstractControllerServer.cloneDataBuilder(AbstractControllerServer.java:543)
    at org.openbase.jul.extension.rsb.com.AbstractControllerServer.notifyChange(AbstractControllerServer.java:623)
    - locked <0x0000000781b4bc18> (a org.openbase.jul.schedule.SyncObject)
    at org.openbase.jul.extension.protobuf.BuilderSyncSetup.unlockWrite(BuilderSyncSetup.java:193)
    at org.openbase.jul.extension.protobuf.ClosableDataBuilder.close(ClosableDataBuilder.java:52)
    at org.openbase.bco.dal.control.layer.unit.AbstractUnitController.applyDataUpdate(AbstractUnitController.java:1192)
    at org.openbase.bco.dal.lib.simulation.service.AbstractScheduledServiceSimulator.lambda$new$0(AbstractScheduledServiceSimulator.java:118)
    at org.openbase.bco.dal.lib.simulation.service.AbstractScheduledServiceSimulator$$Lambda$202/0x00000008004b2c40.run(Unknown Source)
    at java.util.concurrent.Executors$RunnableAdapter.call(java.base@11.0.1/Executors.java:515)
    at java.util.concurrent.FutureTask.runAndReset(java.base@11.0.1/FutureTask.java:305)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(java.base@11.0.1/ScheduledThreadPoolExecutor.java:305)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.1/ThreadPoolExecutor.java:1128)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.1/ThreadPoolExecutor.java:628)
    at java.lang.Thread.run(java.base@11.0.1/Thread.java:834)

Found 4 deadlocks.

Heap
 garbage-first heap   total 227328K, used 68639K [0x0000000780000000, 0x0000000800000000)
  region size 1024K, 18 young (18432K), 6 survivors (6144K)
 Metaspace       used 58783K, capacity 61174K, committed 61352K, reserved 1103872K
  class space    used 6251K, capacity 7091K, committed 7128K, reserved 1048576K

DivineThreepwood commented 5 years ago

All deadlocks are fixed 👍 After the changes, bco runs with 160 simulations per second in benchmark mode without any issues.

DivineThreepwood commented 5 years ago

Fix confirmed.

openbase / bco.dal

AbstractUnitController Deadlock, again :( #137