DatabaseAccessor 在高负载情况下未连接答案

【问题标题】：DatabaseAccessor not connected in a high load scenarioDatabaseAccessor 在高负载情况下未连接
【发布时间】：2017-08-31 14:59:08
【问题描述】：

我在追查我们的应用程序中“EclipseLink-4005 (..) DatabaseAccessor not connected”错误的罪魁祸首时遇到了问题。它是一个独立的应用程序（不是 Web 应用程序），有多个线程连接到同一个数据库（Oracle）。我们使用默认设置的 EclipseLink 2.4.2 及其内部连接池。事务在应用程序中管理并且可以嵌套。该应用程序大部分时间都可以正常工作，但偶尔会在高负载下失败并出现“EclipseLink-4005 (..) DatabaseAccessor not connected”错误。

我能够在我们的测试环境中重现该错误，但无法理解它在什么条件下可能发生。一些事务是长期运行的。是否有可能其中一些超时，导致各自的会话注销并导致另一个线程中的错误？

以下是示例堆栈跟踪：

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），但在错误之前发生的唯一问题是 30 分钟前抛出的 OptimisticLockException，它由应用程序优雅地处理。而且，接下来的半个小时里，同样的连接被愉快地使用了，所以我不认为它被标记为无效。

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)
(..)

还有什么其他原因会断开连接吗？

【问题讨论】：

由于您可以在测试环境中重现它，因此请尝试打开登录以查看导致错误的原因。日志记录可能会减慢速度，因此如果是时间问题，可能会更难重现，但会为您提供每种情况的确切场景。另一件要尝试的事情是最新的 EclipseLink 版本，因为堆栈跟踪中涉及的类自 2.4.2 以来发生了一些变化。
谢谢@Chris，我按照建议启用了日志记录。为问题添加更多信息。

标签： java jpa eclipselink persistence toplink

【解决方案1】：

请允许我回答我自己的问题，以便其他人可以从我的发现中受益。

这个问题原来是由 Eclipse Link 中的错误引起的。请参阅bug 432410，在撰写本文时仍处于打开状态。

在我的特殊情况下，解决方案是避免打开连接，即不要调用EntityManager.unwrap(Connection.class)

【讨论】：