OpenJPA
  1. OpenJPA
  2. OPENJPA-366

InternalException thrown in BrokerImpl.endOperation

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 1.0.0
    • Fix Version/s: 1.0.2, 1.1.0
    • Component/s: kernel
    • Labels:
      None
    • Environment:
      All platforms

      Description

      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.

        Activity

        Hide
        Patrick Linskey added a comment -

        Marking as resolved, as I do not understand what additional issues remain for this issue. If there are any, please expand on them.

        Show
        Patrick Linskey added a comment - Marking as resolved, as I do not understand what additional issues remain for this issue. If there are any, please expand on them.
        Hide
        Albert Lee added a comment -

        There are still other issues need to be resolved. Defer to next release.

        Show
        Albert Lee added a comment - There are still other issues need to be resolved. Defer to next release.
        Hide
        Albert Lee added a comment -

        Add a new message text for InternalException().

        This patch is tested against both 1.1.0 trunk and 1.0.x branch.

        Show
        Albert Lee added a comment - Add a new message text for InternalException(). This patch is tested against both 1.1.0 trunk and 1.0.x branch.
        Hide
        Albert Lee added a comment -

        After a lengthy investigation to this problem, it turns out there are a few problems in this application/ejb usage scenario:

        1) Problem #1 - Application

        The appl uses stateless session bean (SLSB) and JSE style JPA access, therefore the persistence context is extended. In each bean method call, the appl uses the persistence context to access JPA functions but did not clear the context upon method return. This leaves managed entities in the context propagates to the next client/thread who just happens to use the same session bean instance allocated by the EJB container from its slsb pool.

        2) Problem #2 - EJBContainer

        Typically, an application server generates EJB deployment code (GenCode), either statically or at runtime, for an application(.ear) in order to implement EJB Container semantics in the application server. This generated code sits between the ORB/COBRA and the EJB Container. It redirects calls from the client to the EJB Container. Here is a brief sequence of events during this call path:

        a) ORB directs the client method call to the GenCode
        b) GenCode invokes the EJB Container to performs EJB semantics. E.g. start a transaction, CMP/BMP processing. One of the function in this step is to allocate an user-defined bean instance.
        c) GenCode invokes the user define bean method.
        d) GenCode invokes the EJB Container to performs EJB clean up semantics. E.g. commit/rollback transaction, exception handling etc. When this step is finished, the user-defined bean instance is returned back to the bean pool maintained by the EJB Container.
        e) GenCode returns the bean method returned object to ORB
        f) ORB serializes the returned object to an output stream which will be streamed back to the client.

        In the reported problem scenario, the method being calls return a Vector<OrderEntity>. Everything functions normally until step d) to f). After step d), the SLSB instance is returned back to the EJB pool and is available for use by the next client while the current thread is still processing step f). If the returned object contains a managed entity, the serialization process will eventually invocate its owning EntityManager/broker. Since step d) to f) are not synchronized, in a high load environment, EJB Container may allocate the same SLSB instance to a client in another thread. Now there are 2 threads using managed entities in the same persistence context. Since EntityManager is not thread-safe (per JPA spec), the reported exception is observed.

        3) Problem #3 - OpenJPA

        OpenJPA is doing whatever it can to detect the multiple access to the same thread/broker. However when this happens, only a InternalException() with a "null" message is thrown and this percolates back to the user with an PersistenceException with no meaningful message to isolate the problem. This is a critical usability issues.

        Solutions for this Jira report:

        1) Application must clear all Persistence Context upon return for each bean method call. There are explicit example in the JPA spec demonstrates these usage. (JPA spec 5.7.1.1 and 5.7.1.2)
        2) Proposed to enhance the error message when this error condition occurs to explain the cause of the problem and suggested the following possible solutions:
        a) set "openjpa.Multithreaded=true", if the application requires and intent to support this particular usage. Application must fully responsible for the behavior of this undefined semantics.
        b) request application to make sure entity manager defines as attribute(s) in SLSB must be cleared upon each bean method invocation.

        I'll use this Jira report to addess solution 2).

        Albert Lee.

        Show
        Albert Lee added a comment - After a lengthy investigation to this problem, it turns out there are a few problems in this application/ejb usage scenario: 1) Problem #1 - Application The appl uses stateless session bean (SLSB) and JSE style JPA access, therefore the persistence context is extended. In each bean method call, the appl uses the persistence context to access JPA functions but did not clear the context upon method return. This leaves managed entities in the context propagates to the next client/thread who just happens to use the same session bean instance allocated by the EJB container from its slsb pool. 2) Problem #2 - EJBContainer Typically, an application server generates EJB deployment code (GenCode), either statically or at runtime, for an application(.ear) in order to implement EJB Container semantics in the application server. This generated code sits between the ORB/COBRA and the EJB Container. It redirects calls from the client to the EJB Container. Here is a brief sequence of events during this call path: a) ORB directs the client method call to the GenCode b) GenCode invokes the EJB Container to performs EJB semantics. E.g. start a transaction, CMP/BMP processing. One of the function in this step is to allocate an user-defined bean instance. c) GenCode invokes the user define bean method. d) GenCode invokes the EJB Container to performs EJB clean up semantics. E.g. commit/rollback transaction, exception handling etc. When this step is finished, the user-defined bean instance is returned back to the bean pool maintained by the EJB Container. e) GenCode returns the bean method returned object to ORB f) ORB serializes the returned object to an output stream which will be streamed back to the client. In the reported problem scenario, the method being calls return a Vector<OrderEntity>. Everything functions normally until step d) to f). After step d), the SLSB instance is returned back to the EJB pool and is available for use by the next client while the current thread is still processing step f). If the returned object contains a managed entity, the serialization process will eventually invocate its owning EntityManager/broker. Since step d) to f) are not synchronized, in a high load environment, EJB Container may allocate the same SLSB instance to a client in another thread. Now there are 2 threads using managed entities in the same persistence context. Since EntityManager is not thread-safe (per JPA spec), the reported exception is observed. 3) Problem #3 - OpenJPA OpenJPA is doing whatever it can to detect the multiple access to the same thread/broker. However when this happens, only a InternalException() with a "null" message is thrown and this percolates back to the user with an PersistenceException with no meaningful message to isolate the problem. This is a critical usability issues. Solutions for this Jira report: 1) Application must clear all Persistence Context upon return for each bean method call. There are explicit example in the JPA spec demonstrates these usage. (JPA spec 5.7.1.1 and 5.7.1.2) 2) Proposed to enhance the error message when this error condition occurs to explain the cause of the problem and suggested the following possible solutions: a) set "openjpa.Multithreaded=true", if the application requires and intent to support this particular usage. Application must fully responsible for the behavior of this undefined semantics. b) request application to make sure entity manager defines as attribute(s) in SLSB must be cleared upon each bean method invocation. I'll use this Jira report to addess solution 2). Albert Lee.
        Hide
        Albert Lee added a comment -

        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.

        Show
        Albert Lee added a comment - 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.
        Hide
        Albert Lee added a comment -

        The hypothesis that the lock() is missing in endOperation() is incorrect. It was not there by design. Can some administrator remove the attached patch in this report.

        We'll continue to investigate this issue and appreciate if anyone has any clues or ideas on where the problem is or how to attach the problem.

        Thanks

        Show
        Albert Lee added a comment - The hypothesis that the lock() is missing in endOperation() is incorrect. It was not there by design. Can some administrator remove the attached patch in this report. We'll continue to investigate this issue and appreciate if anyone has any clues or ideas on where the problem is or how to attach the problem. Thanks
        Hide
        Albert Lee added a comment -

        Add lock() in BrokerImpl.endOperation().

        Stress test ran for 24 hours and still have not observed the reported problem. Continue to test with increasing workloads and clients for a 48 hours run.

        Show
        Albert Lee added a comment - Add lock() in BrokerImpl.endOperation(). Stress test ran for 24 hours and still have not observed the reported problem. Continue to test with increasing workloads and clients for a 48 hours run.

          People

          • Assignee:
            Albert Lee
            Reporter:
            Albert Lee
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development