Skip to main content

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.

Jump to: navigation, search

EclipseLink/Bugs/259993

< EclipseLink‎ | Bugs
Revision as of 16:53, 22 January 2009 by Michael.obrien.oracle.com (Talk | contribs) (Open Issues)

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

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. \ Both of these tests run em.find(class, PK(int)) after a committed persist.

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

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.

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: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.

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

Debug Results

ConcurrenyManager 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++;
    }

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 20090122:1100 - the fix in bug# 261910 in svn ref 3266 has fixed the first deadlock but we are now experiencing the second deadlock 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

Back to the top