You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@ode.apache.org by Rafal Rusin <ra...@gmail.com> on 2009/02/13 11:10:22 UTC
Bpel execution in ODE
Hello,
could you explain me a bit bpel execution regarding BpelRuntimeContext?
I saw a following happened:
09:59:25,185 | INFO | pool-4-thread-4 | BpelRuntimeContextImpl |
.engine.BpelRuntimeContextImpl 160 | BpelRuntimeContextImpl created
for instance 20598 24589427
09:59:25,269 | INFO | pool-4-thread-7 | BpelRuntimeContextImpl |
.engine.BpelRuntimeContextImpl 160 | BpelRuntimeContextImpl created
for instance 20598 1821816
09:59:25,628 | INFO | pool-4-thread-4 | BpelRuntimeContextImpl |
.engine.BpelRuntimeContextImpl 843 | BpelRuntimeContextImpl setting
execution state on instance 20598 24589427
09:59:25,781 | INFO | pool-4-thread-7 | BpelRuntimeContextImpl |
.engine.BpelRuntimeContextImpl 843 | BpelRuntimeContextImpl setting
execution state on instance 20598 1821816
The numbers at the end (24589427 and 1821816) are hash ids for
BpelRuntimeContextImpl.
It happened after executing concurrently two jobs INVOKE_RESPONSE for
invoke1 and invoke3. A bpel process was like this:
<flow>
<sequence>
<invoke1/>
<invoke2/>
</sequence>
<sequence>
<invoke3/>
<invoke4/>
</sequence>
</flow>
My question is whether such execution should be made synchronized in
ODE? Here setting execution state happened concurrently in
pool-4-thread-4 and pool-4-thread-7.
I used transaction isolation level READ_COMMITTED (a default one). In
this scenario, I had two jobs concurrently, successfully committed and
no critical section was used.
Both transactions saw committed data, so READ_COMMITTED was held.
It lead to storing incorrect execution state for process instance in
DB, since one INVOKE_RESPONSE job work was lost due to overwritten
data.
What transaction isolation level is correct for ODE? And what should I
do to correct this scenario? Do you have any clues?
I had an error in Oracle:
09:59:27,383 | ERROR | pool-4-thread-7 | JacobVPU |
b.vpu.JacobVPU$JacobThreadImpl 463 | Method "run" in class
"org.apache.ode.bpel.engine.BpelRuntimeContextImpl$6" threw an
unexpected excep
tion.
java.lang.IllegalArgumentException: No such channel; id=225
at org.apache.ode.jacob.vpu.ExecutionQueueImpl.findChannelFrame(ExecutionQueueImpl.java:205)
at org.apache.ode.jacob.vpu.ExecutionQueueImpl.consumeExport(ExecutionQueueImpl.java:232)
at org.apache.ode.jacob.vpu.JacobVPU$JacobThreadImpl.importChannel(JacobVPU.java:369)
at org.apache.ode.jacob.JacobObject.importChannel(JacobObject.java:47)
at org.apache.ode.bpel.engine.BpelRuntimeContextImpl$6.run(BpelRuntimeContextImpl.java:967)
at sun.reflect.GeneratedMethodAccessor120.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:585)
at org.apache.ode.jacob.vpu.JacobVPU$JacobThreadImpl.run(JacobVPU.java:451)
at org.apache.ode.jacob.vpu.JacobVPU.execute(JacobVPU.java:139)
at org.apache.ode.bpel.engine.BpelRuntimeContextImpl.execute(BpelRuntimeContextImpl.java:839)
at org.apache.ode.bpel.engine.BpelProcess.handleWorkEvent(BpelProcess.java:418)
at org.apache.ode.bpel.engine.BpelEngineImpl.onScheduledJob(BpelEngineImpl.java:424)
at org.apache.ode.bpel.engine.BpelServerImpl.onScheduledJob(BpelServerImpl.java:377)
at org.apache.ode.scheduler.simple.SimpleScheduler$4$1.call(SimpleScheduler.java:386)
at org.apache.ode.scheduler.simple.SimpleScheduler$4$1.call(SimpleScheduler.java:380)
at org.apache.ode.scheduler.simple.SimpleScheduler.execTransaction(SimpleScheduler.java:208)
at org.apache.ode.scheduler.simple.SimpleScheduler$4.call(SimpleScheduler.java:379)
at org.apache.ode.scheduler.simple.SimpleScheduler$4.call(SimpleScheduler.java:376)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:269)
at java.util.concurrent.FutureTask.run(FutureTask.java:123)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
at java.lang.Thread.run(Thread.java:595)
And in Derby, there was a dead lock.
Regards,
--
Rafał Rusin
www.mimuw.edu.pl/~rrusin
Re: Bpel execution in ODE
Posted by Rafal Rusin <ra...@gmail.com>.
2009/2/16 Rafal Rusin <ra...@gmail.com>:
> 2009/2/13 Matthieu Riou <ma...@gmail.com>:
>> On Fri, Feb 13, 2009 at 2:10 AM, Rafal Rusin <ra...@gmail.com> wrote:
>>
>>> Hello,
>>>
>>> could you explain me a bit bpel execution regarding BpelRuntimeContext?
>>> I saw a following happened:
>>>
>>> 09:59:25,185 | INFO | pool-4-thread-4 | BpelRuntimeContextImpl |
>>> .engine.BpelRuntimeContextImpl 160 | BpelRuntimeContextImpl created
>>> for instance 20598 24589427
>>> 09:59:25,269 | INFO | pool-4-thread-7 | BpelRuntimeContextImpl |
>>> .engine.BpelRuntimeContextImpl 160 | BpelRuntimeContextImpl created
>>> for instance 20598 1821816
>>> 09:59:25,628 | INFO | pool-4-thread-4 | BpelRuntimeContextImpl |
>>> .engine.BpelRuntimeContextImpl 843 | BpelRuntimeContextImpl setting
>>> execution state on instance 20598 24589427
>>> 09:59:25,781 | INFO | pool-4-thread-7 | BpelRuntimeContextImpl |
>>> .engine.BpelRuntimeContextImpl 843 | BpelRuntimeContextImpl setting
>>> execution state on instance 20598 1821816
>>>
>>
>> Is that on trunk or 1.x ? In any case I'm puzzled as to how this is
>> possible. There's a big lock on instances so that a given instance can't be
>> executed by two threads in parallel. Check BpelEngineImpl.onScheduledJob.
>> Given that an INVOKE_RESPONSE handling goes through this method, it's
>> surprising. Logging on the lock manager could provide more details.
>
> OK, thanks for clarifying, I'll check it and give more info.
>
This was on 1.x, in JBI.
Rafal
Re: Bpel execution in ODE
Posted by Matthieu Riou <ma...@gmail.com>.
On Fri, Feb 20, 2009 at 1:04 PM, Rafal Rusin <ra...@gmail.com> wrote:
> I added some logging and saw a following execution path:
>
> 21:19:03,218 | DEBUG | pool-4-thread-1 | SimpleScheduler |
> duler.simple.SimpleScheduler$4 378 | runJob
> hqejbhcnphr426la4ov8qn[0]: {type=INVOKE_INTERNAL, pid={...}Process,
> mexid=130132}
> 21:19:03,218 | DEBUG | pool-4-thread-1 | SimpleScheduler |
> heduler.simple.SimpleScheduler 200 | Beginning a new transaction
> 21:19:03,220 | DEBUG | pool-4-thread-1 | InstanceLockManager |
> pel.engine.InstanceLockManager 48 | Thread[pool-4-thread-1,5,main]:
> lock(iid=null, time=1MICROSECONDS)
> 21:19:03,220 | DEBUG | pool-4-thread-1 | InstanceLockManager |
> pel.engine.InstanceLockManager 52 | Thread[pool-4-thread-1,5,main]:
> lock(iid=null, time=1MICROSECONDS)--> no locking for null iid
> 21:19:04,482 | DEBUG | pool-4-thread-1 | BpelRuntimeContextImpl |
> .engine.BpelRuntimeContextImpl 161 | BpelRuntimeContextImpl created
> for instance 129983 8550354. INDEXED STATE=
> 21:19:04,497 | DEBUG | pool-4-thread-1 | BpelRuntimeContextImpl |
> .engine.BpelRuntimeContextImpl 844 | BpelRuntimeContextImpl execute
> started for instance 129983 8550354. INDEXED STATE=
> 21:19:05,344 | DEBUG | pool-4-thread-1 | BpelRuntimeContextImpl |
> .engine.BpelRuntimeContextImpl 851 | BpelRuntimeContextImpl setting
> execution state on instance 129983 8550354. INDEXED
> 21:19:05,359 | DEBUG | pool-4-thread-1 | SimpleScheduler |
> heduler.simple.SimpleScheduler 215 | Commiting...
> 21:19:05,385 | DEBUG | pool-4-thread-1 | InstanceLockManager |
> pel.engine.InstanceLockManager 90 | Thread[pool-4-thread-1,5,main]:
> unlock(iid=null)
>
> So, here INVOKE_INTERNAL job doesn't have iid, so there's no locking
> and bpelruntimecontext is created, executed and saved on instance
> 129983.
> There was also a concurrent execution in other thread on instance 129983:
> 21:19:05,424 | DEBUG | pool-4-thread-3 | BpelRuntimeContextImpl |
> .engine.BpelRuntimeContextImpl 851 | BpelRuntimeContextImpl setting
> execution state on instance 129983 13326304. INDEXED
>
> I saw that INVOKE_INTERNAL job is created only in
> MyRoleMessageExchangeImpl. And it doesn't set up iid. However it's a
> good behaviour, because there's no knowledge at this point to which
> instance it will go (correct me if I'm wrong).
That's correct.
>
> Later, INVOKE_INTERNAL job without iid is processed, and it gets
> following stacktrace to reach bpelruntimecontext evaluation:
> at
> org.apache.ode.bpel.engine.BpelRuntimeContextImpl.<init>(BpelRuntimeContextImpl.java:161)
> at
> org.apache.ode.bpel.engine.BpelProcess.createRuntimeContext(BpelProcess.java:759)
> at
> org.apache.ode.bpel.engine.PartnerLinkMyRoleImpl.invokeInstance(PartnerLinkMyRoleImpl.java:219)
> at
> org.apache.ode.bpel.engine.BpelProcess.invokeProcess(BpelProcess.java:219)
> at
> org.apache.ode.bpel.engine.BpelProcess.handleWorkEvent(BpelProcess.java:402)
> at
> org.apache.ode.bpel.engine.BpelEngineImpl.onScheduledJob(BpelEngineImpl.java:424)
> at
> org.apache.ode.bpel.engine.BpelServerImpl.onScheduledJob(BpelServerImpl.java:377)
> at
> org.apache.ode.scheduler.simple.SimpleScheduler$4$1.call(SimpleScheduler.java:390)
> at
> org.apache.ode.scheduler.simple.SimpleScheduler$4$1.call(SimpleScheduler.java:384)
> at
> org.apache.ode.scheduler.simple.SimpleScheduler.execTransaction(SimpleScheduler.java:208)
> at
> org.apache.ode.scheduler.simple.SimpleScheduler$4.call(SimpleScheduler.java:383)
> at
> org.apache.ode.scheduler.simple.SimpleScheduler$4.call(SimpleScheduler.java:376)
> at
> java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:269)
> at java.util.concurrent.FutureTask.run(FutureTask.java:123)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
> at java.lang.Thread.run(Thread.java:595)
>
> So, here in BpelProcess, it hits
> } else if (routing.messageRoute != null) {
> // Found a route, hitting it
> target.invokeInstance(mex, routing);
> routed = true;
> }
>
> So I think here should be a reschedule of this job with iid set up.
>
Rescheduling is a little extreme, we could probably just set that lock as
soon as we have the iid. Does that make sense given your scenario?
Matthieu
>
>
> 2009/2/16 Rafal Rusin <ra...@gmail.com>:
> > 2009/2/13 Matthieu Riou <ma...@gmail.com>:
> >> On Fri, Feb 13, 2009 at 2:10 AM, Rafal Rusin <ra...@gmail.com>
> wrote:
> >>
> >>> Hello,
> >>>
> >>> could you explain me a bit bpel execution regarding BpelRuntimeContext?
> >>> I saw a following happened:
> >>>
> >>> 09:59:25,185 | INFO | pool-4-thread-4 | BpelRuntimeContextImpl |
> >>> .engine.BpelRuntimeContextImpl 160 | BpelRuntimeContextImpl created
> >>> for instance 20598 24589427
> >>> 09:59:25,269 | INFO | pool-4-thread-7 | BpelRuntimeContextImpl |
> >>> .engine.BpelRuntimeContextImpl 160 | BpelRuntimeContextImpl created
> >>> for instance 20598 1821816
> >>> 09:59:25,628 | INFO | pool-4-thread-4 | BpelRuntimeContextImpl |
> >>> .engine.BpelRuntimeContextImpl 843 | BpelRuntimeContextImpl setting
> >>> execution state on instance 20598 24589427
> >>> 09:59:25,781 | INFO | pool-4-thread-7 | BpelRuntimeContextImpl |
> >>> .engine.BpelRuntimeContextImpl 843 | BpelRuntimeContextImpl setting
> >>> execution state on instance 20598 1821816
> >>>
> >>
> >> Is that on trunk or 1.x ? In any case I'm puzzled as to how this is
> >> possible. There's a big lock on instances so that a given instance can't
> be
> >> executed by two threads in parallel. Check
> BpelEngineImpl.onScheduledJob.
> >> Given that an INVOKE_RESPONSE handling goes through this method, it's
> >> surprising. Logging on the lock manager could provide more details.
> >
> > OK, thanks for clarifying, I'll check it and give more info.
> >
> >
> >> And the isolation level READ_COMMITTED is the correct one. With a
> "lower"
> >> isolation level, several assumptions coded in the engine would be broken
> as
> >> transactions start influencing each other (which gets tricky in a highly
> >> multi-threaded, shared environment).
> >>
> >> Thanks,
> >> Matthieu
> >>
> >>
> >>>
> >>> The numbers at the end (24589427 and 1821816) are hash ids for
> >>> BpelRuntimeContextImpl.
> >>> It happened after executing concurrently two jobs INVOKE_RESPONSE for
> >>> invoke1 and invoke3. A bpel process was like this:
> >>> <flow>
> >>> <sequence>
> >>> <invoke1/>
> >>> <invoke2/>
> >>> </sequence>
> >>> <sequence>
> >>> <invoke3/>
> >>> <invoke4/>
> >>> </sequence>
> >>> </flow>
> >>>
> >>> My question is whether such execution should be made synchronized in
> >>> ODE? Here setting execution state happened concurrently in
> >>> pool-4-thread-4 and pool-4-thread-7.
> >>> I used transaction isolation level READ_COMMITTED (a default one). In
> >>> this scenario, I had two jobs concurrently, successfully committed and
> >>> no critical section was used.
> >>> Both transactions saw committed data, so READ_COMMITTED was held.
> >>> It lead to storing incorrect execution state for process instance in
> >>> DB, since one INVOKE_RESPONSE job work was lost due to overwritten
> >>> data.
> >>> What transaction isolation level is correct for ODE? And what should I
> >>> do to correct this scenario? Do you have any clues?
> >>>
> >>> I had an error in Oracle:
> >>> 09:59:27,383 | ERROR | pool-4-thread-7 | JacobVPU |
> >>> b.vpu.JacobVPU$JacobThreadImpl 463 | Method "run" in class
> >>> "org.apache.ode.bpel.engine.BpelRuntimeContextImpl$6" threw an
> >>> unexpected excep
> >>> tion.
> >>> java.lang.IllegalArgumentException: No such channel; id=225
> >>> at
> >>>
> org.apache.ode.jacob.vpu.ExecutionQueueImpl.findChannelFrame(ExecutionQueueImpl.java:205)
> >>> at
> >>>
> org.apache.ode.jacob.vpu.ExecutionQueueImpl.consumeExport(ExecutionQueueImpl.java:232)
> >>> at
> >>>
> org.apache.ode.jacob.vpu.JacobVPU$JacobThreadImpl.importChannel(JacobVPU.java:369)
> >>> at
> >>> org.apache.ode.jacob.JacobObject.importChannel(JacobObject.java:47)
> >>> at
> >>>
> org.apache.ode.bpel.engine.BpelRuntimeContextImpl$6.run(BpelRuntimeContextImpl.java:967)
> >>> at sun.reflect.GeneratedMethodAccessor120.invoke(Unknown Source)
> >>> at
> >>>
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> >>> at java.lang.reflect.Method.invoke(Method.java:585)
> >>> at
> >>>
> org.apache.ode.jacob.vpu.JacobVPU$JacobThreadImpl.run(JacobVPU.java:451)
> >>> at org.apache.ode.jacob.vpu.JacobVPU.execute(JacobVPU.java:139)
> >>> at
> >>>
> org.apache.ode.bpel.engine.BpelRuntimeContextImpl.execute(BpelRuntimeContextImpl.java:839)
> >>> at
> >>>
> org.apache.ode.bpel.engine.BpelProcess.handleWorkEvent(BpelProcess.java:418)
> >>> at
> >>>
> org.apache.ode.bpel.engine.BpelEngineImpl.onScheduledJob(BpelEngineImpl.java:424)
> >>> at
> >>>
> org.apache.ode.bpel.engine.BpelServerImpl.onScheduledJob(BpelServerImpl.java:377)
> >>> at
> >>>
> org.apache.ode.scheduler.simple.SimpleScheduler$4$1.call(SimpleScheduler.java:386)
> >>> at
> >>>
> org.apache.ode.scheduler.simple.SimpleScheduler$4$1.call(SimpleScheduler.java:380)
> >>> at
> >>>
> org.apache.ode.scheduler.simple.SimpleScheduler.execTransaction(SimpleScheduler.java:208)
> >>> at
> >>>
> org.apache.ode.scheduler.simple.SimpleScheduler$4.call(SimpleScheduler.java:379)
> >>> at
> >>>
> org.apache.ode.scheduler.simple.SimpleScheduler$4.call(SimpleScheduler.java:376)
> >>> at
> >>> java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:269)
> >>> at java.util.concurrent.FutureTask.run(FutureTask.java:123)
> >>> at
> >>>
> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
> >>> at
> >>>
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
> >>> at java.lang.Thread.run(Thread.java:595)
> >>>
> >>>
> >>> And in Derby, there was a dead lock.
> >>>
> >>> Regards,
> >>> --
> >>> Rafał Rusin
> >>> www.mimuw.edu.pl/~rrusin <http://www.mimuw.edu.pl/%7Errusin> <
> http://www.mimuw.edu.pl/%7Errusin>
> >>>
> >>
> >
> >
> >
> > --
> > Rafał Rusin
> > www.mimuw.edu.pl/~rrusin <http://www.mimuw.edu.pl/%7Errusin>
> >
>
>
>
> --
> Rafał Rusin
> www.mimuw.edu.pl/~rrusin <http://www.mimuw.edu.pl/%7Errusin>
>
Re: Bpel execution in ODE
Posted by Rafal Rusin <ra...@gmail.com>.
I made a patch for it.
I had to modify slightly lockingmanager to be able to acquire a lock
twice for the same thread. A kind of a recurrent lock in case if it
was taken already i BpelEngineImpl.onScheduledJob.
Regards,
2009/2/20 Rafal Rusin <ra...@gmail.com>:
> I added some logging and saw a following execution path:
>
> 21:19:03,218 | DEBUG | pool-4-thread-1 | SimpleScheduler |
> duler.simple.SimpleScheduler$4 378 | runJob
> hqejbhcnphr426la4ov8qn[0]: {type=INVOKE_INTERNAL, pid={...}Process,
> mexid=130132}
> 21:19:03,218 | DEBUG | pool-4-thread-1 | SimpleScheduler |
> heduler.simple.SimpleScheduler 200 | Beginning a new transaction
> 21:19:03,220 | DEBUG | pool-4-thread-1 | InstanceLockManager |
> pel.engine.InstanceLockManager 48 | Thread[pool-4-thread-1,5,main]:
> lock(iid=null, time=1MICROSECONDS)
> 21:19:03,220 | DEBUG | pool-4-thread-1 | InstanceLockManager |
> pel.engine.InstanceLockManager 52 | Thread[pool-4-thread-1,5,main]:
> lock(iid=null, time=1MICROSECONDS)--> no locking for null iid
> 21:19:04,482 | DEBUG | pool-4-thread-1 | BpelRuntimeContextImpl |
> .engine.BpelRuntimeContextImpl 161 | BpelRuntimeContextImpl created
> for instance 129983 8550354. INDEXED STATE=
> 21:19:04,497 | DEBUG | pool-4-thread-1 | BpelRuntimeContextImpl |
> .engine.BpelRuntimeContextImpl 844 | BpelRuntimeContextImpl execute
> started for instance 129983 8550354. INDEXED STATE=
> 21:19:05,344 | DEBUG | pool-4-thread-1 | BpelRuntimeContextImpl |
> .engine.BpelRuntimeContextImpl 851 | BpelRuntimeContextImpl setting
> execution state on instance 129983 8550354. INDEXED
> 21:19:05,359 | DEBUG | pool-4-thread-1 | SimpleScheduler |
> heduler.simple.SimpleScheduler 215 | Commiting...
> 21:19:05,385 | DEBUG | pool-4-thread-1 | InstanceLockManager |
> pel.engine.InstanceLockManager 90 | Thread[pool-4-thread-1,5,main]:
> unlock(iid=null)
>
> So, here INVOKE_INTERNAL job doesn't have iid, so there's no locking
> and bpelruntimecontext is created, executed and saved on instance
> 129983.
> There was also a concurrent execution in other thread on instance 129983:
> 21:19:05,424 | DEBUG | pool-4-thread-3 | BpelRuntimeContextImpl |
> .engine.BpelRuntimeContextImpl 851 | BpelRuntimeContextImpl setting
> execution state on instance 129983 13326304. INDEXED
>
> I saw that INVOKE_INTERNAL job is created only in
> MyRoleMessageExchangeImpl. And it doesn't set up iid. However it's a
> good behaviour, because there's no knowledge at this point to which
> instance it will go (correct me if I'm wrong).
> Later, INVOKE_INTERNAL job without iid is processed, and it gets
> following stacktrace to reach bpelruntimecontext evaluation:
> at org.apache.ode.bpel.engine.BpelRuntimeContextImpl.<init>(BpelRuntimeContextImpl.java:161)
> at org.apache.ode.bpel.engine.BpelProcess.createRuntimeContext(BpelProcess.java:759)
> at org.apache.ode.bpel.engine.PartnerLinkMyRoleImpl.invokeInstance(PartnerLinkMyRoleImpl.java:219)
> at org.apache.ode.bpel.engine.BpelProcess.invokeProcess(BpelProcess.java:219)
> at org.apache.ode.bpel.engine.BpelProcess.handleWorkEvent(BpelProcess.java:402)
> at org.apache.ode.bpel.engine.BpelEngineImpl.onScheduledJob(BpelEngineImpl.java:424)
> at org.apache.ode.bpel.engine.BpelServerImpl.onScheduledJob(BpelServerImpl.java:377)
> at org.apache.ode.scheduler.simple.SimpleScheduler$4$1.call(SimpleScheduler.java:390)
> at org.apache.ode.scheduler.simple.SimpleScheduler$4$1.call(SimpleScheduler.java:384)
> at org.apache.ode.scheduler.simple.SimpleScheduler.execTransaction(SimpleScheduler.java:208)
> at org.apache.ode.scheduler.simple.SimpleScheduler$4.call(SimpleScheduler.java:383)
> at org.apache.ode.scheduler.simple.SimpleScheduler$4.call(SimpleScheduler.java:376)
> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:269)
> at java.util.concurrent.FutureTask.run(FutureTask.java:123)
> at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
> at java.lang.Thread.run(Thread.java:595)
>
> So, here in BpelProcess, it hits
> } else if (routing.messageRoute != null) {
> // Found a route, hitting it
> target.invokeInstance(mex, routing);
> routed = true;
> }
>
> So I think here should be a reschedule of this job with iid set up.
>
>
> 2009/2/16 Rafal Rusin <ra...@gmail.com>:
>> 2009/2/13 Matthieu Riou <ma...@gmail.com>:
>>> On Fri, Feb 13, 2009 at 2:10 AM, Rafal Rusin <ra...@gmail.com> wrote:
>>>
>>>> Hello,
>>>>
>>>> could you explain me a bit bpel execution regarding BpelRuntimeContext?
>>>> I saw a following happened:
>>>>
>>>> 09:59:25,185 | INFO | pool-4-thread-4 | BpelRuntimeContextImpl |
>>>> .engine.BpelRuntimeContextImpl 160 | BpelRuntimeContextImpl created
>>>> for instance 20598 24589427
>>>> 09:59:25,269 | INFO | pool-4-thread-7 | BpelRuntimeContextImpl |
>>>> .engine.BpelRuntimeContextImpl 160 | BpelRuntimeContextImpl created
>>>> for instance 20598 1821816
>>>> 09:59:25,628 | INFO | pool-4-thread-4 | BpelRuntimeContextImpl |
>>>> .engine.BpelRuntimeContextImpl 843 | BpelRuntimeContextImpl setting
>>>> execution state on instance 20598 24589427
>>>> 09:59:25,781 | INFO | pool-4-thread-7 | BpelRuntimeContextImpl |
>>>> .engine.BpelRuntimeContextImpl 843 | BpelRuntimeContextImpl setting
>>>> execution state on instance 20598 1821816
>>>>
>>>
>>> Is that on trunk or 1.x ? In any case I'm puzzled as to how this is
>>> possible. There's a big lock on instances so that a given instance can't be
>>> executed by two threads in parallel. Check BpelEngineImpl.onScheduledJob.
>>> Given that an INVOKE_RESPONSE handling goes through this method, it's
>>> surprising. Logging on the lock manager could provide more details.
>>
>> OK, thanks for clarifying, I'll check it and give more info.
>>
>>
>>> And the isolation level READ_COMMITTED is the correct one. With a "lower"
>>> isolation level, several assumptions coded in the engine would be broken as
>>> transactions start influencing each other (which gets tricky in a highly
>>> multi-threaded, shared environment).
>>>
>>> Thanks,
>>> Matthieu
>>>
>>>
>>>>
>>>> The numbers at the end (24589427 and 1821816) are hash ids for
>>>> BpelRuntimeContextImpl.
>>>> It happened after executing concurrently two jobs INVOKE_RESPONSE for
>>>> invoke1 and invoke3. A bpel process was like this:
>>>> <flow>
>>>> <sequence>
>>>> <invoke1/>
>>>> <invoke2/>
>>>> </sequence>
>>>> <sequence>
>>>> <invoke3/>
>>>> <invoke4/>
>>>> </sequence>
>>>> </flow>
>>>>
>>>> My question is whether such execution should be made synchronized in
>>>> ODE? Here setting execution state happened concurrently in
>>>> pool-4-thread-4 and pool-4-thread-7.
>>>> I used transaction isolation level READ_COMMITTED (a default one). In
>>>> this scenario, I had two jobs concurrently, successfully committed and
>>>> no critical section was used.
>>>> Both transactions saw committed data, so READ_COMMITTED was held.
>>>> It lead to storing incorrect execution state for process instance in
>>>> DB, since one INVOKE_RESPONSE job work was lost due to overwritten
>>>> data.
>>>> What transaction isolation level is correct for ODE? And what should I
>>>> do to correct this scenario? Do you have any clues?
>>>>
>>>> I had an error in Oracle:
>>>> 09:59:27,383 | ERROR | pool-4-thread-7 | JacobVPU |
>>>> b.vpu.JacobVPU$JacobThreadImpl 463 | Method "run" in class
>>>> "org.apache.ode.bpel.engine.BpelRuntimeContextImpl$6" threw an
>>>> unexpected excep
>>>> tion.
>>>> java.lang.IllegalArgumentException: No such channel; id=225
>>>> at
>>>> org.apache.ode.jacob.vpu.ExecutionQueueImpl.findChannelFrame(ExecutionQueueImpl.java:205)
>>>> at
>>>> org.apache.ode.jacob.vpu.ExecutionQueueImpl.consumeExport(ExecutionQueueImpl.java:232)
>>>> at
>>>> org.apache.ode.jacob.vpu.JacobVPU$JacobThreadImpl.importChannel(JacobVPU.java:369)
>>>> at
>>>> org.apache.ode.jacob.JacobObject.importChannel(JacobObject.java:47)
>>>> at
>>>> org.apache.ode.bpel.engine.BpelRuntimeContextImpl$6.run(BpelRuntimeContextImpl.java:967)
>>>> at sun.reflect.GeneratedMethodAccessor120.invoke(Unknown Source)
>>>> at
>>>> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
>>>> at java.lang.reflect.Method.invoke(Method.java:585)
>>>> at
>>>> org.apache.ode.jacob.vpu.JacobVPU$JacobThreadImpl.run(JacobVPU.java:451)
>>>> at org.apache.ode.jacob.vpu.JacobVPU.execute(JacobVPU.java:139)
>>>> at
>>>> org.apache.ode.bpel.engine.BpelRuntimeContextImpl.execute(BpelRuntimeContextImpl.java:839)
>>>> at
>>>> org.apache.ode.bpel.engine.BpelProcess.handleWorkEvent(BpelProcess.java:418)
>>>> at
>>>> org.apache.ode.bpel.engine.BpelEngineImpl.onScheduledJob(BpelEngineImpl.java:424)
>>>> at
>>>> org.apache.ode.bpel.engine.BpelServerImpl.onScheduledJob(BpelServerImpl.java:377)
>>>> at
>>>> org.apache.ode.scheduler.simple.SimpleScheduler$4$1.call(SimpleScheduler.java:386)
>>>> at
>>>> org.apache.ode.scheduler.simple.SimpleScheduler$4$1.call(SimpleScheduler.java:380)
>>>> at
>>>> org.apache.ode.scheduler.simple.SimpleScheduler.execTransaction(SimpleScheduler.java:208)
>>>> at
>>>> org.apache.ode.scheduler.simple.SimpleScheduler$4.call(SimpleScheduler.java:379)
>>>> at
>>>> org.apache.ode.scheduler.simple.SimpleScheduler$4.call(SimpleScheduler.java:376)
>>>> at
>>>> java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:269)
>>>> at java.util.concurrent.FutureTask.run(FutureTask.java:123)
>>>> at
>>>> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
>>>> at
>>>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
>>>> at java.lang.Thread.run(Thread.java:595)
>>>>
>>>>
>>>> And in Derby, there was a dead lock.
>>>>
>>>> Regards,
>>>> --
>>>> Rafał Rusin
>>>> www.mimuw.edu.pl/~rrusin <http://www.mimuw.edu.pl/%7Errusin>
>>>>
>>>
>>
>>
>>
>> --
>> Rafał Rusin
>> www.mimuw.edu.pl/~rrusin
>>
>
>
>
> --
> Rafał Rusin
> www.mimuw.edu.pl/~rrusin
>
--
Rafał Rusin
www.mimuw.edu.pl/~rrusin
Re: Bpel execution in ODE
Posted by Rafal Rusin <ra...@gmail.com>.
I added some logging and saw a following execution path:
21:19:03,218 | DEBUG | pool-4-thread-1 | SimpleScheduler |
duler.simple.SimpleScheduler$4 378 | runJob
hqejbhcnphr426la4ov8qn[0]: {type=INVOKE_INTERNAL, pid={...}Process,
mexid=130132}
21:19:03,218 | DEBUG | pool-4-thread-1 | SimpleScheduler |
heduler.simple.SimpleScheduler 200 | Beginning a new transaction
21:19:03,220 | DEBUG | pool-4-thread-1 | InstanceLockManager |
pel.engine.InstanceLockManager 48 | Thread[pool-4-thread-1,5,main]:
lock(iid=null, time=1MICROSECONDS)
21:19:03,220 | DEBUG | pool-4-thread-1 | InstanceLockManager |
pel.engine.InstanceLockManager 52 | Thread[pool-4-thread-1,5,main]:
lock(iid=null, time=1MICROSECONDS)--> no locking for null iid
21:19:04,482 | DEBUG | pool-4-thread-1 | BpelRuntimeContextImpl |
.engine.BpelRuntimeContextImpl 161 | BpelRuntimeContextImpl created
for instance 129983 8550354. INDEXED STATE=
21:19:04,497 | DEBUG | pool-4-thread-1 | BpelRuntimeContextImpl |
.engine.BpelRuntimeContextImpl 844 | BpelRuntimeContextImpl execute
started for instance 129983 8550354. INDEXED STATE=
21:19:05,344 | DEBUG | pool-4-thread-1 | BpelRuntimeContextImpl |
.engine.BpelRuntimeContextImpl 851 | BpelRuntimeContextImpl setting
execution state on instance 129983 8550354. INDEXED
21:19:05,359 | DEBUG | pool-4-thread-1 | SimpleScheduler |
heduler.simple.SimpleScheduler 215 | Commiting...
21:19:05,385 | DEBUG | pool-4-thread-1 | InstanceLockManager |
pel.engine.InstanceLockManager 90 | Thread[pool-4-thread-1,5,main]:
unlock(iid=null)
So, here INVOKE_INTERNAL job doesn't have iid, so there's no locking
and bpelruntimecontext is created, executed and saved on instance
129983.
There was also a concurrent execution in other thread on instance 129983:
21:19:05,424 | DEBUG | pool-4-thread-3 | BpelRuntimeContextImpl |
.engine.BpelRuntimeContextImpl 851 | BpelRuntimeContextImpl setting
execution state on instance 129983 13326304. INDEXED
I saw that INVOKE_INTERNAL job is created only in
MyRoleMessageExchangeImpl. And it doesn't set up iid. However it's a
good behaviour, because there's no knowledge at this point to which
instance it will go (correct me if I'm wrong).
Later, INVOKE_INTERNAL job without iid is processed, and it gets
following stacktrace to reach bpelruntimecontext evaluation:
at org.apache.ode.bpel.engine.BpelRuntimeContextImpl.<init>(BpelRuntimeContextImpl.java:161)
at org.apache.ode.bpel.engine.BpelProcess.createRuntimeContext(BpelProcess.java:759)
at org.apache.ode.bpel.engine.PartnerLinkMyRoleImpl.invokeInstance(PartnerLinkMyRoleImpl.java:219)
at org.apache.ode.bpel.engine.BpelProcess.invokeProcess(BpelProcess.java:219)
at org.apache.ode.bpel.engine.BpelProcess.handleWorkEvent(BpelProcess.java:402)
at org.apache.ode.bpel.engine.BpelEngineImpl.onScheduledJob(BpelEngineImpl.java:424)
at org.apache.ode.bpel.engine.BpelServerImpl.onScheduledJob(BpelServerImpl.java:377)
at org.apache.ode.scheduler.simple.SimpleScheduler$4$1.call(SimpleScheduler.java:390)
at org.apache.ode.scheduler.simple.SimpleScheduler$4$1.call(SimpleScheduler.java:384)
at org.apache.ode.scheduler.simple.SimpleScheduler.execTransaction(SimpleScheduler.java:208)
at org.apache.ode.scheduler.simple.SimpleScheduler$4.call(SimpleScheduler.java:383)
at org.apache.ode.scheduler.simple.SimpleScheduler$4.call(SimpleScheduler.java:376)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:269)
at java.util.concurrent.FutureTask.run(FutureTask.java:123)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
at java.lang.Thread.run(Thread.java:595)
So, here in BpelProcess, it hits
} else if (routing.messageRoute != null) {
// Found a route, hitting it
target.invokeInstance(mex, routing);
routed = true;
}
So I think here should be a reschedule of this job with iid set up.
2009/2/16 Rafal Rusin <ra...@gmail.com>:
> 2009/2/13 Matthieu Riou <ma...@gmail.com>:
>> On Fri, Feb 13, 2009 at 2:10 AM, Rafal Rusin <ra...@gmail.com> wrote:
>>
>>> Hello,
>>>
>>> could you explain me a bit bpel execution regarding BpelRuntimeContext?
>>> I saw a following happened:
>>>
>>> 09:59:25,185 | INFO | pool-4-thread-4 | BpelRuntimeContextImpl |
>>> .engine.BpelRuntimeContextImpl 160 | BpelRuntimeContextImpl created
>>> for instance 20598 24589427
>>> 09:59:25,269 | INFO | pool-4-thread-7 | BpelRuntimeContextImpl |
>>> .engine.BpelRuntimeContextImpl 160 | BpelRuntimeContextImpl created
>>> for instance 20598 1821816
>>> 09:59:25,628 | INFO | pool-4-thread-4 | BpelRuntimeContextImpl |
>>> .engine.BpelRuntimeContextImpl 843 | BpelRuntimeContextImpl setting
>>> execution state on instance 20598 24589427
>>> 09:59:25,781 | INFO | pool-4-thread-7 | BpelRuntimeContextImpl |
>>> .engine.BpelRuntimeContextImpl 843 | BpelRuntimeContextImpl setting
>>> execution state on instance 20598 1821816
>>>
>>
>> Is that on trunk or 1.x ? In any case I'm puzzled as to how this is
>> possible. There's a big lock on instances so that a given instance can't be
>> executed by two threads in parallel. Check BpelEngineImpl.onScheduledJob.
>> Given that an INVOKE_RESPONSE handling goes through this method, it's
>> surprising. Logging on the lock manager could provide more details.
>
> OK, thanks for clarifying, I'll check it and give more info.
>
>
>> And the isolation level READ_COMMITTED is the correct one. With a "lower"
>> isolation level, several assumptions coded in the engine would be broken as
>> transactions start influencing each other (which gets tricky in a highly
>> multi-threaded, shared environment).
>>
>> Thanks,
>> Matthieu
>>
>>
>>>
>>> The numbers at the end (24589427 and 1821816) are hash ids for
>>> BpelRuntimeContextImpl.
>>> It happened after executing concurrently two jobs INVOKE_RESPONSE for
>>> invoke1 and invoke3. A bpel process was like this:
>>> <flow>
>>> <sequence>
>>> <invoke1/>
>>> <invoke2/>
>>> </sequence>
>>> <sequence>
>>> <invoke3/>
>>> <invoke4/>
>>> </sequence>
>>> </flow>
>>>
>>> My question is whether such execution should be made synchronized in
>>> ODE? Here setting execution state happened concurrently in
>>> pool-4-thread-4 and pool-4-thread-7.
>>> I used transaction isolation level READ_COMMITTED (a default one). In
>>> this scenario, I had two jobs concurrently, successfully committed and
>>> no critical section was used.
>>> Both transactions saw committed data, so READ_COMMITTED was held.
>>> It lead to storing incorrect execution state for process instance in
>>> DB, since one INVOKE_RESPONSE job work was lost due to overwritten
>>> data.
>>> What transaction isolation level is correct for ODE? And what should I
>>> do to correct this scenario? Do you have any clues?
>>>
>>> I had an error in Oracle:
>>> 09:59:27,383 | ERROR | pool-4-thread-7 | JacobVPU |
>>> b.vpu.JacobVPU$JacobThreadImpl 463 | Method "run" in class
>>> "org.apache.ode.bpel.engine.BpelRuntimeContextImpl$6" threw an
>>> unexpected excep
>>> tion.
>>> java.lang.IllegalArgumentException: No such channel; id=225
>>> at
>>> org.apache.ode.jacob.vpu.ExecutionQueueImpl.findChannelFrame(ExecutionQueueImpl.java:205)
>>> at
>>> org.apache.ode.jacob.vpu.ExecutionQueueImpl.consumeExport(ExecutionQueueImpl.java:232)
>>> at
>>> org.apache.ode.jacob.vpu.JacobVPU$JacobThreadImpl.importChannel(JacobVPU.java:369)
>>> at
>>> org.apache.ode.jacob.JacobObject.importChannel(JacobObject.java:47)
>>> at
>>> org.apache.ode.bpel.engine.BpelRuntimeContextImpl$6.run(BpelRuntimeContextImpl.java:967)
>>> at sun.reflect.GeneratedMethodAccessor120.invoke(Unknown Source)
>>> at
>>> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
>>> at java.lang.reflect.Method.invoke(Method.java:585)
>>> at
>>> org.apache.ode.jacob.vpu.JacobVPU$JacobThreadImpl.run(JacobVPU.java:451)
>>> at org.apache.ode.jacob.vpu.JacobVPU.execute(JacobVPU.java:139)
>>> at
>>> org.apache.ode.bpel.engine.BpelRuntimeContextImpl.execute(BpelRuntimeContextImpl.java:839)
>>> at
>>> org.apache.ode.bpel.engine.BpelProcess.handleWorkEvent(BpelProcess.java:418)
>>> at
>>> org.apache.ode.bpel.engine.BpelEngineImpl.onScheduledJob(BpelEngineImpl.java:424)
>>> at
>>> org.apache.ode.bpel.engine.BpelServerImpl.onScheduledJob(BpelServerImpl.java:377)
>>> at
>>> org.apache.ode.scheduler.simple.SimpleScheduler$4$1.call(SimpleScheduler.java:386)
>>> at
>>> org.apache.ode.scheduler.simple.SimpleScheduler$4$1.call(SimpleScheduler.java:380)
>>> at
>>> org.apache.ode.scheduler.simple.SimpleScheduler.execTransaction(SimpleScheduler.java:208)
>>> at
>>> org.apache.ode.scheduler.simple.SimpleScheduler$4.call(SimpleScheduler.java:379)
>>> at
>>> org.apache.ode.scheduler.simple.SimpleScheduler$4.call(SimpleScheduler.java:376)
>>> at
>>> java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:269)
>>> at java.util.concurrent.FutureTask.run(FutureTask.java:123)
>>> at
>>> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
>>> at
>>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
>>> at java.lang.Thread.run(Thread.java:595)
>>>
>>>
>>> And in Derby, there was a dead lock.
>>>
>>> Regards,
>>> --
>>> Rafał Rusin
>>> www.mimuw.edu.pl/~rrusin <http://www.mimuw.edu.pl/%7Errusin>
>>>
>>
>
>
>
> --
> Rafał Rusin
> www.mimuw.edu.pl/~rrusin
>
--
Rafał Rusin
www.mimuw.edu.pl/~rrusin
Re: Bpel execution in ODE
Posted by Rafal Rusin <ra...@gmail.com>.
2009/2/13 Matthieu Riou <ma...@gmail.com>:
> On Fri, Feb 13, 2009 at 2:10 AM, Rafal Rusin <ra...@gmail.com> wrote:
>
>> Hello,
>>
>> could you explain me a bit bpel execution regarding BpelRuntimeContext?
>> I saw a following happened:
>>
>> 09:59:25,185 | INFO | pool-4-thread-4 | BpelRuntimeContextImpl |
>> .engine.BpelRuntimeContextImpl 160 | BpelRuntimeContextImpl created
>> for instance 20598 24589427
>> 09:59:25,269 | INFO | pool-4-thread-7 | BpelRuntimeContextImpl |
>> .engine.BpelRuntimeContextImpl 160 | BpelRuntimeContextImpl created
>> for instance 20598 1821816
>> 09:59:25,628 | INFO | pool-4-thread-4 | BpelRuntimeContextImpl |
>> .engine.BpelRuntimeContextImpl 843 | BpelRuntimeContextImpl setting
>> execution state on instance 20598 24589427
>> 09:59:25,781 | INFO | pool-4-thread-7 | BpelRuntimeContextImpl |
>> .engine.BpelRuntimeContextImpl 843 | BpelRuntimeContextImpl setting
>> execution state on instance 20598 1821816
>>
>
> Is that on trunk or 1.x ? In any case I'm puzzled as to how this is
> possible. There's a big lock on instances so that a given instance can't be
> executed by two threads in parallel. Check BpelEngineImpl.onScheduledJob.
> Given that an INVOKE_RESPONSE handling goes through this method, it's
> surprising. Logging on the lock manager could provide more details.
OK, thanks for clarifying, I'll check it and give more info.
> And the isolation level READ_COMMITTED is the correct one. With a "lower"
> isolation level, several assumptions coded in the engine would be broken as
> transactions start influencing each other (which gets tricky in a highly
> multi-threaded, shared environment).
>
> Thanks,
> Matthieu
>
>
>>
>> The numbers at the end (24589427 and 1821816) are hash ids for
>> BpelRuntimeContextImpl.
>> It happened after executing concurrently two jobs INVOKE_RESPONSE for
>> invoke1 and invoke3. A bpel process was like this:
>> <flow>
>> <sequence>
>> <invoke1/>
>> <invoke2/>
>> </sequence>
>> <sequence>
>> <invoke3/>
>> <invoke4/>
>> </sequence>
>> </flow>
>>
>> My question is whether such execution should be made synchronized in
>> ODE? Here setting execution state happened concurrently in
>> pool-4-thread-4 and pool-4-thread-7.
>> I used transaction isolation level READ_COMMITTED (a default one). In
>> this scenario, I had two jobs concurrently, successfully committed and
>> no critical section was used.
>> Both transactions saw committed data, so READ_COMMITTED was held.
>> It lead to storing incorrect execution state for process instance in
>> DB, since one INVOKE_RESPONSE job work was lost due to overwritten
>> data.
>> What transaction isolation level is correct for ODE? And what should I
>> do to correct this scenario? Do you have any clues?
>>
>> I had an error in Oracle:
>> 09:59:27,383 | ERROR | pool-4-thread-7 | JacobVPU |
>> b.vpu.JacobVPU$JacobThreadImpl 463 | Method "run" in class
>> "org.apache.ode.bpel.engine.BpelRuntimeContextImpl$6" threw an
>> unexpected excep
>> tion.
>> java.lang.IllegalArgumentException: No such channel; id=225
>> at
>> org.apache.ode.jacob.vpu.ExecutionQueueImpl.findChannelFrame(ExecutionQueueImpl.java:205)
>> at
>> org.apache.ode.jacob.vpu.ExecutionQueueImpl.consumeExport(ExecutionQueueImpl.java:232)
>> at
>> org.apache.ode.jacob.vpu.JacobVPU$JacobThreadImpl.importChannel(JacobVPU.java:369)
>> at
>> org.apache.ode.jacob.JacobObject.importChannel(JacobObject.java:47)
>> at
>> org.apache.ode.bpel.engine.BpelRuntimeContextImpl$6.run(BpelRuntimeContextImpl.java:967)
>> at sun.reflect.GeneratedMethodAccessor120.invoke(Unknown Source)
>> at
>> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
>> at java.lang.reflect.Method.invoke(Method.java:585)
>> at
>> org.apache.ode.jacob.vpu.JacobVPU$JacobThreadImpl.run(JacobVPU.java:451)
>> at org.apache.ode.jacob.vpu.JacobVPU.execute(JacobVPU.java:139)
>> at
>> org.apache.ode.bpel.engine.BpelRuntimeContextImpl.execute(BpelRuntimeContextImpl.java:839)
>> at
>> org.apache.ode.bpel.engine.BpelProcess.handleWorkEvent(BpelProcess.java:418)
>> at
>> org.apache.ode.bpel.engine.BpelEngineImpl.onScheduledJob(BpelEngineImpl.java:424)
>> at
>> org.apache.ode.bpel.engine.BpelServerImpl.onScheduledJob(BpelServerImpl.java:377)
>> at
>> org.apache.ode.scheduler.simple.SimpleScheduler$4$1.call(SimpleScheduler.java:386)
>> at
>> org.apache.ode.scheduler.simple.SimpleScheduler$4$1.call(SimpleScheduler.java:380)
>> at
>> org.apache.ode.scheduler.simple.SimpleScheduler.execTransaction(SimpleScheduler.java:208)
>> at
>> org.apache.ode.scheduler.simple.SimpleScheduler$4.call(SimpleScheduler.java:379)
>> at
>> org.apache.ode.scheduler.simple.SimpleScheduler$4.call(SimpleScheduler.java:376)
>> at
>> java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:269)
>> at java.util.concurrent.FutureTask.run(FutureTask.java:123)
>> at
>> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
>> at
>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
>> at java.lang.Thread.run(Thread.java:595)
>>
>>
>> And in Derby, there was a dead lock.
>>
>> Regards,
>> --
>> Rafał Rusin
>> www.mimuw.edu.pl/~rrusin <http://www.mimuw.edu.pl/%7Errusin>
>>
>
--
Rafał Rusin
www.mimuw.edu.pl/~rrusin
Re: Bpel execution in ODE
Posted by Matthieu Riou <ma...@gmail.com>.
On Fri, Feb 13, 2009 at 2:10 AM, Rafal Rusin <ra...@gmail.com> wrote:
> Hello,
>
> could you explain me a bit bpel execution regarding BpelRuntimeContext?
> I saw a following happened:
>
> 09:59:25,185 | INFO | pool-4-thread-4 | BpelRuntimeContextImpl |
> .engine.BpelRuntimeContextImpl 160 | BpelRuntimeContextImpl created
> for instance 20598 24589427
> 09:59:25,269 | INFO | pool-4-thread-7 | BpelRuntimeContextImpl |
> .engine.BpelRuntimeContextImpl 160 | BpelRuntimeContextImpl created
> for instance 20598 1821816
> 09:59:25,628 | INFO | pool-4-thread-4 | BpelRuntimeContextImpl |
> .engine.BpelRuntimeContextImpl 843 | BpelRuntimeContextImpl setting
> execution state on instance 20598 24589427
> 09:59:25,781 | INFO | pool-4-thread-7 | BpelRuntimeContextImpl |
> .engine.BpelRuntimeContextImpl 843 | BpelRuntimeContextImpl setting
> execution state on instance 20598 1821816
>
Is that on trunk or 1.x ? In any case I'm puzzled as to how this is
possible. There's a big lock on instances so that a given instance can't be
executed by two threads in parallel. Check BpelEngineImpl.onScheduledJob.
Given that an INVOKE_RESPONSE handling goes through this method, it's
surprising. Logging on the lock manager could provide more details.
And the isolation level READ_COMMITTED is the correct one. With a "lower"
isolation level, several assumptions coded in the engine would be broken as
transactions start influencing each other (which gets tricky in a highly
multi-threaded, shared environment).
Thanks,
Matthieu
>
> The numbers at the end (24589427 and 1821816) are hash ids for
> BpelRuntimeContextImpl.
> It happened after executing concurrently two jobs INVOKE_RESPONSE for
> invoke1 and invoke3. A bpel process was like this:
> <flow>
> <sequence>
> <invoke1/>
> <invoke2/>
> </sequence>
> <sequence>
> <invoke3/>
> <invoke4/>
> </sequence>
> </flow>
>
> My question is whether such execution should be made synchronized in
> ODE? Here setting execution state happened concurrently in
> pool-4-thread-4 and pool-4-thread-7.
> I used transaction isolation level READ_COMMITTED (a default one). In
> this scenario, I had two jobs concurrently, successfully committed and
> no critical section was used.
> Both transactions saw committed data, so READ_COMMITTED was held.
> It lead to storing incorrect execution state for process instance in
> DB, since one INVOKE_RESPONSE job work was lost due to overwritten
> data.
> What transaction isolation level is correct for ODE? And what should I
> do to correct this scenario? Do you have any clues?
>
> I had an error in Oracle:
> 09:59:27,383 | ERROR | pool-4-thread-7 | JacobVPU |
> b.vpu.JacobVPU$JacobThreadImpl 463 | Method "run" in class
> "org.apache.ode.bpel.engine.BpelRuntimeContextImpl$6" threw an
> unexpected excep
> tion.
> java.lang.IllegalArgumentException: No such channel; id=225
> at
> org.apache.ode.jacob.vpu.ExecutionQueueImpl.findChannelFrame(ExecutionQueueImpl.java:205)
> at
> org.apache.ode.jacob.vpu.ExecutionQueueImpl.consumeExport(ExecutionQueueImpl.java:232)
> at
> org.apache.ode.jacob.vpu.JacobVPU$JacobThreadImpl.importChannel(JacobVPU.java:369)
> at
> org.apache.ode.jacob.JacobObject.importChannel(JacobObject.java:47)
> at
> org.apache.ode.bpel.engine.BpelRuntimeContextImpl$6.run(BpelRuntimeContextImpl.java:967)
> at sun.reflect.GeneratedMethodAccessor120.invoke(Unknown Source)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> at java.lang.reflect.Method.invoke(Method.java:585)
> at
> org.apache.ode.jacob.vpu.JacobVPU$JacobThreadImpl.run(JacobVPU.java:451)
> at org.apache.ode.jacob.vpu.JacobVPU.execute(JacobVPU.java:139)
> at
> org.apache.ode.bpel.engine.BpelRuntimeContextImpl.execute(BpelRuntimeContextImpl.java:839)
> at
> org.apache.ode.bpel.engine.BpelProcess.handleWorkEvent(BpelProcess.java:418)
> at
> org.apache.ode.bpel.engine.BpelEngineImpl.onScheduledJob(BpelEngineImpl.java:424)
> at
> org.apache.ode.bpel.engine.BpelServerImpl.onScheduledJob(BpelServerImpl.java:377)
> at
> org.apache.ode.scheduler.simple.SimpleScheduler$4$1.call(SimpleScheduler.java:386)
> at
> org.apache.ode.scheduler.simple.SimpleScheduler$4$1.call(SimpleScheduler.java:380)
> at
> org.apache.ode.scheduler.simple.SimpleScheduler.execTransaction(SimpleScheduler.java:208)
> at
> org.apache.ode.scheduler.simple.SimpleScheduler$4.call(SimpleScheduler.java:379)
> at
> org.apache.ode.scheduler.simple.SimpleScheduler$4.call(SimpleScheduler.java:376)
> at
> java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:269)
> at java.util.concurrent.FutureTask.run(FutureTask.java:123)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
> at java.lang.Thread.run(Thread.java:595)
>
>
> And in Derby, there was a dead lock.
>
> Regards,
> --
> Rafał Rusin
> www.mimuw.edu.pl/~rrusin <http://www.mimuw.edu.pl/%7Errusin>
>