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

Document History

Date	Author	Version Description & Notes
20090115	Michael O'Brien	1.0 Initial reproduction use cases
20090123	Michael O'Brien	Update details for part 1 fixed by Bugzilla Bug 261910
20090126	Michael O'Brien	Update details for part 2 debug details
20090128	Michael O'Brien	Update code to rev 3322 and re-debug
20090211	Michael O'Brien	Final code review of 2 part fix 259993 Code Review

Status : Fixed

As of the following builds, this issue has been fixed by allowing WebSphere 7.0 to do a partial cache em.clear() during a commit() without resetting the entityManager state/lifecycle flag. Previously we were not releasing the acquired lock because the entityManager state was reset from *Pending (4) to Birth (0) by the WAS7 clear().

EclipseLink 1.1 : 12 Feb 2009

http://fisheye2.atlassian.com/changelog/eclipselink/?cs=3447

https://bugs.eclipse.org/bugs/attachment.cgi?id=125911&action=diff

EclipseLink Trunk

Today

Overview

WebSphere 7.0 fails to run our JPA test suites that previously ran fine on WebSphere 6.1.

The behaviour we are seeing is the inability to acquire the read lock during the commit within a ReadObjectQuery of an entityManager.find() that occurs after a previous commit. There should be no pending changes due in the find().

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

The issue happens differently as two (2) wait issues here in package org.eclipse.persistence.testing.tests.jpa.relationship. \ Both of these tests run em.find(class, PK(int)) after a committed persist.

We get a third thread wait issue when the following two issues are worked around or bypassed in debugging by ignoring the depth flag on the mutex (not a fix).

Primary Failing Find after Previous Committed Changes Tests

   ant server-test-relationships

RelationshipModelJUnitTestSuite.testModifyItem()
- Item item = em.find(Item.class, itemId);
VirtualAttributeTestSuite.testReadVirtualAttribute()
- OneToOneVirtualAttributeHolder holder = createEntityManager().find(OneToOneVirtualAttributeHolder.class, id);

	mutex	ConcurrencyManager  (id=287)	
		activeThread	ThreadPool$Worker  (id=133)	
		depth	1	
		lockedByMergeManager	true	
		numberOfReaders	0	
		numberOfWritersWaiting	0	
		ownerCacheKey	HardCacheWeakIdentityMap$ReferenceCacheKey  (id=288)

The fix in bug# 261910 in svn ref 3266 has fixed the first wait but we are now experiencing the second wait only in the advanced field access model.

Secondary Failing Find on Pending Changes Tests

The following tests continue to hang after rev 3266

    ant server-test-fieldaccess-advanced


	AdvancedJunitTest.testStringArrayField() line: 260 [local variables unavailable]	
	AdvancedJunitTest.testBUG241388() line: 310	
	EntityManagerJUnitTestSuite.testSetFieldForPropertyAccessWithRefresh() line: 3354 [local variables unavailable]	
	EntityManagerJUnitTestSuite.testCascadeMergeManaged() line: 3153 [local variables unavailable]	
	EntityManagerJUnitTestSuite.testCascadeMergeManaged() line: 3176 [local variables unavailable]	
	EntityManagerJUnitTestSuite.testCascadeMergeDetached() line: 3092 [local variables unavailable]	
	EntityManagerJUnitTestSuite.testPrimaryKeyUpdatePKFK() line: 3012 [local variables unavailable]	

	VirtualAttributeTestSuite.testReadVirtualAttribute() line: 79

EntityManagerJUnitTestSuite [line: 3346] - testSetFieldForPropertyAccessWithRefresh()
        employee = em.getReference(Employee.class, employee.getId());
EntityManagerJUnitTestSuite [line: 3921] - internalTestUpdateAllProjectsWithNullTeamLeader(Class)
	List employees = em.createQuery("SELECT OBJECT(e) FROM Employee e").getResultList();

Third Timeout during ConcurrencyManager.acquireReadLock()

This thread wait issue occurs after the first and second thread issues above are fixed. The activeThread (1) and currentThread (0) are different.

Daemon Thread [ORB.thread.pool : 0] (Suspended)	
	Object.wait(long, int) line: not available [native method]	
	ConcurrencyManager(Object).wait() line: 167	
	ConcurrencyManager.acquireReadLock() line: 243	
	ConcurrencyManager.checkReadLock() line: 230	
	HardCacheWeakIdentityMap$ReferenceCacheKey(CacheKey).checkReadLock() line: 180	
	IdentityMapManager.getFromIdentityMap(Vector, Class, boolean, ClassDescriptor) line: 610	

this	ConcurrencyManager  (id=14995)	
	activeThread	ThreadPool$Worker  (id=51)	
		isHung	false	
		lock	Thread$ThreadLock  (id=15034)	
		name	"ORB.thread.pool : 1" (id=15035)

Cause

The ConcurrencyManager(mutex).depth field is not being decremented to 0 in release() - this also keeps the field lockedByMergeManager set to true. The result of this is that the check for cacheKey.isAcquired() or cacheKey.getMutex().depth > 0 causes UnitOfWorkIdentityMapAccessor.getAndCloneCacheKeyFromParent() to stay in the synchronized while loop indefinitely.

This is due to the fact that the currentThread and activeThread on the lock are different - the solution is to make the activeThread the currentThread in this case.

Exceptions

There are 3 possible thread wait issues.

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

1 Timeout during UnitOfWorkIdentityMapAccessor.getAndCloneCacheKeyFromParent()

Note: This timeout continues to occur after rev# 3322 on 28 Jan 2009

[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 - this is just a theory - I am currently debugging the root cause.

    [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)

2 Timeout during ConcurrencyManager.releaseDeferredLock()

Note: This timeout no longer occurs after rev# 3322 on 28 Jan 2009

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)

3 Timeout during ConcurrencyManager.acquireReadLock()

This thread wait issue occurs after the first and second thread issues above are fixed. The activeThread (1) and currentThread (0) are different.

Daemon Thread [ORB.thread.pool : 0] (Suspended)	
	Object.wait(long, int) line: not available [native method]	
	ConcurrencyManager(Object).wait() line: 167	
	ConcurrencyManager.acquireReadLock() line: 243	
	ConcurrencyManager.checkReadLock() line: 230	
	HardCacheWeakIdentityMap$ReferenceCacheKey(CacheKey).checkReadLock() line: 180	
	IdentityMapManager.getFromIdentityMap(Vector, Class, boolean, ClassDescriptor) line: 610	

this	ConcurrencyManager  (id=14995)	
	activeThread	ThreadPool$Worker  (id=51)	
		isHung	false	
		lock	Thread$ThreadLock  (id=15034)	
		name	"ORB.thread.pool : 1" (id=15035)

Logs

These are the FINEST logs up until the first wait.

[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)

Rev 3322 : Retesting

The fix in ref 3322 has reversed test results. Where before we were only hanging in ConcurrencyManager, we now only hang in UnitOfWorkIdentityMapAccessor.

ant server-test-fieldaccess-advanced

We only hang on 1 test instead of 2 - in UnitOfWorkIdentityMapAccessor.getAndCloneCacheKeyFromParent().
We no longer hang on the secondary timeout in ConcurrencyManager.releaseDeferredLock()

ant server-test-relationships

We hang on 7 tests - all in the same place in UnitOfWorkIdentityMapAccessor.getAndCloneCacheKeyFromParent().

We no longer hang on ConcurrencyManager.releaseDeferredLock()

Concepts

JPA Specification Notes

JPA 1.0 Specification

JPA 2.0 Specification

Reproduction

We need to narrow down in what cases this wait loop to occur and in what configuration.

If I debug the infinite loop and change the depth field on the concurrenyManager manually then the test exits the loop and completes with an initial null object and a second query attempt.

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 wait loop) 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);
    }

Debug Results

ConcurrencyManager during getAndCloneCacheKeyFromParent

this	ConcurrencyManager  (id=278)	
	activeThread	ThreadPool$Worker  (id=129)	
		accessControlContext	AccessControlContext  (id=321)	
		activeWasThreadLocals	ThreadPool$WasThreadLocalData[0]  (id=323)	
		blockOn	null	
		contextClassLoader	CompoundClassLoader  (id=214)	
		exceptionHandler	null	
		firstTask_	null	
		inheritableThreadLocals	ThreadLocal$ThreadLocalMap  (id=326)	
		isDaemon	true	
		isHung	false	
		lock	Thread$ThreadLock  (id=328)	
		name	"ORB.thread.pool : 0" (id=330)	
		numberOfActiveWasThreadLocals	0	
		parkBlocker	null	
		priority	5	
		runnable	null	
		stackSize	0	
		started	true	
		startTime	1232557632328	
		stopThrowable	null	
		this$0	ThreadPool  (id=338)	
		threadGroup	ThreadGroup  (id=49)	
		threadLocals	ThreadLocal$ThreadLocalMap  (id=344)	
		threadNumber	"00000024" (id=346)	
		threadRef	455730688	
		uniqueId	99	
		wsThreadLocals	Object[41]  (id=350)	
	depth	1	
	lockedByMergeManager	true	
	numberOfReaders	0	
	numberOfWritersWaiting	0	
	ownerCacheKey	HardCacheWeakIdentityMap$ReferenceCacheKey  (id=206)

Issues

The activeThread on release() is different than the one on acquire()

I am concerned about the assumption that we are using the active thread in release() but in acquire() we explicitly verify this. If this is not an issue then the javadoc needs to state why we are ok with an assumption on release().

ConcurrencyManager.java
    /**
     * Decrement the depth for the active thread.
     * Assume the current thread is the active one.
     * Raise an error if the depth become < 0.
     * The notify will release the first thread waiting on the object,
     * if no threads are waiting it will do nothing.
     */
    public synchronized void release() throws ConcurrencyException {
        if (this.depth == 0) {
            throw ConcurrencyException.signalAttemptedBeforeWait();
        } else {
            this.depth--;
        }
        if (this.depth == 0) {
            this.activeThread = null;
            this.lockedByMergeManager = false;
            notifyAll();
        }
    }
 
 
    /**
     * Wait for all threads except the active thread.
     * If this is the active thread then just increment the depth.
     * This should be called before entering a critical section.
     * called with true from the merge process, if true then the refresh will not refresh the object
     */
    public synchronized void acquire(boolean forMerge) throws ConcurrencyException {
        while (((this.activeThread != null) || (this.numberOfReaders > 0)) && (this.activeThread != Thread.currentThread())) {
            // This must be in a while as multiple threads may be released, or another thread may rush the acquire after one is released.
            try {
                this.numberOfWritersWaiting++;
                wait();
                this.numberOfWritersWaiting--;
            } catch (InterruptedException exception) {
                throw ConcurrencyException.waitWasInterrupted(exception.getMessage());
            }
        }
        if (this.activeThread == null) {
            this.activeThread = Thread.currentThread();
        }
        this.lockedByMergeManager = forMerge;
        this.depth++;
    }

Are the tests running concurrent threads

We need an answer on whether the JUnit test are causing threads to run concurrently on WebSphere 7 - possibly because previous tests' threads were not released.

A) We are running 2 threads one static and one dynamic

Constraints

Concurrency and Thread Safety

Design / Functionality

Alternative 1: Short Fix: Do Not Wait Indefinitely - Invalid

Note: This fix causes an indefinite wait later on in ConcurrencyManager.

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 wait loops in our code. The second wait loop 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 wait loop checks to a single application server's Platform class.

Source

Alternative 3: Full Fix:

What is the cause of the wait loop 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

Existing WebSphere 6.1.0.17 Results

Currently we get 6 failures and 18 errors

Internal WebSphere 6.1 results

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	20090122:1100 - the fix in bug# 261910 in svn ref 3266 has fixed the first wait loop but we are now experiencing the second wait loop only in the advanced field access model

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 is now read only and edits are no longer possible. Please see: https://gitlab.eclipse.org/eclipsefdn/helpdesk/-/wikis/Wiki-shutdown-plan for the plan.

EclipseLink/Bugs/259993

Contents

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

Document History

Status : Fixed

EclipseLink 1.1 : 12 Feb 2009

EclipseLink Trunk

Overview

Primary Failing Find after Previous Committed Changes Tests

Secondary Failing Find on Pending Changes Tests

Third Timeout during ConcurrencyManager.acquireReadLock()

Cause

Exceptions

1 Timeout during UnitOfWorkIdentityMapAccessor.getAndCloneCacheKeyFromParent()

2 Timeout during ConcurrencyManager.releaseDeferredLock()

3 Timeout during ConcurrencyManager.acquireReadLock()

Logs

StackTrace

Rev 3322 : Retesting

ant server-test-fieldaccess-advanced

ant server-test-relationships

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

Debug Results

ConcurrencyManager during getAndCloneCacheKeyFromParent

Issues

The activeThread on release() is different than the one on acquire()

Are the tests running concurrent threads

Constraints

Concurrency and Thread Safety

Design / Functionality

Alternative 1: Short Fix: Do Not Wait Indefinitely - Invalid

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

Existing WebSphere 6.1.0.17 Results

API

GUI

Config files

Documentation

Open Issues

Decisions

Future Considerations

References