Translated message

A translation of this page exists in English.

EAP 6 で警告メッセージ Thread waiting for lock during cleanup と Lock owned during cleanup が表示される

Solution Unverified - Updated -

Environment

  • Red Hat JBoss Enterprise Application Platform (EAP) 6

Issue

サーバーログに、以下の 2 つの警告メッセージが対になって表示されます。

WARN  [org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory] (http-/10.1.2.3:8080-1) Lock owned during cleanup: java.lang.Throwable:Lock owned during cleanup
    at java.net.SocketInputStream.socketRead0(Native Method) [rt.jar:1.6.0_26]
    at java.net.SocketInputStream.read(SocketInputStream.java:129) [rt.jar:1.6.0_26]
    at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114) [mysql-connector-java-5.1.25.jar:]
    at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161) [mysql-connector-java-5.1.25.jar:]
    at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189) [mysql-connector-java-5.1.25.jar:]
    at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3116) [mysql-connector-java-5.1.25.jar:]
    at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3570) [mysql-connector-java-5.1.25.jar:]
    at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3559) [mysql-connector-java-5.1.25.jar:]
    at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4110) [mysql-connector-java-5.1.25.jar:]
    at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2570) [mysql-connector-java-5.1.25.jar:]
    at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2731) [mysql-connector-java-5.1.25.jar:]
    at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2815) [mysql-connector-java-5.1.25.jar:]
    at com.mysql.jdbc.LoadBalancedMySQLConnection.execSQL(LoadBalancedMySQLConnection.java:158) [mysql-connector-java-5.1.25.jar:]
    at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2155) [mysql-connector-java-5.1.25.jar:]
    at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:2322) [mysql-connector-java-5.1.25.jar:]
    at com.mysql.jdbc.JDBC4PreparedStatement.executeQuery(JDBC4PreparedStatement.java) [mysql-connector-java-5.1.25.jar:]
    at org.jboss.jca.adapters.jdbc.CachedPreparedStatement.executeQuery(CachedPreparedStatement.java:107)
    at org.jboss.jca.adapters.jdbc.jdk6.CachedPreparedStatementJDK6.executeQuery(CachedPreparedStatementJDK6.java)
    at org.jboss.jca.adapters.jdbc.WrappedPreparedStatement.executeQuery(WrappedPreparedStatement.java:462)
    at org.jboss.jca.adapters.jdbc.jdk6.WrappedPreparedStatementJDK6.executeQuery(WrappedPreparedStatementJDK6.java)
    at org.hibernate.jdbc.AbstractBatcher.getResultSet(AbstractBatcher.java:208) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
    at org.hibernate.loader.Loader.getResultSet(Loader.java:1953) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
    at org.hibernate.loader.Loader.doQuery(Loader.java:802) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
    at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:274) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
    at org.hibernate.loader.Loader.loadEntity(Loader.java:2037) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
    at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:86) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
    at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:76) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
    at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3293) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
    at org.hibernate.event.def.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:496) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
    at org.hibernate.event.def.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:477) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
    at org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:227) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
    at org.hibernate.event.def.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:285) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
    at org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:152) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
        ...
        at com.example.some.Code.method()
        ...

および

WARN  [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (http-/10.1.2.3:8080-1) IJ000607:ResourceException cleaning up managed connection: org.jboss.jca.core.connectionmanager.listener.NoTxConnectionListener@76594b28[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@7a1ea03b connection handles=0 lastUse=1377351353808 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@1e6f9a58 pool internal context=SemaphoreArrayListManagedConnectionPool@14c5d02c[pool=MyDataSource]]: javax.resource.ResourceException:Still active locks
    at org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnection.cleanup(BaseWrapperManagedConnection.java:356)
    at org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreArrayListManagedConnectionPool.returnConnection(SemaphoreArrayListManagedConnectionPool.java:436)
    at org.jboss.jca.core.connectionmanager.pool.AbstractPool.returnConnection(AbstractPool.java:561)
    at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.returnManagedConnection(AbstractConnectionManager.java:425)
    at org.jboss.jca.core.connectionmanager.listener.NoTxConnectionListener.connectionClosed(NoTxConnectionListener.java:90)
    at org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnection.closeHandle(BaseWrapperManagedConnection.java:557)
    at org.jboss.jca.adapters.jdbc.WrappedConnection.close(WrappedConnection.java:264)
    at org.jboss.jca.adapters.jdbc.jdk6.WrappedConnectionJDK6.close(WrappedConnectionJDK6.java)
    at org.hibernate.connection.DatasourceConnectionProvider.closeConnection(DatasourceConnectionProvider.java:97) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
    at org.hibernate.jdbc.ConnectionManager.closeConnection(ConnectionManager.java:474) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
    at org.hibernate.jdbc.ConnectionManager.aggressiveRelease(ConnectionManager.java:429) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
    at org.hibernate.jdbc.ConnectionManager.afterStatement(ConnectionManager.java:304) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
    at org.hibernate.jdbc.AbstractBatcher.closePreparedStatement(AbstractBatcher.java:572) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
    at org.hibernate.jdbc.AbstractBatcher.closeStatement(AbstractBatcher.java:291) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
    at org.hibernate.jdbc.AbstractBatcher.closeQueryStatement(AbstractBatcher.java:307) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
    at org.hibernate.jdbc.AbstractBatcher.closeQueryStatement(AbstractBatcher.java:234) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
    at org.hibernate.loader.Loader.doQuery(Loader.java:854) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
    at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:274) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
    at org.hibernate.loader.Loader.loadEntity(Loader.java:2037) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
    at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:86) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
    at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:76) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
    at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3293) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
    at org.hibernate.event.def.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:496) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
    at org.hibernate.event.def.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:477) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
    at org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:227) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
    at org.hibernate.event.def.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:285) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
    at org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:152) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
        ...
        at com.example.other.Thing.method()
        ...

Resolution

接続が一度に複数のスレッドで使用されないようにします。この問題は、JBoss でデータソースの interleaving要素を使用すると発生することに注意してください。

関連情報については What does javax.resource.ResourceException: Still active locks mean in JBoss? を参照してください。

また、"Lock owned during cleanup" WARN during server/pool shutdown in EAP も併せて参照してください。

Root Cause

この警告メッセージは、接続が 2 つのスレッドに同時に使用されていることを示しています。2 つ目のスレッドが接続を閉じようとしていますが、アクティブなロックがあります。最初のスレッドが、 接続のロックを保持しています。

This solution is part of Red Hat’s fast-track publication program, providing a huge library of solutions that Red Hat engineers have created while supporting our customers. To give you the knowledge you need the instant it becomes available, these articles may be presented in a raw and unedited form.

Comments