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 <rafal.ru...@gmail.com>:
> 2009/2/13 Matthieu Riou <matthieu.r...@gmail.com>:
>> On Fri, Feb 13, 2009 at 2:10 AM, Rafal Rusin <rafal.ru...@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
