c3p0 0.9.2.1、GWT 2.6.0、SQLServer 2012 を使用しています。
c3p0 から断続的な stackTrace を取得しています
[2015-Feb-03 16:30:12] - [INFO ] - A checked-out resource is overdue, and will be destroyed: com.mchange.v2.c3p0.impl.NewPooledConnection@14bc0e
[2015-Feb-03 16:30:12] - [INFO ] - Logging the stack trace by which the overdue resource was checked-out.
java.lang.Exception: DEBUG STACK TRACE: Overdue resource check-out stack trace.
at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:555)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutAndMarkConnectionInUse(C3P0PooledConnectionPool.java:755)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:682)
at com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getConnection(AbstractPoolBackedDataSource.java:140)
at org.hibernate.c3p0.internal.C3P0ConnectionProvider.getConnection(C3P0ConnectionProvider.java:89)
at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:380)
at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:228)
at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.getConnection(LogicalConnectionImpl.java:171)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.connection(StatementPreparerImpl.java:63)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:162)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:186)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:160)
at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1884)
at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1861)
at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1838)
at org.hibernate.loader.Loader.doQuery(Loader.java:909)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:354)
at org.hibernate.loader.Loader.doList(Loader.java:2551)
at org.hibernate.loader.Loader.doList(Loader.java:2537)
at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2367)
at org.hibernate.loader.Loader.list(Loader.java:2362)
at org.hibernate.loader.criteria.CriteriaLoader.list(CriteriaLoader.java:126)
at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1678)
at org.hibernate.internal.CriteriaImpl.list(CriteriaImpl.java:380)
at net.impro.portal.server.model.dao.CommsQueueDaoImpl.getOldestRecords(CommsQueueDaoImpl.java:54)
at net.impro.portal.server.engine.uploader.AbstractBiometricUploader.getOldestRecords(AbstractBiometricUploader.java:217)
at net.impro.portal.server.engine.uploader.UploaderMorpho$$EnhancerByGuice$$9212bdc2.getOldestRecords(<generated>)
at net.impro.portal.server.engine.uploader.AbstractUploader.getSomeQueueData(AbstractUploader.java:222)
at net.impro.portal.server.engine.uploader.UploaderMorpho$$EnhancerByGuice$$9212bdc2.getSomeQueueData(<generated>)
at net.impro.portal.server.engine.uploader.AbstractBiometricUploader.processLoop(AbstractBiometricUploader.java:92)
at net.impro.portal.server.engine.uploader.AbstractUploader.run(AbstractUploader.java:172)
at java.lang.Thread.run(Unknown Source)
つまり、指定したタイムアウト内に接続が完了していないことがわかります
<property name="hibernate.c3p0.debugUnreturnedConnectionStackTraces" value="true" />
<property name="hibernate.c3p0.unreturnedConnectionTimeout" value="10" />
これがどのように可能であるかを理解できません。私のコードは非常に単純です...
@Transactional
protected void getSomeQueueData() {
logger.error("+Entered Thread " + Thread.currentThread());
//A little clumsy here but I dont see anything wrong
final CommsQueueDao commsQueueDao = InjectHelp.requestNewInstance(CommsQueueDao.class);
List<CommsQueue> qData = getOldestRecords(commsQueueDao, MAX_LOCAL_QUEUE_SIZE);
Iterator<CommsQueue> iterator = qData.iterator();
//Iterate the result, pack it into a local queue
//...
logger.error("-Exit Thread " + Thread.currentThread() + " " + stuffToSend.size());
}
@Transactional
protected List<CommsQueue> getOldestRecords(CommsQueueDao qDao, int fetchSize) {
return qDao.getOldestRecords(getBioAddress(), fetchSize);
}
//FROM MY DAO CLASS
public List<CommsQueue> getOldestRecords(BioAddress bioAddress, int maxRecords) {
Criteria cr = getSession().createCriteria(CommsQueue.class);
cr.add(Restrictions.eq("bioAddress", bioAddress));
cr.addOrder(Order.asc("id"));
cr.setMaxResults(maxRecords);
return cr.list();
}
起動時に、25 個のスレッドが起動し、それぞれが getSomeQueueData() を呼び出します。約 1/10 の確率で失敗します。デバッグ出力を確認すると、予想どおり数秒以内にすべてのスレッドが正常にメソッドに出入りしたことがわかりました。明確にするために、 @Transactional は春ではなく装いです。
---編集--- 私はこの問題を調査するのに何時間も費やしましたが、さらに不可解になるだけです....
また、c3p0 を 0.9.5 に更新しました。
@Transactional は、何らかの理由で不安定なようです。たまに呼ばれません。DAO を通過するすべてのメソッドのスタック トレースを調べると、インターセプターの処理がスキップされていることがよくあります??.
私の DAO には getSession() メソッドがあり、100ms の任意のスリープを追加すると、ほぼすべての stackTrace が注釈がスキップされたことを示します。
さらに、これらの設定により、ほぼ毎回問題が発生します
<property name="hibernate.c3p0.maxPoolSize" value="20" />
<property name="hibernate.c3p0.minPoolSize" value="1" />
<property name="hibernate.c3p0.numHelperThreads" value="1" />
...これらの設定により、問題が発生することはほとんどありません
<property name="hibernate.c3p0.maxPoolSize" value="20" />
<property name="hibernate.c3p0.minPoolSize" value="20" />
<property name="hibernate.c3p0.numHelperThreads" value="20" />
また、c3p0 を完全に削除すると、テストで明らかになった限り、問題が完全に解決するようです。
finally の使用は、リフレクションが偽装で使用された場合に注意する必要があることを読んだことがあり、それを避けるように注意してきました。症状が奇妙すぎて絞り込めません。guice がクラスを正しくバインドしていないように見える場合もあれば、c3p0 エラーのように見える場合もあります。
ああ、com.google.inject.persist.Transactional を使用していることを確認しました。