高負荷シナリオでDatabaseAccessorが接続されていません

Question

私たちのアプリで「EclipseLink-4005（..）DatabaseAccessor未接続」の犯人を追跡する際に問題が発生しました。これは、同じdb（Oracle）に接続する複数のスレッドを持つスタンドアロンのアプリケーション（Webアプリケーションではない）です。 EclipseLink 2.4.2とその内部接続プールをデフォルト設定で使用します。トランザクションはアプリで管理され、ネストすることができます。ほとんどの場合アプリは正常に動作しますが、「EclipseLink-4005（..）DatabaseAccessorが接続されていません。」というエラーが発生して高負荷で失敗することがあります。

テスト環境でエラーを再現できましたが、発生する可能性がある条件の下では理解できませんでした。一部のトランザクションは長時間実行されています。それらのうちのいくつかがタイムアウトして、それぞれのセッションがログアウトし、別のスレッドでエラーが発生する可能性はありますか？

は、以下のサンプルスタックトレースです：

Exception [EclipseLink-4005] (Eclipse Persistence Services - 2.4.2.v20130514-5956486): org.eclipse.persistence.exceptions.DatabaseException 
Exception Description: DatabaseAccessor not connected. 
    at org.eclipse.persistence.exceptions.DatabaseException.databaseAccessorNotConnected(DatabaseException.java:116) 
    at org.eclipse.persistence.internal.databaseaccess.DatasourceAccessor.incrementCallCount(DatasourceAccessor.java:309) 
    at org.eclipse.persistence.internal.databaseaccess.DatasourceAccessor.beginTransaction(DatasourceAccessor.java:238) 
    at org.eclipse.persistence.internal.sessions.AbstractSession.basicBeginTransaction(AbstractSession.java:526) 
    at org.eclipse.persistence.sessions.server.ClientSession.addWriteConnection(ClientSession.java:693) 
    at org.eclipse.persistence.sessions.server.ServerSession.acquireClientConnection(ServerSession.java:246) 
    at org.eclipse.persistence.sessions.server.ClientSession.getAccessor(ClientSession.java:333) 
    at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.getAccessor(UnitOfWorkImpl.java:1867) 
    at org.eclipse.persistence.internal.jpa.EntityManagerImpl.unwrap(EntityManagerImpl.java:2540) 
    (..) 

と

Exception [EclipseLink-4005] (Eclipse Persistence Services - 2.4.2.v20130514-5956486): org.eclipse.persistence.exceptions.DatabaseException 
Exception Description: DatabaseAccessor not connected. 
    at org.eclipse.persistence.exceptions.DatabaseException.databaseAccessorNotConnected(DatabaseException.java:116) 
    at org.eclipse.persistence.internal.databaseaccess.DatasourceAccessor.incrementCallCount(DatasourceAccessor.java:309) 
    at org.eclipse.persistence.internal.databaseaccess.DatasourceAccessor.rollbackTransaction(DatasourceAccessor.java:671) 
    at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.rollbackTransaction(DatabaseAccessor.java:1576) 
    at org.eclipse.persistence.internal.sessions.AbstractSession.basicRollbackTransaction(AbstractSession.java:629) 
    at org.eclipse.persistence.sessions.server.ClientSession.basicRollbackTransaction(ClientSession.java:186) 
    at org.eclipse.persistence.internal.sessions.AbstractSession.rollbackTransaction(AbstractSession.java:3561) 
    at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.rollbackTransaction(UnitOfWorkImpl.java:4641) 
    at org.eclipse.persistence.internal.sessions.RepeatableWriteUnitOfWork.rollbackTransaction(RepeatableWriteUnitOfWork.java:522) 
    at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.release(UnitOfWorkImpl.java:4448) 
    at org.eclipse.persistence.internal.jpa.transaction.EntityTransactionImpl.rollback(EntityTransactionImpl.java:127) 
    (..) 

は、あなたが任意のより多くの情報が必要な場合は私に知らせてください。私は現在アイデアがないので、それを共有して嬉しいです。

---

さらに詳しい情報は、EclipseLinkロギングを有効にした後のものです。

ログに、エラーが発生する直前に接続が切断されることがわかりました（下記参照）。私が最初に考えたのは、それが無効であるとマークされていたからです（DatabaseAccessor.setIsValid）。エラーの前に起こった唯一の問題はOptimisticLockExceptionが30分早くスローされ、アプリケーションによって正常に処理されたことでした。さらに、同じ接続が次の30分にうまく使用されるため、無効とマークされていないと思います。

TRACE [2017-09-01 10:01:04.851/-0700] [Worker-659:org.eclipse.persistence.transaction] [ ] 2017-09-01 10:01:04.851--ClientSession(436256688)--Connection(148152749)--Thread(Thread[Worker-659,5,main])-- commit transaction 
TRACE [2017-09-01 10:01:04.914/-0700] [Worker-659:org.eclipse.persistence.connection] [ ] 2017-09-01 10:01:04.914--ServerSession(441145695)--Connection(148152749)--Thread(Thread[Worker-659,5,main])-- Connection released to connection pool [default]. 
DEBUG [2017-09-01 10:01:04.914/-0700] [Worker-659:org.eclipse.persistence.connection] [ ] 2017-09-01 10:01:04.914--ServerSession(441145695)--Connection(148152749)--Thread(Thread[Worker-659,5,main])-- disconnect 
TRACE [2017-09-01 10:01:04.929/-0700] [Worker-659:org.eclipse.persistence.transaction] [ ] 2017-09-01 10:01:04.929--UnitOfWork(122187888)--Thread(Thread[Worker-659,5,main])-- end unit of work commit 
TRACE [2017-09-01 10:01:04.929/-0700] [Worker-659:org.eclipse.persistence.transaction] [ ] 2017-09-01 10:01:04.929--UnitOfWork(122187888)--Thread(Thread[Worker-659,5,main])-- resume unit of work 
TRACE [2017-09-01 10:01:04.929/-0700] [Worker-659:org.eclipse.persistence.transaction] [ ] 2017-09-01 10:01:04.929--UnitOfWork(122187888)--Thread(Thread[Worker-659,5,main])-- release unit of work 
TRACE [2017-09-01 10:01:04.929/-0700] [Worker-659:org.eclipse.persistence.connection] [ ] 2017-09-01 10:01:04.929--ClientSession(436256688)--Thread(Thread[Worker-659,5,main])-- client released 
TRACE [2017-09-01 10:01:04.929/-0700] [Worker-659:org.eclipse.persistence.query] [ ] 2017-09-01 10:01:04.929--UnitOfWork(122187888)--Thread(Thread[Worker-659,5,main])-- Execute query ReadAllQuery(...) 
TRACE [2017-09-01 10:01:04.929/-0700] [Worker-659:org.eclipse.persistence.connection] [ ] 2017-09-01 10:01:04.929--ServerSession(441145695)--Connection(985262420)--Thread(Thread[Worker-659,5,main])-- Connection acquired from connection pool [default]. 
TRACE [2017-09-01 10:01:04.961/-0700] [Worker-659:org.eclipse.persistence.connection] [ ] 2017-09-01 10:01:04.961--ServerSession(441145695)--Connection(985262420)--Thread(Thread[Worker-659,5,main])-- Connection released to connection pool [default]. 
WARN [2017-09-01 10:01:04.961/-0700] [Worker-659:org.eclipse.persistence] [ ] 2017-09-01 10:01:04.961--UnitOfWork(122187888)--Thread(Thread[Worker-659,5,main])-- 
Local Exception Stack: 
Exception [EclipseLink-4005] (Eclipse Persistence Services - 2.4.2.v20130514-5956486): org.eclipse.persistence.exceptions.DatabaseException 
Exception Description: DatabaseAccessor not connected. 
    at org.eclipse.persistence.exceptions.DatabaseException.databaseAccessorNotConnected(DatabaseException.java:116) 
    at org.eclipse.persistence.internal.databaseaccess.DatasourceAccessor.incrementCallCount(DatasourceAccessor.java:309) 
    at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.basicExecuteCall(DatabaseAccessor.java:581) 
    at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.executeCall(DatabaseAccessor.java:537) 
    at org.eclipse.persistence.internal.sessions.AbstractSession.basicExecuteCall(AbstractSession.java:1805) 
    at org.eclipse.persistence.sessions.server.ServerSession.executeCall(ServerSession.java:566) 
(..) 

接続が切断される他の理由はありますか。

Answer 1

私自身の質問に答えることができますので、他の人が私の発見の恩恵を受けることができます。

この問題は、Eclipse Linkのバグが原因であることが判明しました。まだ開かれているときはbug 432410を参照してください。

私の特定のケースでのソリューションを使用すると、エラーに至るまで何が起こっているかを確認するためにログオン回してみてください、テスト環境でそれを再現することができますので、接続はすなわちEntityManager.unwrap(Connection.class)