0

I am using c3p0 0.9.2.1, GWT 2.6.0, SQLServer 2012.

I am getting an intermittent stackTrace from c3p0

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

So, its telling me I havent finished with the connection within the timeout I have specified 

<property name="hibernate.c3p0.debugUnreturnedConnectionStackTraces" value="true" />
<property name="hibernate.c3p0.unreturnedConnectionTimeout" value="10" />

I fail to understand how this is possible. My code is very simple...

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

On start up, 25 threads startup, each calling getSomeQueueData(). About 1/10 times it fails. I check the debug output and find that every thread has successfully entered and exited the method within a couple of seconds as expected, so why is c3p0 telling me that the connection is still in use? Just to clarify, the @Transactional is guice, not spring.

---EDIT--- I have spent many hours investigating this issue and it only becomes more puzzling....

I have also updated c3p0 to 0.9.5

The @Transactional seems erratic for some reason. Once in a while it doesnt get called. I inspect the stack trace of every method that passes through my DAO and every so often, it indicates that the interceptor processing has been skipped??.

In my DAO I have a getSession() method, and when I add an arbitrary sleep of 100ms , then almost every stackTrace indicates that the annotation has been skipped.

Additionally, these settings make the problem happen almost every time

<property name="hibernate.c3p0.maxPoolSize" value="20" />
<property name="hibernate.c3p0.minPoolSize" value="1" />
<property name="hibernate.c3p0.numHelperThreads" value="1" />

...these settings make the problem happen very rarely

<property name="hibernate.c3p0.maxPoolSize" value="20" />
<property name="hibernate.c3p0.minPoolSize" value="20" />
<property name="hibernate.c3p0.numHelperThreads" value="20" />

And removing c3p0 altogether seems to fix the problem completely as far as my testing reveals.

I have read that the use of finally is something to beware of for cases where reflection us used by guice and I have been careful to avoid that. The symptoms are too bizarre for me to narrow it down. Sometimes it seems like guice is not binding my class correctly, sometimes it seems like a c3p0 error.

Oh, I have checked that I am using com.google.inject.persist.Transactional.

user2046211
  • 356
  • 1
  • 4
  • 20
  • Do you call `close()` on your Session at some point? – David Levesque Feb 03 '15 at 16:29
  • This is a Java issue and not related in any way to GWT. update your tag to increase your chances to get an unswer. – Momo Feb 03 '15 at 19:54
  • I dont call close() because Transactional should take care of session management. I thought it might be related to GWT if Transactional is not behaving as I expect. I will add a java tag. Thanks. – user2046211 Feb 03 '15 at 20:20
  • What is the package of the Transactional annotation in your imports? – David Levesque Feb 03 '15 at 21:29
  • I dont have code with me but I think its com.google.inject.persist. I guess I should really state the Transactional is related to google guice rather than gwt. – user2046211 Feb 03 '15 at 21:36

1 Answers1

0

Having tried an alternative pooling library without resolving the problem, I turned my attention to dependency injection. I think the problem is related to code existing in the constructor of a guice managed class. If the effects of that code has the potential to call methods marked as @Transactional, then this problem can occur where the transactional annotation is "skipped".

This seems to make sense to me, so I have moved this from the constructor. I will keep monitoring it for a while before Im convinced this is the solution.

user2046211
  • 356
  • 1
  • 4
  • 20