[
https://issues.apache.org/jira/browse/OPENJPA-366?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#action_12529474
]
Albert Lee commented on OPENJPA-366:
------------------------------------
An update to this issue:
1) The test scenario is a simple Sale - 1toM - Order processing
2) A EJB 2.1 stateless session bean StationBean is used to drive the Sale. It
uses JSE style access to JPA functions.
public void ejbCreate() throws javax.ejb.CreateException {
ut = (UserTransaction) getSessionContext().getUserTransaction();
saleFactory = Persistence.createEntityManagerFactory("StationSale");
saleManager = saleFactory.createEntityManager();
}
3) This bean has a getListOrder() method returns Vector<Order>.
public Vector getListOrders(int saleid) throws Exception {
String methodName = "getListOrders";
Vector v = new Vector();
try {
ut.begin();
saleManager.joinTransaction();
Sale sl = saleManager.find(Sale.class, saleid);
if (sl != null) {
saleManager.refresh(sl);
Collection c = sl.getOrders();
if (c != null) {
Iterator ids = c.iterator();
while (ids.hasNext()) {
Order o = (Order) ids.next();
if (o != null) {
v.add(o);
}
}
}
ut.commit();
} else {
throw new Exception("getListOrders, Unable to find Sale ,
returned null for saleid = " + saleid);
}
} catch (Exception e1) {
ut.rollback();
throw e1;
}
return v;
}
4) A test driver accesses the StationBean in multiple clients under heavy load.
As a result, the observed exception as report in the original comment occurs.
5) Re-run the test with "openjpa.Multithreaded=true" property resolved the
problem. It is due to the fact that this property installed a ReentrantLock in
the BrokerImpl to synchronize multiple invocations to the same BrokerImpl.
6) After further analysis of the problem, the following stacks revealed the
sources of the multiple invocations to the same broker:
>>> Thread 1 : Thread[ORB.thread.pool : 3,5,main]
java.lang.Exception: curThread=Thread[ORB.thread.pool :
3,5,main]:lock={noLock}:threadCnt=2:_operationCount=0
at org.apache.openjpa.kernel.BrokerImpl.beginOperation(BrokerImpl.java:1723)
at org.apache.openjpa.kernel.BrokerImpl.newObjectId(BrokerImpl.java:1060)
at
org.apache.openjpa.kernel.DelegatingBroker.newObjectId(DelegatingBroker.java:252)
at
org.apache.openjpa.persistence.EntityManagerImpl.find(EntityManagerImpl.java:347)
at
com.ibm.svt.shoppingcartModule.stationstore.StationStoreSessionBean.getListOrders(StationStoreSessionBean.java:603)
at
com.ibm.svt.shoppingcartModule.stationstore.EJSRemoteStatelessStationStoreSession_5a5c538c.getListOrders(Unknown
Source)
at
com.ibm.svt.shoppingcartModule.stationstore._EJSRemoteStatelessStationStoreSession_5a5c538c_Tie.getListOrders(_EJSRemoteStatelessStationStoreSession_5a5c538c_Tie.java:244)
at
com.ibm.svt.shoppingcartModule.stationstore._EJSRemoteStatelessStationStoreSession_5a5c538c_Tie._invoke(_EJSRemoteStatelessStationStoreSession_5a5c538c_Tie.java:100)
at
com.ibm.CORBA.iiop.ServerDelegate.dispatchInvokeHandler(ServerDelegate.java:613)
at com.ibm.CORBA.iiop.ServerDelegate.dispatch(ServerDelegate.java:466)
at com.ibm.rmi.iiop.ORB.process(ORB.java:503)
at com.ibm.CORBA.iiop.ORB.process(ORB.java:1553)
at com.ibm.rmi.iiop.Connection.respondTo(Connection.java:2680)
at com.ibm.rmi.iiop.Connection.doWork(Connection.java:2554)
at com.ibm.rmi.iiop.WorkUnitImpl.doWork(WorkUnitImpl.java:62)
at com.ibm.ejs.oa.pool.PooledThread.run(ThreadPool.java:118)
at com.ibm.ws.util.ThreadPool$Worker.run(ThreadPool.java:1469)
>>> Thread 2 : Thread[ORB.thread.pool : 2,5,main]
java.lang.Exception: curThread=Thread[ORB.thread.pool :
2,5,main]:lock={noLock}:threadCnt=1:_operationCount=0
at org.apache.openjpa.kernel.BrokerImpl.beginOperation(BrokerImpl.java:1723)
at org.apache.openjpa.kernel.BrokerImpl.isActive(BrokerImpl.java:1683)
at org.apache.openjpa.kernel.StateManagerImpl.load(StateManagerImpl.java:352)
at org.apache.openjpa.kernel.DetachManager.preDetach(DetachManager.java:156)
at
org.apache.openjpa.kernel.DetachManager.preSerialize(DetachManager.java:91)
at
org.apache.openjpa.kernel.StateManagerImpl.serializing(StateManagerImpl.java:1310)
at
com.ibm.svt.shoppingcartModule.storeEntities.Order.pcSerializing(Order.java)
at com.ibm.svt.shoppingcartModule.storeEntities.Order.writeObject(Order.java)
at sun.reflect.GeneratedMethodAccessor57.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:615)
at
com.ibm.rmi.io.IIOPOutputStream.invokeObjectWriter(IIOPOutputStream.java:966)
at com.ibm.rmi.io.IIOPOutputStream.outputObject(IIOPOutputStream.java:1002)
at
com.ibm.rmi.io.IIOPOutputStream.writeSerializable(IIOPOutputStream.java:1050)
at
com.ibm.rmi.io.IIOPOutputStream.simpleWriteObjectInternal(IIOPOutputStream.java:427)
at
com.ibm.rmi.io.IIOPOutputStream.simpleWriteObjectLoop(IIOPOutputStream.java:455)
at
com.ibm.rmi.io.IIOPOutputStream.defaultWriteObjectDelegate(IIOPOutputStream.java:566)
at
com.ibm.rmi.io.OutputStreamHook.defaultWriteObject(OutputStreamHook.java:132)
at java.util.Vector.writeObject(Vector.java:869)
at sun.reflect.GeneratedMethodAccessor10.invoke(Unknown Source)
at java.util.Vector.writeObject(Vector.java:869)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at sun.reflect.GeneratedMethodAccessor10.invoke(Unknown Source)
at java.lang.reflect.Method.invoke(Method.java:615)
at
com.ibm.rmi.io.IIOPOutputStream.invokeObjectWriter(IIOPOutputStream.java:966)
at com.ibm.rmi.io.IIOPOutputStream.outputObject(IIOPOutputStream.java:1002)
at
com.ibm.rmi.io.IIOPOutputStream.writeSerializable(IIOPOutputStream.java:1050)
at
com.ibm.rmi.io.IIOPOutputStream.simpleWriteObjectInternal(IIOPOutputStream.java:427)
at
com.ibm.rmi.io.IIOPOutputStream.simpleWriteObjectLoop(IIOPOutputStream.java:455)
at
com.ibm.rmi.io.IIOPOutputStream.simpleWriteObject(IIOPOutputStream.java:512)
at com.ibm.rmi.io.ValueHandlerImpl.writeValue(ValueHandlerImpl.java:159)
at com.ibm.rmi.iiop.CDROutputStream.write_value(CDROutputStream.java:1477)
at com.ibm.rmi.iiop.CDROutputStream.write_value(CDROutputStream.java:1497)
at com.ibm.rmi.iiop.CDROutputStream.write_value(CDROutputStream.java:1459)
at
com.ibm.svt.shoppingcartModule.stationstore._EJSRemoteStatelessStationStoreSession_5a5c538c_Tie.getListOrders(_EJSRemoteStatelessStationStoreSession_5a5c538c_Tie.java:256)
at
com.ibm.svt.shoppingcartModule.stationstore._EJSRemoteStatelessStationStoreSession_5a5c538c_Tie._invoke(_EJSRemoteStatelessStationStoreSession_5a5c538c_Tie.java:100)
at
com.ibm.CORBA.iiop.ServerDelegate.dispatchInvokeHandler(ServerDelegate.java:613)
at com.ibm.CORBA.iiop.ServerDelegate.dispatch(ServerDelegate.java:466)
at com.ibm.rmi.iiop.ORB.process(ORB.java:503)
at com.ibm.CORBA.iiop.ORB.process(ORB.java:1553)
at com.ibm.rmi.iiop.Connection.respondTo(Connection.java:2680)
at com.ibm.rmi.iiop.Connection.doWork(Connection.java:2554)
at com.ibm.rmi.iiop.WorkUnitImpl.doWork(WorkUnitImpl.java:62)
at com.ibm.ejs.oa.pool.PooledThread.run(ThreadPool.java:118)
at com.ibm.ws.util.ThreadPool$Worker.run(ThreadPool.java:1469)
7) Thread #1 is doing the normal em.find processing and hits the
BrokerImpl.beginOperation().
8) Thread #2 has completed the em.find processing and the Vector<Order> is
collected properly in the getListOrder() method. ORB/CORBA is trying to
serialize the return Vector<Order> back to the remote client.
9) During this processing, it is getting back to openjpa to serialize an Order
in the returning collection:
at
org.apache.openjpa.kernel.StateManagerImpl.serializing(StateManagerImpl.java:1310)
at
com.ibm.svt.shoppingcartModule.storeEntities.Order.pcSerializing(Order.java)
at com.ibm.svt.shoppingcartModule.storeEntities.Order.writeObject(Order.java)
at sun.reflect.GeneratedMethodAccessor57.invoke(Unknown Source)
10) The EJB container guarantees a different StationBean instance is invoked
from getListOrders() method call which initiated from different
threads/clients, and since the em in each StationBean instance is obtained
independently from Persistence class, we can concluded the em.find() in each
bean invocation must use a different broker for the em.find() call.
11) Therefore we suspect somehow a incorrect broker (same broker used by Thread
#1) is used during the pcSerializing invocation in Thread #2.
12) Another supporting fact for the hypothesis is we have observed scenario
where there are up to 6 threads accessing the same BrokerImpl. Out of these
call stacks, there is always only one thread exhibits the same stack pattern as
in Thread #1 and the other threads have the Thread #2 call stack pattern.
Questions:
1) What is(are) the conditions (e.g. openjpa features/property) that trigger
the Order.pcSerializing() processing? I wrote a simplier test that mimic the
test case and was unable to drive the Order.pcSerializing() method call.
2) How is the Order.pcSerilizing() determine which BrokerImpl to use to perform
the serialization?
3) Any suggestings or insight into how to identify the culprit of this problem?
Any help on this matter is greatly appreciated.
Albert Lee.
> InternalException thrown in BrokerImpl.endOperation
> ---------------------------------------------------
>
> Key: OPENJPA-366
> URL: https://issues.apache.org/jira/browse/OPENJPA-366
> Project: OpenJPA
> Issue Type: Bug
> Components: kernel
> Affects Versions: 1.0.0
> Environment: All platforms
> Reporter: Albert Lee
> Assignee: Albert Lee
> Fix For: 1.0.1, 1.1.0
>
>
> Under heavy load during stress test, the following exception is observed:
> <openjpa-1.0.0-SNAPSHOT-r420667:570288M fatal general error>
> org.apache.openjpa.persistence.PersistenceException: null
> at
> org.apache.openjpa.kernel.BrokerImpl.endOperation(BrokerImpl.java:1728)
> at org.apache.openjpa.kernel.BrokerImpl.isActive(BrokerImpl.java:1676)
> at
> org.apache.openjpa.kernel.DelegatingBroker.isActive(DelegatingBroker.java:420)
> at
> org.apache.openjpa.persistence.EntityManagerImpl.isActive(EntityManagerImpl.java:502)
> at
> org.apache.openjpa.persistence.PersistenceExceptions$2.translate(PersistenceExceptions.java:66)
> at
> org.apache.openjpa.kernel.DelegatingBroker.translate(DelegatingBroker.java:110)
> at
> org.apache.openjpa.kernel.DelegatingBroker.newObjectId(DelegatingBroker.java:262)
> at
> org.apache.openjpa.persistence.EntityManagerImpl.find(EntityManagerImpl.java:347)
> at
> com.ibm.svt.shoppingcartModule.stationstore.StationStoreSessionBean.getListOrders(StationStoreSessionBean.java:603)
> at
> com.ibm.svt.shoppingcartModule.stationstore.EJSRemoteStatelessStationStoreSession_5a5c538c.getListOrders(Unknown
> Source)
> at
> com.ibm.svt.shoppingcartModule.stationstore._EJSRemoteStatelessStationStoreSession_5a5c538c_Tie.getListOrders(_EJSRemoteStatelessStationStoreSession_5a5c538c_Tie.java:244)
> at
> com.ibm.svt.shoppingcartModule.stationstore._EJSRemoteStatelessStationStoreSession_5a5c538c_Tie._invoke(_EJSRemoteStatelessStationStoreSession_5a5c538c_Tie.java:100)
> at
> com.ibm.CORBA.iiop.ServerDelegate.dispatchInvokeHandler(ServerDelegate.java:613)
> at com.ibm.CORBA.iiop.ServerDelegate.dispatch(ServerDelegate.java:466)
> at com.ibm.rmi.iiop.ORB.process(ORB.java:503)
> at com.ibm.CORBA.iiop.ORB.process(ORB.java:1553)
> at com.ibm.rmi.iiop.Connection.respondTo(Connection.java:2680)
> at com.ibm.rmi.iiop.Connection.doWork(Connection.java:2554)
> at com.ibm.rmi.iiop.WorkUnitImpl.doWork(WorkUnitImpl.java:62)
> at com.ibm.ejs.oa.pool.PooledThread.run(ThreadPool.java:118)
> at com.ibm.ws.util.ThreadPool$Worker.run(ThreadPool.java:1469)
> [8/31/07 22:45:26:265 EDT] 000000c1 SystemOut O MDD Translating
> exception: <openjpa-0.0.0-r420667:570288 fatal internal error>
> org.apache.openjpa.util.InternalException: null
> [8/31/07 22:45:26:265 EDT] 000000c1 SystemErr R
> <openjpa-0.0.0-r420667:570288 fatal internal error>
> org.apache.openjpa.util.InternalException: null
> [8/31/07 22:45:26:265 EDT] 000000c1 SystemErr R at
> org.apache.openjpa.kernel.BrokerImpl.endOperation(BrokerImpl.java:1728)
> After some investigation, it was determined that the internal exception is
> caused by
> if (_operationCount < 1)
> throw new InternalException();
> in BrokerImpl.endOperation();
> We believe the cause of the problem is a lock() method call is missing in the
> endOperation()
> public boolean endOperation() {
> lock(); <<<<< This is the missing lock() call since
> BrokerImpl.java was created
> try {
> if (_operationCount == 1 && (_autoDetach & DETACH_NONTXREAD) != 0
> && (_flags & FLAG_ACTIVE) == 0) {
> detachAllInternal(null);
> }
> if (_operationCount < 1)
> throw new InternalException();
> return _operationCount == 1;
> } catch (OpenJPAException ke) {
> throw ke;
> } catch (RuntimeException re) {
> throw new GeneralException(re);
> } finally {
> _operationCount--;
> if (_operationCount == 0)
> _operating.clear();
> unlock();
> }
> }
> Once we have done more tests and verify the fix, I'll submit a patch for this
> problem.
> If anyone doesn't think this is the solution. please response.
> Albert Lee.
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
