openbase / bco.dal

Domotic Abstraction Layer
Other
1 stars 2 forks source link

Deadlock in AbstractUnitController during config update #104

Closed DivineThreepwood closed 5 years ago

DivineThreepwood commented 6 years ago
Found one Java-level deadlock:
=============================
"pool-1-thread-96":
  waiting to lock monitor 0x00007ffa1404dbb8 (object 0x00000000808c91f0, a org.openbase.jul.schedule.SyncObject),
  which is held by "Thread-275"
"Thread-275":
  waiting to lock monitor 0x00007ff9c800a618 (object 0x00000000808c8f98, a org.openbase.jul.schedule.SyncObject),
  which is held by "pool-1-thread-96"
Java stack information for the threads listed above:
===================================================
"pool-1-thread-96":
    at org.openbase.jul.extension.rsb.com.AbstractConfigurableController.getConfig(AbstractConfigurableController.java:177)
    - waiting to lock <0x00000000808c91f0> (a org.openbase.jul.schedule.SyncObject)
    at org.openbase.bco.dal.lib.layer.unit.AbstractUnitController.toString(AbstractUnitController.java:511)
    at java.lang.String.valueOf(String.java:2994)
    at java.lang.StringBuilder.append(StringBuilder.java:131)
    at org.openbase.jul.extension.rsb.com.RSBCommunicationService.activate(RSBCommunicationService.java:324)
    - locked <0x00000000808c8f98> (a org.openbase.jul.schedule.SyncObject)
    at org.openbase.bco.dal.lib.layer.unit.AbstractHostUnitController.activate(AbstractHostUnitController.java:103)
    - locked <0x0000000080913a88> (a org.openbase.jul.schedule.SyncObject)
    at org.openbase.jul.storage.registry.ActivatableEntryRegistrySynchronizer.update(ActivatableEntryRegistrySynchronizer.java:50)
    at org.openbase.jul.storage.registry.RegistrySynchronizer.internalSync(RegistrySynchronizer.java:189)
    - locked <0x000000008092bc90> (a org.openbase.jul.schedule.SyncObject)
    at org.openbase.jul.storage.registry.RegistrySynchronizer.access$000(RegistrySynchronizer.java:55)
    at org.openbase.jul.storage.registry.RegistrySynchronizer$1.relay(RegistrySynchronizer.java:93)
    at org.openbase.jul.schedule.RecurrenceEventFilter.relay(RecurrenceEventFilter.java:231)
    at org.openbase.jul.schedule.RecurrenceEventFilter.callRelay(RecurrenceEventFilter.java:216)
    at org.openbase.jul.schedule.RecurrenceEventFilter.trigger(RecurrenceEventFilter.java:153)
    - locked <0x000000008092a0d0> (a org.openbase.jul.storage.registry.RegistrySynchronizer$1)
    at org.openbase.jul.schedule.RecurrenceEventFilter.trigger(RecurrenceEventFilter.java:104)
    - locked <0x000000008092a0d0> (a org.openbase.jul.storage.registry.RegistrySynchronizer$1)
    at org.openbase.jul.storage.registry.RegistrySynchronizer.lambda$null$0(RegistrySynchronizer.java:104)
    at org.openbase.jul.storage.registry.RegistrySynchronizer$$Lambda$118/433794715.run(Unknown Source)
    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)
"Thread-275":
    at org.openbase.jul.extension.rsb.com.RSBCommunicationService.validateInitialization(RSBCommunicationService.java:763)
    - waiting to lock <0x00000000808c8f98> (a org.openbase.jul.schedule.SyncObject)
    at org.openbase.jul.extension.rsb.com.RSBCommunicationService.isActive(RSBCommunicationService.java:416)
    at org.openbase.jul.extension.rsb.com.AbstractConfigurableController.applyConfigUpdate(AbstractConfigurableController.java:103)
    - locked <0x00000000808c91f0> (a org.openbase.jul.schedule.SyncObject)
    at org.openbase.bco.dal.lib.layer.unit.AbstractUnitController.applyConfigUpdate(AbstractUnitController.java:303)
    at org.openbase.bco.dal.lib.layer.unit.AbstractUnitController$1.update(AbstractUnitController.java:127)
    at org.openbase.bco.dal.lib.layer.unit.AbstractUnitController$1.update(AbstractUnitController.java:121)
    at org.openbase.jul.pattern.AbstractObservable.notifyObservers(AbstractObservable.java:253)
    - locked <0x000000008023d170> (a org.openbase.jul.pattern.AbstractObservable$2)
    at org.openbase.jul.pattern.AbstractObservable.notifyObservers(AbstractObservable.java:190)
    at org.openbase.jul.extension.rsb.com.RSBRemoteService.applyDataUpdate(RSBRemoteService.java:1540)
    at org.openbase.jul.extension.rsb.com.RSBRemoteService.applyEventUpdate(RSBRemoteService.java:1194)
    - locked <0x000000008023d218> (a org.openbase.jul.schedule.SyncObject)
    at org.openbase.jul.extension.rsb.com.RSBRemoteService.applyEventUpdate(RSBRemoteService.java:1142)
    at org.openbase.jul.extension.rsb.com.RSBRemoteService$InternalUpdateHandler.internalNotify(RSBRemoteService.java:1478)
    at rsb.eventprocessing.SingleThreadEventReceivingStrategy$DispatchThread.run(SingleThreadEventReceivingStrategy.java:100)
    - locked <0x0000000080b3fd48> (a java.util.Collections$SynchronizedSet)
Found 1 deadlock.
Heap
 PSYoungGen      total 684544K, used 442549K [0x00000000d5580000, 0x0000000100000000, 0x0000000100000000)
  eden space 669696K, 65% used [0x00000000d5580000,0x00000000f00b0a80,0x00000000fe380000)
  from space 14848K, 34% used [0x00000000ff180000,0x00000000ff67cce0,0x0000000100000000)
  to   space 14336K, 0% used [0x00000000fe380000,0x00000000fe380000,0x00000000ff180000)
 ParOldGen       total 699392K, used 15550K [0x0000000080000000, 0x00000000aab00000, 0x00000000d5580000)
  object space 699392K, 2% used [0x0000000080000000,0x0000000080f2f898,0x00000000aab00000)
 Metaspace       used 36093K, capacity 40362K, committed 40448K, reserved 1085440K
  class space    used 4383K, capacity 5086K, committed 5120K, reserved 1048576K
DivineThreepwood commented 6 years ago

Issue has hopefully fixed by openbase/jul@8b7e6ca where I use the global manageable lock for config updates to avoid this deadlock. It was caused because of a config update (holding the config lock) waiting for the manageable lock to verify the initialization while the controller was still in the activation method holding the manageable lock but waiting for the config lock to print the label within the toString() Method. This issue maybe occurs since the unit controller initialization is done via the global thread pool to reduce the observer notification load.

DivineThreepwood commented 6 years ago

Seems to be solved with commit openbase/jul@40ee3a2 and openbase/bco.dal@ee83a7a Let's keep this issue at least for one week in the review section so it can be reopen if it occurs again.