Revision as of 10:16, 21 January 2009

Bug Analysis Document: 259993: Deadlock on em.find() on WebSphere 7.0.0.1

Bugzilla Bug 259993

Document History

Date	Author	Version Description & Notes
20080115	Michael O'Brien	1.0 Initial reproduction use cases

Overview

This bug describes the behavior and fix for an isssue where an em.find() on WebSphere 7.0.0.1 hangs indefinitly when attempting to acquire lock on the concurrencyManager on a cacheKey.

We have two (2) deadlock issues here in package org.eclipse.persistence.testing.tests.jpa.relationship.

RelationshipModelJUnitTestSuite.testModifyItem()
VirtualAttributeTestSuite.testInsertVirtualAttribute()

Exceptions

There is no exception until the tests are stopped or the server is restarted. We then get a deadlock timeout exception. If this initial deadlock is avoided in code we experience a secondary deadlock in ConcurrencyManager.

Timeout during UnitOfWorkIdentityMapAccessor.getAndCloneCacheKeyFromParent()

[1/15/09 17:48:15:936 EST] 0000000e ThreadMonitor W   WSVR0605W: Thread "ORB.thread.pool : 1" (00000022) has been active for 670586 milliseconds and may be hung.  There is/are 2 thread(s) in total in the server that may be hung.
	at java.lang.Object.wait(Native Method)
	at java.lang.Object.wait(Object.java:196)
	at org.eclipse.persistence.internal.sessions.UnitOfWorkIdentityMapAccessor.getAndCloneCacheKeyFromParent(UnitOfWorkIdentityMapAccessor.java:146)

After adding code to break out of the wait() loop. We probably get this serialization error because even though both our test client (JUNit) and the EJB 3.0 jar model on the server reside on the same machine - they live in different JVM processes.

    [junit]     org.omg.CORBA.MARSHAL: Unable to read value from underlying
bridge : Mismatched serialization UIDs : Source (RepId
RMI:junit.framework.AssertionFailedError:2E921E9DEB124A7F:0000000000000001) 
= 0000000000000001 whereas Target (RepId
RMI:junit.framework.AssertionFailedError:048A3675A6FD5463:A02206A4C2A2FD62)
= A02206A4C2A2FD62  vmcid: IBM  minor code: 896  completed: No)

Timeout during ConcurrencyManager.releaseDeferredLock()

1/19/09 16:17:33:719 EST] 00000019 TimeoutManage I   WTRN0006W: Transaction
0000011EF0BF93D7000000010000000F3FC544039A0DB96F61B909BB432079E1295E672A0000011EF0BF93D7000000010000000F3FC544039A0DB96F61B909BB432079E1295E672A00000001
has timed out after 120 seconds.
[1/19/09 16:17:33:719 EST] 00000019 TimeoutManage I   WTRN0124I: When the timeout occurred the thread with which the transaction is, or was most recently, associated was Thread[ORB.thread.pool : 0,5,main]. The stack trace of this thread when the timeout occurred was: 
	java.lang.Thread.sleep(Native Method)
	java.lang.Thread.sleep(Thread.java:850)
	org.eclipse.persistence.internal.helper.ConcurrencyManager.releaseDeferredLock(ConcurrencyManager.java:429)

Logs

These are the FINEST logs up until the first deadlock.

[1/21/09 9:10:17:763 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:17.763--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--sequencing connected, state is Preallocation_Transaction_NoAccessor_State
[1/21/09 9:10:17:763 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:17.763--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--sequence VIRTUAL_ATTRIBUTE_SEQ: preallocation size 50
[1/21/09 9:10:17:763 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:17.763--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--sequence ONE_TO_ONE_VIRTUAL_ATTRIBUTE_SEQ: preallocation size 50
[1/21/09 9:10:17:763 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:17.763--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--sequence SALESPERSON_SEQ: preallocation size 50
[1/21/09 9:10:17:763 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:17.763--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--sequence ORDER_SEQ: preallocation size 50
[1/21/09 9:10:17:763 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:17.763--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--sequence DISTRIBUTOR_TABLE_GENERATOR: preallocation size 50
[1/21/09 9:10:17:763 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:17.763--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--sequence ISOLATED_ITEM_SEQ: preallocation size 50
[1/21/09 9:10:17:763 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:17.763--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--sequence CUSTOMER_TABLE_GENERATOR: preallocation size 50
[1/21/09 9:10:17:779 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:17.763--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--sequence MANUFACTURER_TABLE_GENERATOR: preallocation size 50
[1/21/09 9:10:17:779 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:17.779--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--sequence ENTITYC_SEQ: preallocation size 50
[1/21/09 9:10:17:779 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:17.779--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--sequence ENTITYA_SEQ: preallocation size 50
[1/21/09 9:10:17:779 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:17.779--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--sequence ITEM_SEQ: preallocation size 50
[1/21/09 9:10:17:779 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:17.779--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--sequence ENTITYB_SEQ: preallocation size 50
[1/21/09 9:10:17:779 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:17.779--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--sequence ENTITYD_SEQ: preallocation size 50
[1/21/09 9:10:21:470 EST] 0000001a SystemOut     O [EL Info]: 2009.01.21 09:10:21.470--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--jar:file:/C:/opt/was7b/WebSphere/AppServer/profiles/AppSrv01/installedApps/mobrien-pc2Node05Cell/eclipselink-relationships-model.ear/eclipselink-relationships-model_ejb.jar!/-default login successful
[1/21/09 9:10:21:470 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:21.470--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--End deploying Persistence Unit default; state Deployed; factoryCount 1
[1/21/09 9:10:21:517 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:21.517--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--Execute query DataModifyQuery(sql="ALTER TABLE O_O_VIRTUAL DROP CONSTRAINT FK_O_O_VIRTUAL_VIRTUAL_ID")
[1/21/09 9:10:21:532 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:21.532--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--reconnecting to external connection pool
[1/21/09 9:10:21:532 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:21.532--ServerSession(1034173860)--Connection(1975285180)--Thread(Thread[ORB.thread.pool : 0,5,main])--ALTER TABLE O_O_VIRTUAL DROP CONSTRAINT FK_O_O_VIRTUAL_VIRTUAL_ID
[1/21/09 9:10:21:939 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:21.939--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--Execute query DataModifyQuery(sql="DROP TABLE CMP3_VIRTUAL")
[1/21/09 9:10:21:954 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:21.954--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--reconnecting to external connection pool
[1/21/09 9:10:21:954 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:21.954--ServerSession(1034173860)--Connection(1460295434)--Thread(Thread[ORB.thread.pool : 0,5,main])--DROP TABLE CMP3_VIRTUAL
[1/21/09 9:10:22:126 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:22.126--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--Execute query DataModifyQuery(sql="CREATE TABLE CMP3_VIRTUAL (CMP3_VIRTUALID NUMBER(15) NOT NULL, DESCRIPTION VARCHAR2(60) NULL, PRIMARY KEY (CMP3_VIRTUALID))")
[1/21/09 9:10:22:126 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:22.126--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--reconnecting to external connection pool
[1/21/09 9:10:22:126 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:22.126--ServerSession(1034173860)--Connection(1887596674)--Thread(Thread[ORB.thread.pool : 0,5,main])--CREATE TABLE CMP3_VIRTUAL (CMP3_VIRTUALID NUMBER(15) NOT NULL, DESCRIPTION VARCHAR2(60) NULL, PRIMARY KEY (CMP3_VIRTUALID))
[1/21/09 9:10:22:173 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:22.173--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--Execute query DataModifyQuery(sql="DROP TABLE O_O_VIRTUAL")
[1/21/09 9:10:22:173 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:22.173--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--reconnecting to external connection pool
[1/21/09 9:10:22:173 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:22.173--ServerSession(1034173860)--Connection(692595016)--Thread(Thread[ORB.thread.pool : 0,5,main])--DROP TABLE O_O_VIRTUAL
[1/21/09 9:10:22:267 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:22.252--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--Execute query DataModifyQuery(sql="CREATE TABLE O_O_VIRTUAL (O_O_VIRTUALID NUMBER(15) NOT NULL, VIRTUAL_ID NUMBER(15) NULL, PRIMARY KEY (O_O_VIRTUALID))")
[1/21/09 9:10:22:267 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:22.267--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--reconnecting to external connection pool
[1/21/09 9:10:22:267 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:22.267--ServerSession(1034173860)--Connection(1592024804)--Thread(Thread[ORB.thread.pool : 0,5,main])--CREATE TABLE O_O_VIRTUAL (O_O_VIRTUALID NUMBER(15) NOT NULL, VIRTUAL_ID NUMBER(15) NULL, PRIMARY KEY (O_O_VIRTUALID))
[1/21/09 9:10:22:549 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:22.549--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--Execute query DataModifyQuery(sql="ALTER TABLE O_O_VIRTUAL ADD CONSTRAINT FK_O_O_VIRTUAL_VIRTUAL_ID FOREIGN KEY (VIRTUAL_ID) REFERENCES CMP3_VIRTUAL (CMP3_VIRTUALID)")
[1/21/09 9:10:22:549 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:22.549--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--reconnecting to external connection pool
[1/21/09 9:10:22:549 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:22.549--ServerSession(1034173860)--Connection(423303483)--Thread(Thread[ORB.thread.pool : 0,5,main])--ALTER TABLE O_O_VIRTUAL ADD CONSTRAINT FK_O_O_VIRTUAL_VIRTUAL_ID FOREIGN KEY (VIRTUAL_ID) REFERENCES CMP3_VIRTUAL (CMP3_VIRTUALID)
[1/21/09 9:10:22:580 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:22.580--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--Execute query DataModifyQuery(sql="CREATE TABLE CMP3_CUSTOMER_SEQ (SEQ_NAME VARCHAR2(50) NOT NULL, SEQ_COUNT NUMBER(38) NULL, PRIMARY KEY (SEQ_NAME))")
[1/21/09 9:10:22:580 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:22.580--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--reconnecting to external connection pool
[1/21/09 9:10:22:580 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:22.580--ServerSession(1034173860)--Connection(1497061691)--Thread(Thread[ORB.thread.pool : 0,5,main])--CREATE TABLE CMP3_CUSTOMER_SEQ (SEQ_NAME VARCHAR2(50) NOT NULL, SEQ_COUNT NUMBER(38) NULL, PRIMARY KEY (SEQ_NAME))
[1/21/09 9:10:22:689 EST] 0000001a DMAdapter     I com.ibm.ws.ffdc.impl.DMAdapter getAnalysisEngine FFDC1009I: Analysis Engine using data base: C:\opt\was7b\WebSphere\AppServer\profiles\AppSrv01\properties\logbr\ffdc\adv\ffdcdb.xml
[1/21/09 9:10:22:752 EST] 0000001a FfdcProvider  I com.ibm.ws.ffdc.impl.FfdcProvider logIncident FFDC1003I: FFDC Incident emitted on C:\opt\was7b\WebSphere\AppServer\profiles\AppSrv01\logs\ffdc\server1_2e7c2e7c_09.01.21_09.10.22.61143645.txt com.ibm.ws.rsadapter.jdbc.WSJdbcPreparedStatement.pmiExecuteUpdate 807
[1/21/09 9:10:22:861 EST] 0000001a FfdcProvider  I com.ibm.ws.ffdc.impl.FfdcProvider logIncident FFDC1003I: FFDC Incident emitted on C:\opt\was7b\WebSphere\AppServer\profiles\AppSrv01\logs\ffdc\server1_2e7c2e7c_09.01.21_09.10.22.81543646.txt com.ibm.ws.rsadapter.jdbc.WSJdbcPreparedStatement.executeUpdate 449
[1/21/09 9:10:22:877 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:22.877--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--SELECT 1 FROM DUAL
[1/21/09 9:10:22:924 EST] 0000001a SystemOut     O [EL Warning]: 2009.01.21 09:10:22.908--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--Exception [EclipseLink-4002] (Eclipse Persistence Services - 1.1.0.20090121-SNAPSHOT): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: java.sql.SQLException: ORA-00955: name is already used by an existing object

Error Code: 955
Call: CREATE TABLE CMP3_CUSTOMER_SEQ (SEQ_NAME VARCHAR2(50) NOT NULL, SEQ_COUNT NUMBER(38) NULL, PRIMARY KEY (SEQ_NAME))
Query: DataModifyQuery(sql="CREATE TABLE CMP3_CUSTOMER_SEQ (SEQ_NAME VARCHAR2(50) NOT NULL, SEQ_COUNT NUMBER(38) NULL, PRIMARY KEY (SEQ_NAME))")
[1/21/09 9:10:22:924 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:22.924--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--Execute query DataModifyQuery(sql="CREATE TABLE SEQUENCE (SEQ_NAME VARCHAR2(50) NOT NULL, SEQ_COUNT NUMBER(38) NULL, PRIMARY KEY (SEQ_NAME))")
[1/21/09 9:10:22:924 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:22.924--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--reconnecting to external connection pool
[1/21/09 9:10:22:924 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:22.924--ServerSession(1034173860)--Connection(619914483)--Thread(Thread[ORB.thread.pool : 0,5,main])--CREATE TABLE SEQUENCE (SEQ_NAME VARCHAR2(50) NOT NULL, SEQ_COUNT NUMBER(38) NULL, PRIMARY KEY (SEQ_NAME))
[1/21/09 9:10:22:940 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:22.940--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--SELECT 1 FROM DUAL
[1/21/09 9:10:22:940 EST] 0000001a SystemOut     O [EL Warning]: 2009.01.21 09:10:22.940--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--Exception [EclipseLink-4002] (Eclipse Persistence Services - 1.1.0.20090121-SNAPSHOT): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: java.sql.SQLException: ORA-00955: name is already used by an existing object

Error Code: 955
Call: CREATE TABLE SEQUENCE (SEQ_NAME VARCHAR2(50) NOT NULL, SEQ_COUNT NUMBER(38) NULL, PRIMARY KEY (SEQ_NAME))
Query: DataModifyQuery(sql="CREATE TABLE SEQUENCE (SEQ_NAME VARCHAR2(50) NOT NULL, SEQ_COUNT NUMBER(38) NULL, PRIMARY KEY (SEQ_NAME))")
[1/21/09 9:10:22:940 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:22.940--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--Execute query DataModifyQuery(sql="CREATE TABLE CMP3_VIRTUAL_SEQ (SEQ_NAME VARCHAR2(50) NOT NULL, SEQ_COUNT NUMBER(38) NULL, PRIMARY KEY (SEQ_NAME))")
[1/21/09 9:10:22:940 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:22.940--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--reconnecting to external connection pool
[1/21/09 9:10:22:940 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:22.940--ServerSession(1034173860)--Connection(190384985)--Thread(Thread[ORB.thread.pool : 0,5,main])--CREATE TABLE CMP3_VIRTUAL_SEQ (SEQ_NAME VARCHAR2(50) NOT NULL, SEQ_COUNT NUMBER(38) NULL, PRIMARY KEY (SEQ_NAME))
[1/21/09 9:10:22:940 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:22.940--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--SELECT 1 FROM DUAL
[1/21/09 9:10:22:955 EST] 0000001a SystemOut     O [EL Warning]: 2009.01.21 09:10:22.955--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--Exception [EclipseLink-4002] (Eclipse Persistence Services - 1.1.0.20090121-SNAPSHOT): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: java.sql.SQLException: ORA-00955: name is already used by an existing object

Error Code: 955
Call: CREATE TABLE CMP3_VIRTUAL_SEQ (SEQ_NAME VARCHAR2(50) NOT NULL, SEQ_COUNT NUMBER(38) NULL, PRIMARY KEY (SEQ_NAME))
Query: DataModifyQuery(sql="CREATE TABLE CMP3_VIRTUAL_SEQ (SEQ_NAME VARCHAR2(50) NOT NULL, SEQ_COUNT NUMBER(38) NULL, PRIMARY KEY (SEQ_NAME))")
[1/21/09 9:10:22:955 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:22.955--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--Execute query DataModifyQuery(sql="CREATE TABLE CMP3_ENTITYA_SEQ (SEQ_NAME VARCHAR2(50) NOT NULL, SEQ_COUNT NUMBER(38) NULL, PRIMARY KEY (SEQ_NAME))")
[1/21/09 9:10:22:955 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:22.955--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--reconnecting to external connection pool
[1/21/09 9:10:22:955 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:22.955--ServerSession(1034173860)--Connection(1793092320)--Thread(Thread[ORB.thread.pool : 0,5,main])--CREATE TABLE CMP3_ENTITYA_SEQ (SEQ_NAME VARCHAR2(50) NOT NULL, SEQ_COUNT NUMBER(38) NULL, PRIMARY KEY (SEQ_NAME))
[1/21/09 9:10:22:955 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:22.955--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--SELECT 1 FROM DUAL
[1/21/09 9:10:22:955 EST] 0000001a SystemOut     O [EL Warning]: 2009.01.21 09:10:22.955--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--Exception [EclipseLink-4002] (Eclipse Persistence Services - 1.1.0.20090121-SNAPSHOT): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: java.sql.SQLException: ORA-00955: name is already used by an existing object

Error Code: 955
Call: CREATE TABLE CMP3_ENTITYA_SEQ (SEQ_NAME VARCHAR2(50) NOT NULL, SEQ_COUNT NUMBER(38) NULL, PRIMARY KEY (SEQ_NAME))
Query: DataModifyQuery(sql="CREATE TABLE CMP3_ENTITYA_SEQ (SEQ_NAME VARCHAR2(50) NOT NULL, SEQ_COUNT NUMBER(38) NULL, PRIMARY KEY (SEQ_NAME))")
[1/21/09 9:10:22:955 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:22.955--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--Execute query DataModifyQuery(sql="CREATE TABLE CMP3_ENTITYB_SEQ (SEQ_NAME VARCHAR2(50) NOT NULL, SEQ_COUNT NUMBER(38) NULL, PRIMARY KEY (SEQ_NAME))")
[1/21/09 9:10:22:955 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:22.955--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--reconnecting to external connection pool
[1/21/09 9:10:22:955 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:22.955--ServerSession(1034173860)--Connection(1332957043)--Thread(Thread[ORB.thread.pool : 0,5,main])--CREATE TABLE CMP3_ENTITYB_SEQ (SEQ_NAME VARCHAR2(50) NOT NULL, SEQ_COUNT NUMBER(38) NULL, PRIMARY KEY (SEQ_NAME))
[1/21/09 9:10:22:971 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:22.971--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--SELECT 1 FROM DUAL
[1/21/09 9:10:22:971 EST] 0000001a SystemOut     O [EL Warning]: 2009.01.21 09:10:22.971--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--Exception [EclipseLink-4002] (Eclipse Persistence Services - 1.1.0.20090121-SNAPSHOT): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: java.sql.SQLException: ORA-00955: name is already used by an existing object

Error Code: 955
Call: CREATE TABLE CMP3_ENTITYB_SEQ (SEQ_NAME VARCHAR2(50) NOT NULL, SEQ_COUNT NUMBER(38) NULL, PRIMARY KEY (SEQ_NAME))
Query: DataModifyQuery(sql="CREATE TABLE CMP3_ENTITYB_SEQ (SEQ_NAME VARCHAR2(50) NOT NULL, SEQ_COUNT NUMBER(38) NULL, PRIMARY KEY (SEQ_NAME))")
[1/21/09 9:10:22:971 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:22.971--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--Execute query DataModifyQuery(sql="CREATE TABLE CMP3_ENTITYC_SEQ (SEQ_NAME VARCHAR2(50) NOT NULL, SEQ_COUNT NUMBER(38) NULL, PRIMARY KEY (SEQ_NAME))")
[1/21/09 9:10:22:971 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:22.971--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--reconnecting to external connection pool
[1/21/09 9:10:22:971 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:22.971--ServerSession(1034173860)--Connection(991968032)--Thread(Thread[ORB.thread.pool : 0,5,main])--CREATE TABLE CMP3_ENTITYC_SEQ (SEQ_NAME VARCHAR2(50) NOT NULL, SEQ_COUNT NUMBER(38) NULL, PRIMARY KEY (SEQ_NAME))
[1/21/09 9:10:22:987 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:22.987--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--SELECT 1 FROM DUAL
[1/21/09 9:10:22:987 EST] 0000001a SystemOut     O [EL Warning]: 2009.01.21 09:10:22.987--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--Exception [EclipseLink-4002] (Eclipse Persistence Services - 1.1.0.20090121-SNAPSHOT): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: java.sql.SQLException: ORA-00955: name is already used by an existing object

Error Code: 955
Call: CREATE TABLE CMP3_ENTITYC_SEQ (SEQ_NAME VARCHAR2(50) NOT NULL, SEQ_COUNT NUMBER(38) NULL, PRIMARY KEY (SEQ_NAME))
Query: DataModifyQuery(sql="CREATE TABLE CMP3_ENTITYC_SEQ (SEQ_NAME VARCHAR2(50) NOT NULL, SEQ_COUNT NUMBER(38) NULL, PRIMARY KEY (SEQ_NAME))")
[1/21/09 9:10:22:987 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:22.987--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--Execute query DataModifyQuery(sql="CREATE TABLE CMP3_ENTITYD_SEQ (SEQ_NAME VARCHAR2(50) NOT NULL, SEQ_COUNT NUMBER(38) NULL, PRIMARY KEY (SEQ_NAME))")
[1/21/09 9:10:22:987 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:22.987--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--reconnecting to external connection pool
[1/21/09 9:10:22:987 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:22.987--ServerSession(1034173860)--Connection(500964828)--Thread(Thread[ORB.thread.pool : 0,5,main])--CREATE TABLE CMP3_ENTITYD_SEQ (SEQ_NAME VARCHAR2(50) NOT NULL, SEQ_COUNT NUMBER(38) NULL, PRIMARY KEY (SEQ_NAME))
[1/21/09 9:10:22:987 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:22.987--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--SELECT 1 FROM DUAL
[1/21/09 9:10:22:987 EST] 0000001a SystemOut     O [EL Warning]: 2009.01.21 09:10:22.987--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--Exception [EclipseLink-4002] (Eclipse Persistence Services - 1.1.0.20090121-SNAPSHOT): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: java.sql.SQLException: ORA-00955: name is already used by an existing object

Error Code: 955
Call: CREATE TABLE CMP3_ENTITYD_SEQ (SEQ_NAME VARCHAR2(50) NOT NULL, SEQ_COUNT NUMBER(38) NULL, PRIMARY KEY (SEQ_NAME))
Query: DataModifyQuery(sql="CREATE TABLE CMP3_ENTITYD_SEQ (SEQ_NAME VARCHAR2(50) NOT NULL, SEQ_COUNT NUMBER(38) NULL, PRIMARY KEY (SEQ_NAME))")
[1/21/09 9:10:22:987 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:22.987--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--Execute query DataReadQuery(sql="SELECT * FROM CMP3_VIRTUAL_SEQ WHERE SEQ_NAME = 'ONE_TO_ONE_VIRTUAL_ATTRIBUTE_SEQ'")
[1/21/09 9:10:22:987 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:22.987--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--reconnecting to external connection pool
[1/21/09 9:10:22:987 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:22.987--ServerSession(1034173860)--Connection(2136899422)--Thread(Thread[ORB.thread.pool : 0,5,main])--SELECT * FROM CMP3_VIRTUAL_SEQ WHERE SEQ_NAME = ONE_TO_ONE_VIRTUAL_ATTRIBUTE_SEQ
[1/21/09 9:10:23:034 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.034--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--Execute query DataReadQuery(sql="SELECT * FROM CMP3_CUSTOMER_SEQ WHERE SEQ_NAME = 'ISOLATED_ITEM_SEQ'")
[1/21/09 9:10:23:034 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.034--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--reconnecting to external connection pool
[1/21/09 9:10:23:034 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:23.034--ServerSession(1034173860)--Connection(674965563)--Thread(Thread[ORB.thread.pool : 0,5,main])--SELECT * FROM CMP3_CUSTOMER_SEQ WHERE SEQ_NAME = ISOLATED_ITEM_SEQ
[1/21/09 9:10:23:065 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.065--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--Execute query DataReadQuery(sql="SELECT * FROM CMP3_ENTITYA_SEQ WHERE SEQ_NAME = 'ENTITYA_SEQ'")
[1/21/09 9:10:23:065 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.065--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--reconnecting to external connection pool
[1/21/09 9:10:23:065 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:23.065--ServerSession(1034173860)--Connection(1642291683)--Thread(Thread[ORB.thread.pool : 0,5,main])--SELECT * FROM CMP3_ENTITYA_SEQ WHERE SEQ_NAME = ENTITYA_SEQ
[1/21/09 9:10:23:065 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.065--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--Execute query DataReadQuery(sql="SELECT * FROM CMP3_CUSTOMER_SEQ WHERE SEQ_NAME = 'SALESPERSON_SEQ'")
[1/21/09 9:10:23:065 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.065--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--reconnecting to external connection pool
[1/21/09 9:10:23:065 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:23.065--ServerSession(1034173860)--Connection(428808591)--Thread(Thread[ORB.thread.pool : 0,5,main])--SELECT * FROM CMP3_CUSTOMER_SEQ WHERE SEQ_NAME = SALESPERSON_SEQ
[1/21/09 9:10:23:065 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.065--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--Execute query DataReadQuery(sql="SELECT * FROM SEQUENCE WHERE SEQ_NAME = 'CUSTOMER_TABLE_GENERATOR'")
[1/21/09 9:10:23:065 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.065--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--reconnecting to external connection pool
[1/21/09 9:10:23:065 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:23.065--ServerSession(1034173860)--Connection(1361203490)--Thread(Thread[ORB.thread.pool : 0,5,main])--SELECT * FROM SEQUENCE WHERE SEQ_NAME = CUSTOMER_TABLE_GENERATOR
[1/21/09 9:10:23:065 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.065--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--Execute query DataReadQuery(sql="SELECT * FROM CMP3_CUSTOMER_SEQ WHERE SEQ_NAME = 'ITEM_SEQ'")
[1/21/09 9:10:23:065 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.065--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--reconnecting to external connection pool
[1/21/09 9:10:23:065 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:23.065--ServerSession(1034173860)--Connection(202509330)--Thread(Thread[ORB.thread.pool : 0,5,main])--SELECT * FROM CMP3_CUSTOMER_SEQ WHERE SEQ_NAME = ITEM_SEQ
[1/21/09 9:10:23:065 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.065--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--Execute query DataReadQuery(sql="SELECT * FROM CMP3_CUSTOMER_SEQ WHERE SEQ_NAME = 'ORDER_SEQ'")
[1/21/09 9:10:23:065 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.065--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--reconnecting to external connection pool
[1/21/09 9:10:23:065 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:23.065--ServerSession(1034173860)--Connection(1133069193)--Thread(Thread[ORB.thread.pool : 0,5,main])--SELECT * FROM CMP3_CUSTOMER_SEQ WHERE SEQ_NAME = ORDER_SEQ
[1/21/09 9:10:23:080 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.065--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--Execute query DataReadQuery(sql="SELECT * FROM SEQUENCE WHERE SEQ_NAME = 'MANUFACTURER_TABLE_GENERATOR'")
[1/21/09 9:10:23:080 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.080--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--reconnecting to external connection pool
[1/21/09 9:10:23:080 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:23.080--ServerSession(1034173860)--Connection(2077129678)--Thread(Thread[ORB.thread.pool : 0,5,main])--SELECT * FROM SEQUENCE WHERE SEQ_NAME = MANUFACTURER_TABLE_GENERATOR
[1/21/09 9:10:23:080 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.080--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--Execute query DataReadQuery(sql="SELECT * FROM CMP3_ENTITYD_SEQ WHERE SEQ_NAME = 'ENTITYD_SEQ'")
[1/21/09 9:10:23:080 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.080--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--reconnecting to external connection pool
[1/21/09 9:10:23:080 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:23.080--ServerSession(1034173860)--Connection(861942624)--Thread(Thread[ORB.thread.pool : 0,5,main])--SELECT * FROM CMP3_ENTITYD_SEQ WHERE SEQ_NAME = ENTITYD_SEQ
[1/21/09 9:10:23:080 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.080--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--Execute query DataReadQuery(sql="SELECT * FROM CMP3_VIRTUAL_SEQ WHERE SEQ_NAME = 'VIRTUAL_ATTRIBUTE_SEQ'")
[1/21/09 9:10:23:080 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.080--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--reconnecting to external connection pool
[1/21/09 9:10:23:080 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:23.080--ServerSession(1034173860)--Connection(1798269743)--Thread(Thread[ORB.thread.pool : 0,5,main])--SELECT * FROM CMP3_VIRTUAL_SEQ WHERE SEQ_NAME = VIRTUAL_ATTRIBUTE_SEQ
[1/21/09 9:10:23:080 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.080--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--Execute query DataReadQuery(sql="SELECT * FROM CMP3_ENTITYB_SEQ WHERE SEQ_NAME = 'ENTITYB_SEQ'")
[1/21/09 9:10:23:080 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.080--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--reconnecting to external connection pool
[1/21/09 9:10:23:080 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:23.080--ServerSession(1034173860)--Connection(637019640)--Thread(Thread[ORB.thread.pool : 0,5,main])--SELECT * FROM CMP3_ENTITYB_SEQ WHERE SEQ_NAME = ENTITYB_SEQ
[1/21/09 9:10:23:080 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.080--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--Execute query DataReadQuery(sql="SELECT * FROM SEQUENCE WHERE SEQ_NAME = 'DISTRIBUTOR_TABLE_GENERATOR'")
[1/21/09 9:10:23:080 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.080--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--reconnecting to external connection pool
[1/21/09 9:10:23:080 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:23.080--ServerSession(1034173860)--Connection(1643274738)--Thread(Thread[ORB.thread.pool : 0,5,main])--SELECT * FROM SEQUENCE WHERE SEQ_NAME = DISTRIBUTOR_TABLE_GENERATOR
[1/21/09 9:10:23:096 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.096--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--Execute query DataReadQuery(sql="SELECT * FROM CMP3_ENTITYC_SEQ WHERE SEQ_NAME = 'ENTITYC_SEQ'")
[1/21/09 9:10:23:096 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.096--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--reconnecting to external connection pool
[1/21/09 9:10:23:096 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:23.096--ServerSession(1034173860)--Connection(429267350)--Thread(Thread[ORB.thread.pool : 0,5,main])--SELECT * FROM CMP3_ENTITYC_SEQ WHERE SEQ_NAME = ENTITYC_SEQ
[1/21/09 9:10:23:096 EST] 0000001a SystemOut     O [EL Finer]: 2009.01.21 09:10:23.096--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--initialize all identitymaps
[1/21/09 9:10:23:159 EST] 0000001a SystemOut     O _VirtualAttributeTestSuite: testInsertVirtualAttribute()
[1/21/09 9:10:23:252 EST] 0000001a SystemOut     O [EL Finer]: 2009.01.21 09:10:23.252--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--client acquired
[1/21/09 9:10:23:252 EST] 0000001a SystemOut     O [EL Finer]: 2009.01.21 09:10:23.252--UnitOfWork(1697735985)--Thread(Thread[ORB.thread.pool : 0,5,main])--TX binding to tx mgr, status=STATUS_ACTIVE
[1/21/09 9:10:23:252 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.252--UnitOfWork(1697735985)--Thread(Thread[ORB.thread.pool : 0,5,main])--Execute query DoesExistQuery(referenceClass=OneToOneVirtualAttributeHolder )
[1/21/09 9:10:23:268 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.268--UnitOfWork(1697735985)--Thread(Thread[ORB.thread.pool : 0,5,main])--PERSIST operation called on: org.eclipse.persistence.testing.models.jpa.virtualattribute.OneToOneVirtualAttributeHolder@518f518f.
[1/21/09 9:10:23:268 EST] 0000001a SystemOut     O [EL Finer]: 2009.01.21 09:10:23.268--ClientSession(96077242)--Thread(Thread[ORB.thread.pool : 0,5,main])--TX beginTransaction, status=STATUS_ACTIVE
[1/21/09 9:10:23:268 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.268--ClientSession(96077242)--Thread(Thread[ORB.thread.pool : 0,5,main])--Execute query DataModifyQuery(sql="UPDATE CMP3_VIRTUAL_SEQ SET SEQ_COUNT = SEQ_COUNT + #PREALLOC_SIZE WHERE SEQ_NAME = #SEQ_NAME")
[1/21/09 9:10:23:284 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.268--ClientSession(96077242)--Thread(Thread[ORB.thread.pool : 0,5,main])--reconnecting to external connection pool
[1/21/09 9:10:23:284 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:23.284--ClientSession(96077242)--Connection(1149256832)--Thread(Thread[ORB.thread.pool : 0,5,main])--UPDATE CMP3_VIRTUAL_SEQ SET SEQ_COUNT = SEQ_COUNT + ? WHERE SEQ_NAME = ?
	bind => [50, ONE_TO_ONE_VIRTUAL_ATTRIBUTE_SEQ]
[1/21/09 9:10:23:299 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.299--ClientSession(96077242)--Thread(Thread[ORB.thread.pool : 0,5,main])--Execute query ValueReadQuery(sql="SELECT SEQ_COUNT FROM CMP3_VIRTUAL_SEQ WHERE SEQ_NAME = #SEQ_NAME")
[1/21/09 9:10:23:299 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:23.299--ClientSession(96077242)--Connection(1149256832)--Thread(Thread[ORB.thread.pool : 0,5,main])--SELECT SEQ_COUNT FROM CMP3_VIRTUAL_SEQ WHERE SEQ_NAME = ?
	bind => [ONE_TO_ONE_VIRTUAL_ATTRIBUTE_SEQ]
[1/21/09 9:10:23:331 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.331--ClientSession(96077242)--Connection(1149256832)--Thread(Thread[ORB.thread.pool : 0,5,main])--local sequencing preallocation for ONE_TO_ONE_VIRTUAL_ATTRIBUTE_SEQ: objects: 50 , first: 1,601, last: 1,650
[1/21/09 9:10:23:331 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.331--UnitOfWork(1697735985)--Thread(Thread[ORB.thread.pool : 0,5,main])--assign sequence to the object (1,601 -> org.eclipse.persistence.testing.models.jpa.virtualattribute.OneToOneVirtualAttributeHolder@518f518f)
[1/21/09 9:10:23:346 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.346--UnitOfWork(1697735985)--Thread(Thread[ORB.thread.pool : 0,5,main])--Execute query DoesExistQuery(referenceClass=VirtualAttribute )
[1/21/09 9:10:23:346 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.346--UnitOfWork(1697735985)--Thread(Thread[ORB.thread.pool : 0,5,main])--PERSIST operation called on: org.eclipse.persistence.testing.models.jpa.virtualattribute.VirtualAttribute@51a551a5.
[1/21/09 9:10:23:346 EST] 0000001a SystemOut     O [EL Finer]: 2009.01.21 09:10:23.346--ClientSession(96077242)--Thread(Thread[ORB.thread.pool : 0,5,main])--TX beginTransaction, status=STATUS_ACTIVE
[1/21/09 9:10:23:346 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.346--ClientSession(96077242)--Thread(Thread[ORB.thread.pool : 0,5,main])--Execute query DataModifyQuery(sql="UPDATE CMP3_VIRTUAL_SEQ SET SEQ_COUNT = SEQ_COUNT + #PREALLOC_SIZE WHERE SEQ_NAME = #SEQ_NAME")
[1/21/09 9:10:23:346 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:23.346--ClientSession(96077242)--Connection(1149256832)--Thread(Thread[ORB.thread.pool : 0,5,main])--UPDATE CMP3_VIRTUAL_SEQ SET SEQ_COUNT = SEQ_COUNT + ? WHERE SEQ_NAME = ?
	bind => [50, VIRTUAL_ATTRIBUTE_SEQ]
[1/21/09 9:10:23:346 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.346--ClientSession(96077242)--Thread(Thread[ORB.thread.pool : 0,5,main])--Execute query ValueReadQuery(sql="SELECT SEQ_COUNT FROM CMP3_VIRTUAL_SEQ WHERE SEQ_NAME = #SEQ_NAME")
[1/21/09 9:10:23:346 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:23.346--ClientSession(96077242)--Connection(1149256832)--Thread(Thread[ORB.thread.pool : 0,5,main])--SELECT SEQ_COUNT FROM CMP3_VIRTUAL_SEQ WHERE SEQ_NAME = ?
	bind => [VIRTUAL_ATTRIBUTE_SEQ]
[1/21/09 9:10:23:346 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.346--ClientSession(96077242)--Connection(1149256832)--Thread(Thread[ORB.thread.pool : 0,5,main])--local sequencing preallocation for VIRTUAL_ATTRIBUTE_SEQ: objects: 50 , first: 1,601, last: 1,650
[1/21/09 9:10:23:362 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.346--UnitOfWork(1697735985)--Thread(Thread[ORB.thread.pool : 0,5,main])--assign sequence to the object (1,601 -> org.eclipse.persistence.testing.models.jpa.virtualattribute.VirtualAttribute@51a551a5)
[1/21/09 9:10:23:362 EST] 0000001a SystemOut     O [EL Finer]: 2009.01.21 09:10:23.362--ClientSession(96077242)--Thread(Thread[ORB.thread.pool : 0,5,main])--TX beginTransaction, status=STATUS_ACTIVE
[1/21/09 9:10:23:378 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.378--UnitOfWork(1697735985)--Thread(Thread[ORB.thread.pool : 0,5,main])--Execute query InsertObjectQuery(org.eclipse.persistence.testing.models.jpa.virtualattribute.VirtualAttribute@51a551a5)
[1/21/09 9:10:23:378 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:23.378--ClientSession(96077242)--Connection(1149256832)--Thread(Thread[ORB.thread.pool : 0,5,main])--INSERT INTO CMP3_VIRTUAL (CMP3_VIRTUALID, DESCRIPTION) VALUES (?, ?)
	bind => [1601, virtualAttribute]
[1/21/09 9:10:23:424 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.424--UnitOfWork(1697735985)--Thread(Thread[ORB.thread.pool : 0,5,main])--Execute query InsertObjectQuery(org.eclipse.persistence.testing.models.jpa.virtualattribute.OneToOneVirtualAttributeHolder@518f518f)
[1/21/09 9:10:23:424 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.424--UnitOfWork(1697735985)--Thread(Thread[ORB.thread.pool : 0,5,main])--Execute query WriteObjectQuery(org.eclipse.persistence.testing.models.jpa.virtualattribute.VirtualAttribute@51a551a5)
[1/21/09 9:10:23:424 EST] 0000001a SystemOut     O [EL Fine]: 2009.01.21 09:10:23.424--ClientSession(96077242)--Connection(1149256832)--Thread(Thread[ORB.thread.pool : 0,5,main])--INSERT INTO O_O_VIRTUAL (O_O_VIRTUALID, VIRTUAL_ID) VALUES (?, ?)
	bind => [1601, 1601]
[1/21/09 9:10:23:440 EST] 0000001a SystemOut     O [EL Finer]: 2009.01.21 09:10:23.440--UnitOfWork(1697735985)--Thread(Thread[ORB.thread.pool : 0,5,main])--TX beforeCompletion callback, status=STATUS_ACTIVE
[1/21/09 9:10:23:440 EST] 0000001a SystemOut     O [EL Finer]: 2009.01.21 09:10:23.440--UnitOfWork(1697735985)--Thread(Thread[ORB.thread.pool : 0,5,main])--begin unit of work commit
[1/21/09 9:10:23:487 EST] 0000001a SystemOut     O [EL Finer]: 2009.01.21 09:10:23.487--UnitOfWork(1697735985)--Thread(Thread[ORB.thread.pool : 0,5,main])--initialize identitymaps
[1/21/09 9:10:23:487 EST] 0000001a SystemOut     O [EL Finer]: 2009.01.21 09:10:23.487--UnitOfWork(1697735985)--Thread(Thread[ORB.thread.pool : 0,5,main])--TX afterCompletion callback, status=COMMITTED
[1/21/09 9:10:23:487 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.487--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--local sequencing preallocation is copied to preallocation after transaction commit
[1/21/09 9:10:23:581 EST] 0000001a SystemOut     O [EL Finer]: 2009.01.21 09:10:23.581--ServerSession(1034173860)--Thread(Thread[ORB.thread.pool : 0,5,main])--client acquired
[1/21/09 9:10:23:628 EST] 0000001a SystemOut     O [EL Finest]: 2009.01.21 09:10:23.628--UnitOfWork(614868134)--Thread(Thread[ORB.thread.pool : 0,5,main])--Execute query ReadObjectQuery(referenceClass=OneToOneVirtualAttributeHolder sql="SELECT O_O_VIRTUALID, VIRTUAL_ID FROM O_O_VIRTUAL WHERE (O_O_VIRTUALID = ?)")

StackTrace

Query: DataModifyQuery(sql="CREATE TABLE CMP3_ENTITYD_SEQ (SEQ_NAME VARCHAR2(50) NOT NULL, SEQ_COUNT NUMBER(38) NULL, PRIMARY KEY (SEQ_NAME))")
[1/15/09 17:48:15:936 EST] 0000000e ThreadMonitor W   WSVR0605W: Thread "ORB.thread.pool : 1" (00000022) has been active for 670586 milliseconds and may be hung.  There is/are 2 thread(s) in total in the server that may be hung.
	at java.lang.Object.wait(Native Method)
	at java.lang.Object.wait(Object.java:196)
	at org.eclipse.persistence.internal.sessions.UnitOfWorkIdentityMapAccessor.getAndCloneCacheKeyFromParent(UnitOfWorkIdentityMapAccessor.java:146)
	at org.eclipse.persistence.internal.sessions.UnitOfWorkIdentityMapAccessor.getFromIdentityMap(UnitOfWorkIdentityMapAccessor.java:110)
	at org.eclipse.persistence.internal.queries.ExpressionQueryMechanism.checkCacheForObject(ExpressionQueryMechanism.java:730)
	at org.eclipse.persistence.queries.ReadObjectQuery.checkEarlyReturnImpl(ReadObjectQuery.java:229)
	at org.eclipse.persistence.queries.ObjectLevelReadQuery.checkEarlyReturn(ObjectLevelReadQuery.java:627)
	at org.eclipse.persistence.queries.DatabaseQuery.execute(DatabaseQuery.java:613)
	at org.eclipse.persistence.queries.ObjectLevelReadQuery.execute(ObjectLevelReadQuery.java:891)
	at org.eclipse.persistence.queries.ReadObjectQuery.execute(ReadObjectQuery.java:397)
	at org.eclipse.persistence.queries.ObjectLevelReadQuery.executeInUnitOfWork(ObjectLevelReadQuery.java:954)
	at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.internalExecuteQuery(UnitOfWorkImpl.java:2651)
	at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1181)
	at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1165)
	at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1125)
	at org.eclipse.persistence.internal.jpa.EntityManagerImpl.executeQuery(EntityManagerImpl.java:571)
	at org.eclipse.persistence.internal.jpa.EntityManagerImpl.findInternal(EntityManagerImpl.java:516)
	at org.eclipse.persistence.internal.jpa.EntityManagerImpl.find(EntityManagerImpl.java:431)
	at org.eclipse.persistence.internal.jpa.EntityManagerImpl.find(EntityManagerImpl.java:339)
	at com.ibm.ws.jpa.management.JPATxEmInvocation.find(JPATxEmInvocation.java:211)
	at com.ibm.ws.jpa.management.JPAEntityManager.find(JPAEntityManager.java:175)
	at org.eclipse.persistence.testing.tests.jpa.relationships.VirtualAttributeTestSuite.testReadVirtualAttribute(VirtualAttributeTestSuite.java:76)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:45)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37)
	at java.lang.reflect.Method.invoke(Method.java:599)
	at junit.framework.TestCase.runTest(TestCase.java:154)
	at junit.framework.TestCase.runBare(TestCase.java:127)
	at org.eclipse.persistence.testing.framework.junit.JUnitTestCase.runBareServer(JUnitTestCase.java:391)
	at org.eclipse.persistence.testing.framework.server.TestRunnerBean.runTest(TestRunnerBean.java:87)
	at org.eclipse.persistence.testing.framework.server.EJSRemote0SLTestRunner_ed643271.runTest(EJSRemote0SLTestRunner_ed643271.java)
	at org.eclipse.persistence.testing.framework.server._EJSRemote0SLTestRunner_ed643271_Tie.runTest(_EJSRemote0SLTestRunner_ed643271_Tie.java)
	at org.eclipse.persistence.testing.framework.server._EJSRemote0SLTestRunner_ed643271_Tie._invoke(_EJSRemote0SLTestRunner_ed643271_Tie.java)
	at com.ibm.CORBA.iiop.ServerDelegate.dispatchInvokeHandler(ServerDelegate.java:622)
	at com.ibm.CORBA.iiop.ServerDelegate.dispatch(ServerDelegate.java:475)
	at com.ibm.rmi.iiop.ORB.process(ORB.java:504)
	at com.ibm.CORBA.iiop.ORB.process(ORB.java:1571)
	at com.ibm.rmi.iiop.Connection.respondTo(Connection.java:2771)
	at com.ibm.rmi.iiop.Connection.doWork(Connection.java:2640)
	at com.ibm.rmi.iiop.WorkUnitImpl.doWork(WorkUnitImpl.java:63)
	at com.ibm.ejs.oa.pool.PooledThread.run(ThreadPool.java:118)
	at com.ibm.ws.util.ThreadPool$Worker.run(ThreadPool.java:1527)

Concepts

JPA Specification Notes

JPA 1.0 Specification

JPA 2.0 Specification

Reproduction

We need to narrow down in what cases this deadlock occurs and in what configuration.

WebSphere Behavior

We have the following use-case points to verify. Installation with/without admin security, installation as a service/non-service, running in debug/non-debug,

Note: It helps that I have 2 WebSphere 7 servers running because the first install was with security settings on which causes a UI security popup on all config/deploy/stop actions with a 30 sec timeout.

Reproduces?

With admin security = yes
Without admin security = no
Install as a service = no
Install as a non-service = yes
Run server in non-debug mode = yes
Run server in debug mode = no
- With Eclipse debug client attached = no
- Without Eclipse debug client attached = yes

entityManager.find() Behaviour

em.find() after a previous insert
em.find() in another update

Debugging EclipseLink in WebSphere 7 from Eclipse

See procedure on setting up WebSphere 7 so that we can debug the JUnit server tests from the Eclipse IDE by attaching to the 7781 JDWP debug port of a debug mode WebSphere server instance.

http://wiki.eclipse.org/EclipseLink/Examples/JPA/WebSphere7_Web_Tutorial#Remote_Debugging_EclipseLink_in_WebSphere_7.0_from_Eclipse_3.4

Prerequisites

Data Model

Use Case 1:

StackTrace

Logs

Analysis

Before debugging this issue it looks like the following code is never returning from the while loop because either the lock was not released or the cached object is still null.

package org.eclipse.persistence.internal.sessions;
public class UnitOfWorkIdentityMapAccessor extends IdentityMapAccessor {
    /**
     * INTERNAL:
     * This method will return the object from the parent and clone it.
     */
    protected Object getAndCloneCacheKeyFromParent(Vector primaryKey, Class theClass, boolean shouldReturnInvalidatedObjects, ClassDescriptor descriptor) {
        // Note: Objects returned from the parent's identity map should include invalidated
        // objects. This is important because this internal method is used in the existence
        // check in the UnitOfWork.
        UnitOfWorkImpl unitOfWork = (UnitOfWorkImpl)getSession();
        org.eclipse.persistence.internal.sessions.IdentityMapAccessor parentIdentityMapAccessor = unitOfWork.getParent().getIdentityMapAccessorInstance();
        CacheKey cacheKey = parentIdentityMapAccessor.getCacheKeyForObject(primaryKey, theClass, descriptor);
        if ((cacheKey == null) && unitOfWork.getParent().isUnitOfWork()) {
            //for nested unit of work
            //make parent clone and register object
            ((UnitOfWorkIdentityMapAccessor)parentIdentityMapAccessor).getAndCloneCacheKeyFromParent(primaryKey, theClass, shouldReturnInvalidatedObjects, descriptor);
            //get the cachekey that was created in the parent.
            cacheKey = parentIdentityMapAccessor.getCacheKeyForObject(primaryKey, theClass, descriptor);
        }
 
        Object objectFromCache = null;
        // this check could be simplfied to one line but would create a window
        // in which GC could remove the object and we would end up with a null pointer
        // as well we must inspect the cacheKey without locking on it.
        if ((cacheKey != null) && (shouldReturnInvalidatedObjects || !descriptor.getCacheInvalidationPolicy().isInvalidated(cacheKey))) {
            synchronized (cacheKey.getMutex()) {
                //if the object in the cachekey is null but the key is acquired then
                //someone must be rebuilding it or creating a new one.  Sleep until
                // it's finished. A plain wait here would be more efficient but we may not
                // get notified for quite some time (ie deadlock) if the other thread
                //is building the object.  Must wait and not sleep in order for the monitor to be released
                objectFromCache = cacheKey.getObject();
                try {
                    while (cacheKey.isAcquired() && (objectFromCache == null)) {
// WebSphere 7.0.0.1 hangs indefinetly here
                        cacheKey.getMutex().wait(5); // in milliseconds
                    }
                } catch (InterruptedException ex) {
                }
                if (objectFromCache == null) {
                    return null;
                }
            }
        } else {
            return null;
        }
 
        // Consider read-only class CR#4094
        if (getSession().isClassReadOnly(theClass, descriptor)) {
            // PERF: Just return the original object.
            return objectFromCache;
        }
 
        if(getSession() instanceof RepeatableWriteUnitOfWork ) {
            Object unregisteredDeletedClone = ((RepeatableWriteUnitOfWork)getSession()).getUnregisteredDeletedCloneForOriginal(objectFromCache);
            if(unregisteredDeletedClone != null) {
                return unregisteredDeletedClone;
            }
        }
 
        return unitOfWork.cloneAndRegisterObject(objectFromCache, cacheKey, descriptor);
    }

Constraints

Concurrency and Thread Safety

Design / Functionality

Alternative 1: Short Fix: Do Not Wait Indefinitely

This change will affect all platforms. However it does not fix the core of the problem where we are getting a mismatched serialization UID for the failing - previously hung tests.

The fix essentially involves limiting the number of wait cycles when holding for the mutex on the key to release - as opposed to waiting for the mutex forever.

Part 1: UnitOfWorkIdentityMapAccessor

Source

              private static final int MAXIMUM_MUTEX_STILL_ACQUIRED_WAIT_ITERATIONS = 2000;
              private static final int MUTEX_STILL_ACQUIRED_WAIT_MILLISECONDS_TIME = 5;
 
               objectFromCache = cacheKey.getObject();
                try {
--->                int iterations = 0;
                    while (cacheKey.isAcquired() && (objectFromCache == null) 
--->                    && (iterations++ < MAXIMUM_MUTEX_STILL_ACQUIRED_WAIT_ITERATIONS)) {
                        cacheKey.getMutex().wait(MUTEX_STILL_ACQUIRED_WAIT_MILLISECONDS_TIME);
                    }
                } catch (InterruptedException ex) {
                  // we should log a finest message here
                }

Part 2: ConcurrencyManager

The alt #1 workaround allows the tests to continue and emit the base server exception below:

    [junit]     org.omg.CORBA.MARSHAL: Unable to read value from underlying
bridge : Mismatched serialization UIDs : Source (RepId
RMI:junit.framework.AssertionFailedError:2E921E9DEB124A7F:0000000000000001) 
= 0000000000000001 whereas Target (RepId
RMI:junit.framework.AssertionFailedError:048A3675A6FD5463:A02206A4C2A2FD62)
= A02206A4C2A2FD62  vmcid: IBM  minor code: 896  completed: No)

There are (2) two nested deadlocks in our code. The second deadlock occurs periodically after the first has been fixed during testModifyItem() in ConcurrencyManager.releasesDeferredLock()

Stacktrace

1/19/09 16:17:33:719 EST] 00000019 TimeoutManage I   WTRN0006W: Transaction
0000011EF0BF93D7000000010000000F3FC544039A0DB96F61B909BB432079E1295E672A0000011EF0BF93D7000000010000000F3FC544039A0DB96F61B909BB432079E1295E672A00000001
has timed out after 120 seconds.
[1/19/09 16:17:33:719 EST] 00000019 TimeoutManage I   WTRN0124I: When the timeout occurred the thread with which the transaction is, or was most recently, associated was Thread[ORB.thread.pool : 0,5,main]. The stack trace of this thread when the timeout occurred was: 
	java.lang.Thread.sleep(Native Method)
	java.lang.Thread.sleep(Thread.java:850)
	org.eclipse.persistence.internal.helper.ConcurrencyManager.releaseDeferredLock(ConcurrencyManager.java:429)
	org.eclipse.persistence.internal.helper.ConcurrencyManager.checkDeferredLock(ConcurrencyManager.java:193)
	org.eclipse.persistence.internal.identitymaps.CacheKey.checkDeferredLock(CacheKey.java:176)
	org.eclipse.persistence.internal.identitymaps.IdentityMapManager.getFromIdentityMapWithDeferredLock(IdentityMapManager.java:686)
	org.eclipse.persistence.internal.sessions.IdentityMapAccessor.getFromIdentityMapWithDeferredLock(IdentityMapAccessor.java:424)
	org.eclipse.persistence.internal.queries.ExpressionQueryMechanism.checkCacheForObject(ExpressionQueryMechanism.java:728)
	org.eclipse.persistence.queries.ReadObjectQuery.checkEarlyReturnImpl(ReadObjectQuery.java:229)
	org.eclipse.persistence.queries.ObjectLevelReadQuery.checkEarlyReturn(ObjectLevelReadQuery.java:620)
	org.eclipse.persistence.queries.ObjectLevelReadQuery.checkEarlyReturn(ObjectLevelReadQuery.java:644)
	org.eclipse.persistence.queries.DatabaseQuery.execute(DatabaseQuery.java:613)
	org.eclipse.persistence.queries.ObjectLevelReadQuery.execute(ObjectLevelReadQuery.java:891)
	org.eclipse.persistence.queries.ReadObjectQuery.execute(ReadObjectQuery.java:397)
	org.eclipse.persistence.queries.ObjectLevelReadQuery.executeInUnitOfWork(ObjectLevelReadQuery.java:954)
	org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.internalExecuteQuery(UnitOfWorkImpl.java:2651)
	org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1181)
	org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1165)
	org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1125)
	org.eclipse.persistence.internal.jpa.EntityManagerImpl.executeQuery(EntityManagerImpl.java:571)
	org.eclipse.persistence.internal.jpa.EntityManagerImpl.findInternal(EntityManagerImpl.java:516)
	org.eclipse.persistence.internal.jpa.EntityManagerImpl.find(EntityManagerImpl.java:431)
	org.eclipse.persistence.internal.jpa.EntityManagerImpl.find(EntityManagerImpl.java:339)
	com.ibm.ws.jpa.management.JPATxEmInvocation.find(JPATxEmInvocation.java:211)
	com.ibm.ws.jpa.management.JPAEntityManager.find(JPAEntityManager.java:175)
	org.eclipse.persistence.testing.tests.jpa.relationships.RelationshipModelJUnitTestSuite.testModifyItem(RelationshipModelJUnitTestSuite.java:119)
	sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:45)
	sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37)
	java.lang.reflect.Method.invoke(Method.java:599)
	junit.framework.TestCase.runTest(TestCase.java:154)
	junit.framework.TestCase.runBare(TestCase.java:127)
	org.eclipse.persistence.testing.framework.junit.JUnitTestCase.runBareServer(JUnitTestCase.java:391)
	org.eclipse.persistence.testing.framework.server.TestRunnerBean.runTest(TestRunnerBean.java:87)
	org.eclipse.persistence.testing.framework.server.EJSRemote0SLTestRunner_ed643271.runTest(EJSRemote0SLTestRunner_ed643271.java)
	org.eclipse.persistence.testing.framework.server._EJSRemote0SLTestRunner_ed643271_Tie.runTest(_EJSRemote0SLTestRunner_ed643271_Tie.java)
	org.eclipse.persistence.testing.framework.server._EJSRemote0SLTestRunner_ed643271_Tie._invoke(_EJSRemote0SLTestRunner_ed643271_Tie.java)
	com.ibm.CORBA.iiop.ServerDelegate.dispatchInvokeHandler(ServerDelegate.java:622)

        while (true) {
            // 2612538 - the default size of Map (32) is appropriate
            Map recursiveSet = new IdentityHashMap();
            if (isBuildObjectOnThreadComplete(currentThread, recursiveSet)) {// Thread job done.
                lockManager.releaseActiveLocksOnThread();
                removeDeferredLockManager(currentThread);
                AbstractSessionLog.getLog().log(SessionLog.FINER, "deferred_locks_released", currentThread.getName());
                return;
            } else {// Not done yet, wait and check again.
                try {
---->                Thread.sleep(1);
                } catch (InterruptedException ignoreAndContinue) {
                }
            }
        }

Logs

server-run-test:
     [echo] Running test eclipselink-relationships-model on websphere
Warning: Reference compile.server.path has not been set at runtime, but was found during
build file parsing, attempting to resolve. Future versions of Ant may support
 referencing ids defined in non-executed targets.
Warning: Reference compile.path has not been set at runtime, but was found during
build file parsing, attempting to resolve. Future versions of Ant may support
 referencing ids defined in non-executed targets.
    [junit] Running org.eclipse.persistence.testing.tests.jpa.relationships.ServerTestSuite
    [junit]     org.omg.CORBA.MARSHAL: Unable to read value from underlying bridge : Mismatched serialization UIDs : Source (RepId RMI:junit.framework.AssertionFailedError:2E921E9DEB124A7F:0000000000000001) = 0000000000000001 whereas Target
 (RepId RMI:junit.framework.AssertionFailedError:048A3675A6FD5463:A02206A4C2A2FD62) = A02206A4C2A2FD62  vmcid: IBM  minor code: 896  completed: No)
    [junit]     org.omg.CORBA.MARSHAL: Unable to read value from underlying bridge : Mismatched serialization UIDs : Source (RepId RMI:junit.framework.AssertionFailedError:2E921E9DEB124A7F:0000000000000001) = 0000000000000001 whereas Target
 (RepId RMI:junit.framework.AssertionFailedError:048A3675A6FD5463:A02206A4C2A2FD62) = A02206A4C2A2FD62  vmcid: IBM  minor code: 896  completed: No)
    [junit] Tests run: 30, Failures: 0, Errors: 2, Time elapsed: 69.799 sec

BUILD SUCCESSFUL
Total time: 3 minutes 44 seconds

Alternative 2: Long Fix: WebSphere 7.0 Platform Change for Alternative 1

This change will target the change in alternative 1 to WebSphere 7 only. I don't think we should limit these two deadlock checks to a single application server's Platform class.

Source

Alternative 3: Full Fix:

What is the cause of the deadlock for the following two specific test cases on WebSphere 7?

package org.eclipse.persistence.testing.tests.jpa.relationship;
 
RelationshipModelJUnitTestSuite.testModifyItem()
   Item item = em.find(Item.class, itemId);
VirtualAttributeTestSuite.testInsertVirtualAttribute()

Source

Decision

Pending code-review.

Logs

Implementation

Logging

Testing

Full regression tests on another JEE server like WebLogic will be required. Full regression tests on an SE (servlet only) server like Tomcat will be required.

API

GUI

Config files

Documentation

Open Issues

Issue #	Owner	Description / Notes
I1	mobrien	- If we go with alt#1 - we need a number for the maximum timeout wait (1/10/30 seconds)
I2	mobrien	-

Decisions

Issue #	Description / Notes	Decision

Future Considerations

During the research for this bug, the following items were identified as out of scope but are captured here as potential future enhancements. If agreed upon during the review process these should be logged in the bug system.

References

EclipseLink Fisheye Revision pending

Breadcrumbs

Notice: this Wiki will be going read only early in 2024 and edits will no longer be possible. Please see: https://gitlab.eclipse.org/eclipsefdn/helpdesk/-/wikis/Wiki-shutdown-plan for the plan.

Difference between revisions of "EclipseLink/Bugs/259993"

Revision as of 10:16, 21 January 2009

Contents

Bug Analysis Document: 259993: Deadlock on em.find() on WebSphere 7.0.0.1

Document History

Overview

Exceptions

Timeout during UnitOfWorkIdentityMapAccessor.getAndCloneCacheKeyFromParent()

Timeout during ConcurrencyManager.releaseDeferredLock()

Logs

StackTrace

Concepts

JPA Specification Notes

JPA 1.0 Specification

JPA 2.0 Specification

Reproduction

WebSphere Behavior

Reproduces?

entityManager.find() Behaviour

Debugging EclipseLink in WebSphere 7 from Eclipse

Prerequisites

Data Model

Use Case 1:

StackTrace

Logs

Analysis

Constraints

Concurrency and Thread Safety

Design / Functionality

Alternative 1: Short Fix: Do Not Wait Indefinitely

Part 1: UnitOfWorkIdentityMapAccessor

Source

Part 2: ConcurrencyManager

Stacktrace

Logs

Alternative 2: Long Fix: WebSphere 7.0 Platform Change for Alternative 1

Source

Alternative 3: Full Fix:

Source

Decision

Logs

Implementation

Logging

Testing

API

GUI

Config files

Documentation

Open Issues

Decisions

Future Considerations

References