Deadlock in IOC (ConcurrentBarrier vs JustInTimeObjectCreator)

classic Classic list List threaded Threaded
5 messages Options
Reply | Threaded
Open this post in threaded view
|

Deadlock in IOC (ConcurrentBarrier vs JustInTimeObjectCreator)

Oliver Kaiser
Hi everyone,


we recently found a strange deadlock problem; first seemed to be related
to switching from 5.5.0-beta-1 to 5.5.0, at least
in the full application it was easy to reproduce with the latter but (in
a few manual tests) not with the beta.

after trying to reduce it to a minimal test case…  it can be triggered
with either (and 5.4.x); maybe in the "real" code the calls
take long enough to avoid the data race or at least make it unlikely.


on to the questions:

* has anyone seen something like this before? closest bug i can find is:
https://issues.apache.org/jira/browse/TAPESTRY-2561

* is this likely related to registry startup? kinda afraid of same
situation during normal operations, though once most/all services
are realized everything should be fine

thanks for reading & any hints you can offer

Regards,
Oliver


it appears all of the following is required:

* a builder method for a simple class (not a service); with some kind of
call to IOC (inject anything)

   public static SomeClass build(@Inject @Symbol("some.symbol") String
uri) {
     return new SomeClass();
   }


* this class is a dependency for a shared service:

public class SharedImpl implements Shared {

   public SharedImpl(SomeClass iDoNothing) {
   }


* two services marked as eager-load; both require the shared service

   public static void bind(ServiceBinder binder) {
     binder.bind(JobAdder.class, JobAdderImpl.class).eagerLoad();
     binder.bind(Other.class, OtherImpl.class).eagerLoad();
     binder.bind(Shared.class, SharedImpl.class);
   }


* JobAdder c-tor adds Runnable(s) to PeriodicExecutor

   public JobAdderImpl(List<RunnableJobData> parts, PeriodicExecutor exec) {
     LOG.info("Blocked here?");

     for (RunnableJobData p : parts) {
       exec.addJob(new ImmediateStartIntervalSchedule(1000 * 60),
p.name, p.run);
     }
   }


* the Runnable and OtherImpl (c-tor) call the shared service (instances
are realized)

   @Contribute(JobAdder.class)
   public static void contributeJobParts(OrderedConfiguration conf,
Shared something) {

     conf.add("abc", new RunnableJobData("abc", () -> {
       LOG.info("starting job");
       something.doFoo();


   public class OtherImpl implements Other {

     public OtherImpl(Shared xx) {
       xx.doFoo();


* the jobs start immediately (no initial delay)

   public class ImmediateStartIntervalSchedule extends IntervalSchedule {

     public ImmediateStartIntervalSchedule(final long interval) {
       super(interval);
     }

     @Override
     public long firstExecution() {
       return System.currentTimeMillis();
     }



probably the easiest fix (for us) is to avoid the immediate execution of
periodic jobs while "RegistryImpl.performRegistryStartup"
is still running on the main thread; e.g. adding the jobs from a
@Startup method seems to work ok

maybe PeriodicExecutorImpl::start should be called from @Startup instead
of @PostInjection (assuming startup methods are called after the
registry is done, while @PostInjection is called earlier?)


in the trace below both threads "hold" a R-lock, one also has (upgraded
to) W, the second blocks on W … that seems wrong

https://github.com/apache/tapestry-5/blob/master/tapestry-ioc/src/main/java/org/apache/tapestry5/ioc/internal/util/ConcurrentBarrier.java#L54
maybe reentrancy; but i'm not sure about the "upgrade R to W" logic



here is the test source: https://easyupload.io/xzy6j1


Found one Java-level deadlock:
=============================
"main":
   waiting to lock monitor 0x00007f7f38008b80 (object
0x000000071554f4a8, a
org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator),
   which is held by "Tapestry PeriodicExecutor"
"Tapestry PeriodicExecutor":
   waiting for ownable synchronizer 0x0000000716130940, (a
java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync),
   which is held by "main"


"main":
         at
org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator.obtainObjectFromCreator(JustInTimeObjectCreator.java:62)
         - waiting to lock <0x000000071554f4a8> (a
org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator)
         at
org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator.createObject(JustInTimeObjectCreator.java:55)
         at $SymbolSource_c9319bed00c.delegate(Unknown Source)
         at $SymbolSource_c9319bed00c.valueForSymbol(Unknown Source)
         at
org.apache.tapestry5.ioc.internal.services.SymbolObjectProvider.provide(SymbolObjectProvider.java:50)

         at
org.apache.tapestry5.ioc.internal.ModuleImpl$1.invoke(ModuleImpl.java:198)
         at
org.apache.tapestry5.ioc.internal.util.ConcurrentBarrier.withWrite(ConcurrentBarrier.java:139)
         at
org.apache.tapestry5.ioc.internal.ModuleImpl$2.invoke(ModuleImpl.java:215)
         at
org.apache.tapestry5.ioc.internal.util.ConcurrentBarrier.withRead(ConcurrentBarrier.java:83)
         at
org.apache.tapestry5.ioc.internal.ModuleImpl.findOrCreate(ModuleImpl.java:221)
         at
org.apache.tapestry5.ioc.internal.ModuleImpl.getService(ModuleImpl.java:112)


         at
org.apache.tapestry5.ioc.internal.AbstractReloadableObjectCreator.createObject(AbstractReloadableObjectCreator.java:118)
         - locked <0x00000007154d53f8> (a
org.apache.tapestry5.ioc.internal.ReloadableServiceImplementationObjectCreator)
         at $Shared_c9319bed012.delegate(Unknown Source)
         at $Shared_c9319bed012.doFoo(Unknown Source)
         at $Shared_c9319bed00e.doFoo(Unknown Source)
         at de.eddyson.t5.deadlock.OtherImpl.<init>(OtherImpl.java:8)

         at
org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator.obtainObjectFromCreator(JustInTimeObjectCreator.java:67)
         - locked <0x00000007156584b0> (a
org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator)
         at
org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator.createObject(JustInTimeObjectCreator.java:55)
         at
org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator.eagerLoadService(JustInTimeObjectCreator.java:88)
         at
org.apache.tapestry5.ioc.internal.RegistryImpl.performRegistryStartup(RegistryImpl.java:357)
         at
org.apache.tapestry5.ioc.internal.RegistryWrapper.performRegistryStartup(RegistryWrapper.java:89)



"Tapestry PeriodicExecutor":
         at jdk.internal.misc.Unsafe.park(java.base@11.0.8/Native Method)
         - parking to wait for  <0x0000000716130940> (a
java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)
         at
java.util.concurrent.locks.LockSupport.park(java.base@11.0.8/LockSupport.java:194)
         at
java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(java.base@11.0.8/AbstractQueuedSynchronizer.java:885)
         at
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(java.base@11.0.8/AbstractQueuedSynchronizer.java:917)
         at
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(java.base@11.0.8/AbstractQueuedSynchronizer.java:1240)
         at
java.util.concurrent.locks.ReentrantReadWriteLock$WriteLock.lock(java.base@11.0.8/ReentrantReadWriteLock.java:959)
         at
org.apache.tapestry5.ioc.internal.util.ConcurrentBarrier.withWrite(ConcurrentBarrier.java:135)
         at
org.apache.tapestry5.ioc.internal.ModuleImpl$2.invoke(ModuleImpl.java:215)
         at
org.apache.tapestry5.ioc.internal.util.ConcurrentBarrier.withRead(ConcurrentBarrier.java:83)
         at
org.apache.tapestry5.ioc.internal.ModuleImpl.findOrCreate(ModuleImpl.java:221)
         at
org.apache.tapestry5.ioc.internal.ModuleImpl.getService(ModuleImpl.java:112)
         at
org.apache.tapestry5.ioc.internal.RegistryImpl.getService(RegistryImpl.java:497)

         - locked <0x000000071554f4a8> (a
org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator)
         at
org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator.createObject(JustInTimeObjectCreator.java:55)
         at $SymbolSource_c9319bed00c.delegate(Unknown Source)
         at $SymbolSource_c9319bed00c.valueForSymbol(Unknown Source)
         at
org.apache.tapestry5.ioc.internal.services.SymbolObjectProvider.provide(SymbolObjectProvider.java:50)

         at
org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator.obtainObjectFromCreator(JustInTimeObjectCreator.java:67)
         - locked <0x000000071548fd68> (a
org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator)
         at
org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator.createObject(JustInTimeObjectCreator.java:55)
         at $ParallelExecutor_c9319bed010.delegate(Unknown Source)
         at $ParallelExecutor_c9319bed010.invoke(Unknown Source)
         at
org.apache.tapestry5.ioc.internal.services.cron.PeriodicExecutorImpl$Job.start(PeriodicExecutorImpl.java:181)
         at
org.apache.tapestry5.ioc.internal.services.cron.PeriodicExecutorImpl.executeCurrentBatch(PeriodicExecutorImpl.java:382)
         at
org.apache.tapestry5.ioc.internal.services.cron.PeriodicExecutorImpl.run(PeriodicExecutorImpl.java:315)

---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: Deadlock in IOC (ConcurrentBarrier vs JustInTimeObjectCreator)

Thiago H de Paula Figueiredo
Hello!

It's a very specific corner case. Please create a JIRA ticket and I'll try
to fix it. Thanks for posting and investigating!

On Thu, Jul 30, 2020 at 1:44 PM Oliver Kaiser <[hidden email]>
wrote:

> Hi everyone,
>
>
> we recently found a strange deadlock problem; first seemed to be related
> to switching from 5.5.0-beta-1 to 5.5.0, at least
> in the full application it was easy to reproduce with the latter but (in
> a few manual tests) not with the beta.
>
> after trying to reduce it to a minimal test case…  it can be triggered
> with either (and 5.4.x); maybe in the "real" code the calls
> take long enough to avoid the data race or at least make it unlikely.
>
>
> on to the questions:
>
> * has anyone seen something like this before? closest bug i can find is:
> https://issues.apache.org/jira/browse/TAPESTRY-2561
>
> * is this likely related to registry startup? kinda afraid of same
> situation during normal operations, though once most/all services
> are realized everything should be fine
>
> thanks for reading & any hints you can offer
>
> Regards,
> Oliver
>
>
> it appears all of the following is required:
>
> * a builder method for a simple class (not a service); with some kind of
> call to IOC (inject anything)
>
>    public static SomeClass build(@Inject @Symbol("some.symbol") String
> uri) {
>      return new SomeClass();
>    }
>
>
> * this class is a dependency for a shared service:
>
> public class SharedImpl implements Shared {
>
>    public SharedImpl(SomeClass iDoNothing) {
>    }
>
>
> * two services marked as eager-load; both require the shared service
>
>    public static void bind(ServiceBinder binder) {
>      binder.bind(JobAdder.class, JobAdderImpl.class).eagerLoad();
>      binder.bind(Other.class, OtherImpl.class).eagerLoad();
>      binder.bind(Shared.class, SharedImpl.class);
>    }
>
>
> * JobAdder c-tor adds Runnable(s) to PeriodicExecutor
>
>    public JobAdderImpl(List<RunnableJobData> parts, PeriodicExecutor exec)
> {
>      LOG.info("Blocked here?");
>
>      for (RunnableJobData p : parts) {
>        exec.addJob(new ImmediateStartIntervalSchedule(1000 * 60),
> p.name, p.run);
>      }
>    }
>
>
> * the Runnable and OtherImpl (c-tor) call the shared service (instances
> are realized)
>
>    @Contribute(JobAdder.class)
>    public static void contributeJobParts(OrderedConfiguration conf,
> Shared something) {
>
>      conf.add("abc", new RunnableJobData("abc", () -> {
>        LOG.info("starting job");
>        something.doFoo();
>
>
>    public class OtherImpl implements Other {
>
>      public OtherImpl(Shared xx) {
>        xx.doFoo();
>
>
> * the jobs start immediately (no initial delay)
>
>    public class ImmediateStartIntervalSchedule extends IntervalSchedule {
>
>      public ImmediateStartIntervalSchedule(final long interval) {
>        super(interval);
>      }
>
>      @Override
>      public long firstExecution() {
>        return System.currentTimeMillis();
>      }
>
>
>
> probably the easiest fix (for us) is to avoid the immediate execution of
> periodic jobs while "RegistryImpl.performRegistryStartup"
> is still running on the main thread; e.g. adding the jobs from a
> @Startup method seems to work ok
>
> maybe PeriodicExecutorImpl::start should be called from @Startup instead
> of @PostInjection (assuming startup methods are called after the
> registry is done, while @PostInjection is called earlier?)
>
>
> in the trace below both threads "hold" a R-lock, one also has (upgraded
> to) W, the second blocks on W … that seems wrong
>
>
> https://github.com/apache/tapestry-5/blob/master/tapestry-ioc/src/main/java/org/apache/tapestry5/ioc/internal/util/ConcurrentBarrier.java#L54
> maybe reentrancy; but i'm not sure about the "upgrade R to W" logic
>
>
>
> here is the test source: https://easyupload.io/xzy6j1
>
>
> Found one Java-level deadlock:
> =============================
> "main":
>    waiting to lock monitor 0x00007f7f38008b80 (object
> 0x000000071554f4a8, a
> org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator),
>    which is held by "Tapestry PeriodicExecutor"
> "Tapestry PeriodicExecutor":
>    waiting for ownable synchronizer 0x0000000716130940, (a
> java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync),
>    which is held by "main"
>
>
> "main":
>          at
>
> org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator.obtainObjectFromCreator(JustInTimeObjectCreator.java:62)
>          - waiting to lock <0x000000071554f4a8> (a
> org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator)
>          at
>
> org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator.createObject(JustInTimeObjectCreator.java:55)
>          at $SymbolSource_c9319bed00c.delegate(Unknown Source)
>          at $SymbolSource_c9319bed00c.valueForSymbol(Unknown Source)
>          at
>
> org.apache.tapestry5.ioc.internal.services.SymbolObjectProvider.provide(SymbolObjectProvider.java:50)
> …
>          at
> org.apache.tapestry5.ioc.internal.ModuleImpl$1.invoke(ModuleImpl.java:198)
>          at
>
> org.apache.tapestry5.ioc.internal.util.ConcurrentBarrier.withWrite(ConcurrentBarrier.java:139)
>          at
> org.apache.tapestry5.ioc.internal.ModuleImpl$2.invoke(ModuleImpl.java:215)
>          at
>
> org.apache.tapestry5.ioc.internal.util.ConcurrentBarrier.withRead(ConcurrentBarrier.java:83)
>          at
>
> org.apache.tapestry5.ioc.internal.ModuleImpl.findOrCreate(ModuleImpl.java:221)
>          at
>
> org.apache.tapestry5.ioc.internal.ModuleImpl.getService(ModuleImpl.java:112)
>
> …
>          at
>
> org.apache.tapestry5.ioc.internal.AbstractReloadableObjectCreator.createObject(AbstractReloadableObjectCreator.java:118)
>          - locked <0x00000007154d53f8> (a
>
> org.apache.tapestry5.ioc.internal.ReloadableServiceImplementationObjectCreator)
>          at $Shared_c9319bed012.delegate(Unknown Source)
>          at $Shared_c9319bed012.doFoo(Unknown Source)
>          at $Shared_c9319bed00e.doFoo(Unknown Source)
>          at de.eddyson.t5.deadlock.OtherImpl.<init>(OtherImpl.java:8)
> …
>          at
>
> org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator.obtainObjectFromCreator(JustInTimeObjectCreator.java:67)
>          - locked <0x00000007156584b0> (a
> org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator)
>          at
>
> org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator.createObject(JustInTimeObjectCreator.java:55)
>          at
>
> org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator.eagerLoadService(JustInTimeObjectCreator.java:88)
>          at
>
> org.apache.tapestry5.ioc.internal.RegistryImpl.performRegistryStartup(RegistryImpl.java:357)
>          at
>
> org.apache.tapestry5.ioc.internal.RegistryWrapper.performRegistryStartup(RegistryWrapper.java:89)
>
>
>
> "Tapestry PeriodicExecutor":
>          at jdk.internal.misc.Unsafe.park(java.base@11.0.8/Native Method)
>          - parking to wait for  <0x0000000716130940> (a
> java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)
>          at
> java.util.concurrent.locks.LockSupport.park(java.base@11.0.8
> /LockSupport.java:194)
>          at
>
> java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(java.base@11.0.8
> /AbstractQueuedSynchronizer.java:885)
>          at
>
> java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(java.base@11.0.8
> /AbstractQueuedSynchronizer.java:917)
>          at
>
> java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(java.base@11.0.8
> /AbstractQueuedSynchronizer.java:1240)
>          at
>
> java.util.concurrent.locks.ReentrantReadWriteLock$WriteLock.lock(java.base@11.0.8
> /ReentrantReadWriteLock.java:959)
>          at
>
> org.apache.tapestry5.ioc.internal.util.ConcurrentBarrier.withWrite(ConcurrentBarrier.java:135)
>          at
> org.apache.tapestry5.ioc.internal.ModuleImpl$2.invoke(ModuleImpl.java:215)
>          at
>
> org.apache.tapestry5.ioc.internal.util.ConcurrentBarrier.withRead(ConcurrentBarrier.java:83)
>          at
>
> org.apache.tapestry5.ioc.internal.ModuleImpl.findOrCreate(ModuleImpl.java:221)
>          at
>
> org.apache.tapestry5.ioc.internal.ModuleImpl.getService(ModuleImpl.java:112)
>          at
>
> org.apache.tapestry5.ioc.internal.RegistryImpl.getService(RegistryImpl.java:497)
> …
>          - locked <0x000000071554f4a8> (a
> org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator)
>          at
>
> org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator.createObject(JustInTimeObjectCreator.java:55)
>          at $SymbolSource_c9319bed00c.delegate(Unknown Source)
>          at $SymbolSource_c9319bed00c.valueForSymbol(Unknown Source)
>          at
>
> org.apache.tapestry5.ioc.internal.services.SymbolObjectProvider.provide(SymbolObjectProvider.java:50)
> …
>          at
>
> org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator.obtainObjectFromCreator(JustInTimeObjectCreator.java:67)
>          - locked <0x000000071548fd68> (a
> org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator)
>          at
>
> org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator.createObject(JustInTimeObjectCreator.java:55)
>          at $ParallelExecutor_c9319bed010.delegate(Unknown Source)
>          at $ParallelExecutor_c9319bed010.invoke(Unknown Source)
>          at
>
> org.apache.tapestry5.ioc.internal.services.cron.PeriodicExecutorImpl$Job.start(PeriodicExecutorImpl.java:181)
>          at
>
> org.apache.tapestry5.ioc.internal.services.cron.PeriodicExecutorImpl.executeCurrentBatch(PeriodicExecutorImpl.java:382)
>          at
>
> org.apache.tapestry5.ioc.internal.services.cron.PeriodicExecutorImpl.run(PeriodicExecutorImpl.java:315)
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>
>

--
Thiago
Reply | Threaded
Open this post in threaded view
|

Re: Deadlock in IOC (ConcurrentBarrier vs JustInTimeObjectCreator)

Thiago H de Paula Figueiredo
Hello, Oliver!

I've committed a fix using your code as a test and uploaded a new Tapestry
5.6.0 snapshot to the ASF snapshot repository at
https://repository.apache.org/content/groups/snapshots/. Could you please
test on your end too? Thanks in advance.

On Sat, Aug 15, 2020 at 3:08 PM Thiago H. de Paula Figueiredo <
[hidden email]> wrote:

> Hello!
>
> It's a very specific corner case. Please create a JIRA ticket and I'll try
> to fix it. Thanks for posting and investigating!
>
> On Thu, Jul 30, 2020 at 1:44 PM Oliver Kaiser <[hidden email]>
> wrote:
>
>> Hi everyone,
>>
>>
>> we recently found a strange deadlock problem; first seemed to be related
>> to switching from 5.5.0-beta-1 to 5.5.0, at least
>> in the full application it was easy to reproduce with the latter but (in
>> a few manual tests) not with the beta.
>>
>> after trying to reduce it to a minimal test case…  it can be triggered
>> with either (and 5.4.x); maybe in the "real" code the calls
>> take long enough to avoid the data race or at least make it unlikely.
>>
>>
>> on to the questions:
>>
>> * has anyone seen something like this before? closest bug i can find is:
>> https://issues.apache.org/jira/browse/TAPESTRY-2561
>>
>> * is this likely related to registry startup? kinda afraid of same
>> situation during normal operations, though once most/all services
>> are realized everything should be fine
>>
>> thanks for reading & any hints you can offer
>>
>> Regards,
>> Oliver
>>
>>
>> it appears all of the following is required:
>>
>> * a builder method for a simple class (not a service); with some kind of
>> call to IOC (inject anything)
>>
>>    public static SomeClass build(@Inject @Symbol("some.symbol") String
>> uri) {
>>      return new SomeClass();
>>    }
>>
>>
>> * this class is a dependency for a shared service:
>>
>> public class SharedImpl implements Shared {
>>
>>    public SharedImpl(SomeClass iDoNothing) {
>>    }
>>
>>
>> * two services marked as eager-load; both require the shared service
>>
>>    public static void bind(ServiceBinder binder) {
>>      binder.bind(JobAdder.class, JobAdderImpl.class).eagerLoad();
>>      binder.bind(Other.class, OtherImpl.class).eagerLoad();
>>      binder.bind(Shared.class, SharedImpl.class);
>>    }
>>
>>
>> * JobAdder c-tor adds Runnable(s) to PeriodicExecutor
>>
>>    public JobAdderImpl(List<RunnableJobData> parts, PeriodicExecutor
>> exec) {
>>      LOG.info("Blocked here?");
>>
>>      for (RunnableJobData p : parts) {
>>        exec.addJob(new ImmediateStartIntervalSchedule(1000 * 60),
>> p.name, p.run);
>>      }
>>    }
>>
>>
>> * the Runnable and OtherImpl (c-tor) call the shared service (instances
>> are realized)
>>
>>    @Contribute(JobAdder.class)
>>    public static void contributeJobParts(OrderedConfiguration conf,
>> Shared something) {
>>
>>      conf.add("abc", new RunnableJobData("abc", () -> {
>>        LOG.info("starting job");
>>        something.doFoo();
>>
>>
>>    public class OtherImpl implements Other {
>>
>>      public OtherImpl(Shared xx) {
>>        xx.doFoo();
>>
>>
>> * the jobs start immediately (no initial delay)
>>
>>    public class ImmediateStartIntervalSchedule extends IntervalSchedule {
>>
>>      public ImmediateStartIntervalSchedule(final long interval) {
>>        super(interval);
>>      }
>>
>>      @Override
>>      public long firstExecution() {
>>        return System.currentTimeMillis();
>>      }
>>
>>
>>
>> probably the easiest fix (for us) is to avoid the immediate execution of
>> periodic jobs while "RegistryImpl.performRegistryStartup"
>> is still running on the main thread; e.g. adding the jobs from a
>> @Startup method seems to work ok
>>
>> maybe PeriodicExecutorImpl::start should be called from @Startup instead
>> of @PostInjection (assuming startup methods are called after the
>> registry is done, while @PostInjection is called earlier?)
>>
>>
>> in the trace below both threads "hold" a R-lock, one also has (upgraded
>> to) W, the second blocks on W … that seems wrong
>>
>>
>> https://github.com/apache/tapestry-5/blob/master/tapestry-ioc/src/main/java/org/apache/tapestry5/ioc/internal/util/ConcurrentBarrier.java#L54
>> maybe reentrancy; but i'm not sure about the "upgrade R to W" logic
>>
>>
>>
>> here is the test source: https://easyupload.io/xzy6j1
>>
>>
>> Found one Java-level deadlock:
>> =============================
>> "main":
>>    waiting to lock monitor 0x00007f7f38008b80 (object
>> 0x000000071554f4a8, a
>> org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator),
>>    which is held by "Tapestry PeriodicExecutor"
>> "Tapestry PeriodicExecutor":
>>    waiting for ownable synchronizer 0x0000000716130940, (a
>> java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync),
>>    which is held by "main"
>>
>>
>> "main":
>>          at
>>
>> org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator.obtainObjectFromCreator(JustInTimeObjectCreator.java:62)
>>          - waiting to lock <0x000000071554f4a8> (a
>> org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator)
>>          at
>>
>> org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator.createObject(JustInTimeObjectCreator.java:55)
>>          at $SymbolSource_c9319bed00c.delegate(Unknown Source)
>>          at $SymbolSource_c9319bed00c.valueForSymbol(Unknown Source)
>>          at
>>
>> org.apache.tapestry5.ioc.internal.services.SymbolObjectProvider.provide(SymbolObjectProvider.java:50)
>> …
>>          at
>> org.apache.tapestry5.ioc.internal.ModuleImpl$1.invoke(ModuleImpl.java:198)
>>          at
>>
>> org.apache.tapestry5.ioc.internal.util.ConcurrentBarrier.withWrite(ConcurrentBarrier.java:139)
>>          at
>> org.apache.tapestry5.ioc.internal.ModuleImpl$2.invoke(ModuleImpl.java:215)
>>          at
>>
>> org.apache.tapestry5.ioc.internal.util.ConcurrentBarrier.withRead(ConcurrentBarrier.java:83)
>>          at
>>
>> org.apache.tapestry5.ioc.internal.ModuleImpl.findOrCreate(ModuleImpl.java:221)
>>          at
>>
>> org.apache.tapestry5.ioc.internal.ModuleImpl.getService(ModuleImpl.java:112)
>>
>> …
>>          at
>>
>> org.apache.tapestry5.ioc.internal.AbstractReloadableObjectCreator.createObject(AbstractReloadableObjectCreator.java:118)
>>          - locked <0x00000007154d53f8> (a
>>
>> org.apache.tapestry5.ioc.internal.ReloadableServiceImplementationObjectCreator)
>>          at $Shared_c9319bed012.delegate(Unknown Source)
>>          at $Shared_c9319bed012.doFoo(Unknown Source)
>>          at $Shared_c9319bed00e.doFoo(Unknown Source)
>>          at de.eddyson.t5.deadlock.OtherImpl.<init>(OtherImpl.java:8)
>> …
>>          at
>>
>> org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator.obtainObjectFromCreator(JustInTimeObjectCreator.java:67)
>>          - locked <0x00000007156584b0> (a
>> org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator)
>>          at
>>
>> org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator.createObject(JustInTimeObjectCreator.java:55)
>>          at
>>
>> org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator.eagerLoadService(JustInTimeObjectCreator.java:88)
>>          at
>>
>> org.apache.tapestry5.ioc.internal.RegistryImpl.performRegistryStartup(RegistryImpl.java:357)
>>          at
>>
>> org.apache.tapestry5.ioc.internal.RegistryWrapper.performRegistryStartup(RegistryWrapper.java:89)
>>
>>
>>
>> "Tapestry PeriodicExecutor":
>>          at jdk.internal.misc.Unsafe.park(java.base@11.0.8/Native Method)
>>          - parking to wait for  <0x0000000716130940> (a
>> java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)
>>          at
>> java.util.concurrent.locks.LockSupport.park(java.base@11.0.8
>> /LockSupport.java:194)
>>          at
>>
>> java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(java.base@11.0.8
>> /AbstractQueuedSynchronizer.java:885)
>>          at
>>
>> java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(java.base@11.0.8
>> /AbstractQueuedSynchronizer.java:917)
>>          at
>>
>> java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(java.base@11.0.8
>> /AbstractQueuedSynchronizer.java:1240)
>>          at
>>
>> java.util.concurrent.locks.ReentrantReadWriteLock$WriteLock.lock(java.base@11.0.8
>> /ReentrantReadWriteLock.java:959)
>>          at
>>
>> org.apache.tapestry5.ioc.internal.util.ConcurrentBarrier.withWrite(ConcurrentBarrier.java:135)
>>          at
>> org.apache.tapestry5.ioc.internal.ModuleImpl$2.invoke(ModuleImpl.java:215)
>>          at
>>
>> org.apache.tapestry5.ioc.internal.util.ConcurrentBarrier.withRead(ConcurrentBarrier.java:83)
>>          at
>>
>> org.apache.tapestry5.ioc.internal.ModuleImpl.findOrCreate(ModuleImpl.java:221)
>>          at
>>
>> org.apache.tapestry5.ioc.internal.ModuleImpl.getService(ModuleImpl.java:112)
>>          at
>>
>> org.apache.tapestry5.ioc.internal.RegistryImpl.getService(RegistryImpl.java:497)
>> …
>>          - locked <0x000000071554f4a8> (a
>> org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator)
>>          at
>>
>> org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator.createObject(JustInTimeObjectCreator.java:55)
>>          at $SymbolSource_c9319bed00c.delegate(Unknown Source)
>>          at $SymbolSource_c9319bed00c.valueForSymbol(Unknown Source)
>>          at
>>
>> org.apache.tapestry5.ioc.internal.services.SymbolObjectProvider.provide(SymbolObjectProvider.java:50)
>> …
>>          at
>>
>> org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator.obtainObjectFromCreator(JustInTimeObjectCreator.java:67)
>>          - locked <0x000000071548fd68> (a
>> org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator)
>>          at
>>
>> org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator.createObject(JustInTimeObjectCreator.java:55)
>>          at $ParallelExecutor_c9319bed010.delegate(Unknown Source)
>>          at $ParallelExecutor_c9319bed010.invoke(Unknown Source)
>>          at
>>
>> org.apache.tapestry5.ioc.internal.services.cron.PeriodicExecutorImpl$Job.start(PeriodicExecutorImpl.java:181)
>>          at
>>
>> org.apache.tapestry5.ioc.internal.services.cron.PeriodicExecutorImpl.executeCurrentBatch(PeriodicExecutorImpl.java:382)
>>          at
>>
>> org.apache.tapestry5.ioc.internal.services.cron.PeriodicExecutorImpl.run(PeriodicExecutorImpl.java:315)
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: [hidden email]
>> For additional commands, e-mail: [hidden email]
>>
>>
>
> --
> Thiago
>


--
Thiago
Reply | Threaded
Open this post in threaded view
|

Re: Deadlock in IOC (ConcurrentBarrier vs JustInTimeObjectCreator)

Oliver Kaiser
On 08/16/2020 10:20 PM, Thiago H. de Paula Figueiredo wrote:

> I've committed a fix using your code as a test and uploaded a new Tapestry
> 5.6.0 snapshot to the ASF snapshot repository at
> https://repository.apache.org/content/groups/snapshots/. Could you please
> test on your end too? Thanks in advance.


sure; that seems to fix it

thank you,
Oliver

---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: Deadlock in IOC (ConcurrentBarrier vs JustInTimeObjectCreator)

Thiago H de Paula Figueiredo
On Mon, Aug 17, 2020 at 6:42 AM Oliver Kaiser <[hidden email]>
wrote:

> sure; that seems to fix it
>

Thank *you* for doing almost the whole work here: spotting the issue,
creating a test case, suggesting the fix (which was exactly what you
suggested) then confirming it. :)


>
> thank you,
> Oliver
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>
>

--
Thiago