c3p0:JDBC DataSources/Resource Pools / Bugs / #32 cached statements closing connections prematurely

Steve Waldman - 2006-09-07

Logged In: YES
user_id=175530

[i'm sorry this has gone unanswered or addressed for so
long. i'm puzzled by the stack trace, line 1682 of
c3p0-0.9.1-pre5a falls in addBatch (which should complain
about being called if its parent Connection has been
called), not in close() which should not. it's interesting
that statement caching seems to be involved; nothing in your
stack traces seems to hint that. if you still see this
problem when you turn statement caching on, can you try it
with the most recent version, and if the problem persists,
send along more information (including the irrelevant parts
of stack traces you omitted, so i can try to get some better
sense of what's going on, and c3p0's version banner and
configuration dump.) Thanks, and sorry again.]

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Hugo - 2006-10-06

Logged In: YES
user_id=1613706

I do have a similar behavior with the C3P0-0_9_1-pre9
version (and hibernate 3.1 too):

It seems to occur mainly under heavy load (8 connections
creation in few seconds)

connection creation timestamp:

[- CONNECTION CREATION TIMESTAMP -]

INFO [RMI TCP Connection(176)-10.0.0.36] TISRepository () -
2006-10-06 13:57:31,843 - Create new session for thread RMI
TCP Connection(176)-10.0.0.36

INFO [RMI TCP Connection(176)-10.0.0.36] TISRepository () -
2006-10-06 13:57:42,109 - Create new TEMPORARY session for
thread RMI TCP Connection(176)-10.0.0.36

INFO [RMI TCP Connection(180)-10.0.0.36] TISRepository () -
2006-10-06 13:58:12,515 - Create new session for thread RMI
TCP Connection(180)-10.0.0.36

INFO [RMI TCP Connection(184)-10.0.0.36] TISRepository () -
2006-10-06 13:58:53,062 - Create new session for thread RMI
TCP Connection(184)-10.0.0.36

INFO [RMI TCP Connection(199)-10.0.0.36] TISRepository () -
2006-10-06 14:01:18,703 - Create new session for thread RMI
TCP Connection(199)-10.0.0.36

INFO [RMI TCP Connection(199)-10.0.0.36] TISRepository () -
2006-10-06 14:01:30,281 - Create new TEMPORARY session for
thread RMI TCP Connection(199)-10.0.0.36

INFO [RMI TCP Connection(205)-10.0.0.36] TISRepository () -
2006-10-06 14:02:22,921 - Create new session for thread RMI
TCP Connection(205)-10.0.0.36

INFO [RMI TCP Connection(209)-10.0.0.36] TISRepository () -
2006-10-06 14:02:35,609 - Create new session for thread RMI
TCP Connection(209)-10.0.0.36

[- STACK TRACE -]

org.hibernate.exception.GenericJDBCException: could not
execute query

at
org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:103)

at
org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:91)

at
org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:43)

at
org.hibernate.loader.Loader.doList(Loader.java:2148)

at
org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2029)

at
org.hibernate.loader.Loader.list(Loader.java:2024)

at
org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:375)

at
org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:308)

at
org.hibernate.engine.query.HQLQueryPlan.performList(HQLQueryPlan.java:153)

at
org.hibernate.impl.SessionImpl.list(SessionImpl.java:1106)

at
org.hibernate.impl.QueryImpl.list(QueryImpl.java:79)

at
com.temis.idm.tis.document.data.impl.AnalysisDAO.getAnnotationOccurrences(AnalysisDAO.java:1305)

at
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)

at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

at java.lang.reflect.Method.invoke(Method.java:324)

at
sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:261)

at
sun.rmi.transport.Transport$1.run(Transport.java:148)

at
java.security.AccessController.doPrivileged(Native Method)

at
sun.rmi.transport.Transport.serviceCall(Transport.java:144)

at
sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:460)

at
sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:701)

at java.lang.Thread.run(Thread.java:534)

Caused by: java.sql.SQLException: You can't operate on a
closed Statement!!!

at
com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:106)

at
com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:65)

at
com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:85)

at
org.hibernate.jdbc.AbstractBatcher.getResultSet(AbstractBatcher.java:139)

at
org.hibernate.loader.Loader.getResultSet(Loader.java:1669)

at
org.hibernate.loader.Loader.doQuery(Loader.java:662)

at
org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:224)

at
org.hibernate.loader.Loader.doList(Loader.java:2145)

... 19 more

Caused by: java.lang.NullPointerException

at
com.mchange.v2.c3p0.impl.NewProxyResultSet.attach(NewProxyResultSet.java:3690)

at
com.mchange.v2.c3p0.impl.NewProxyResultSet.<init>(NewProxyResultSet.java:3702)

at
com.mchange.v2.c3p0.impl.NewProxyResultSet.<init>(NewProxyResultSet.java:3714)

at
com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:79)

... 24 more

Hope this help,

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Steve Waldman - 2006-10-06

Logged In: YES
user_id=175530

Hugo,

Can you check whether the behavior you're observing under
c3p0-0.9.1-pre9 only occurs with statement caching enabled?
The exception you are seeing is generated by the proxy
statement, that wraps the cached statement, so it's not as
one might guess a matter of the statement cache prematurely
closing a Statement. Instead it looks as though the (proxy)
Connection was closed concurrently with a call to
executeQuery. The query succeeds, but the attempt to make a
result set fails, as the result set tries to associate
itself with a Connection now null. But close()ing the
Connection before a query executed on a statement completes
would be a pretty bad hibernate bug. I doubt it would only
show up with c3p0. It's interesting that you observe this
primarily after a burst of Connection acquisitions. Perhaps
this occurs after c3p0 has decided an error indicates that
all pooled Connections must be replaced? c3p0 should not
abruptly close checked-out Connections, even in this case
though. (I should log a message at WARNING when c3p0
refreshes the pool due to an error that it takes to mean
pool corruption. Right now, neither you or I would ever know.)

In both reports, there is no obvious relationship between
what's visible in the stack traces and the statement cache.
So, I'd be very curious to know whether the behavior goes
away with maxStatements / maxStatementsPerConnection both
set to 0.

Is this easy to reproduce? If I send you a modified version
of the library with some extra debugging gunk to test some
guesses, would you be able to try it, and likely to observe
the problem?

Thanks for the report, and any more information you can offer!

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Hugo - 2006-10-06

Logged In: YES
user_id=1613706

It occurs with c3p0.max_statements=0. I didn't try with
maxStatementsPerConnection=0 yet, but will try next.

It's not so easy to reproduce since it occurs randomly, but
still quite often (once a day I will say). So feel free to
send me a modified version, so we could get more informations.

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Hugo - 2006-10-06

Logged In: YES
user_id=1613706

By the way what is the correct spelling of the parameters ?
(I'm using hibernate)

c3p0.maxStatements
c3p0.max_Statements
hibernate.c3p0.maxStatements
hibernate.c3p0.max_Statements ?

and the same question for maxStatementsPerConnection.

Maybe it is just a bad spelling problem...

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Steve Waldman - 2006-10-06

Logged In: YES
user_id=175530

Hugo,

The c3p0 parameters are c3p0.maxStatements and
c3p0.maxStatementsPerConnection. But the way hibernate wraps
c3p0 (I've proposed this be changed in a nondisruptive way
several times, but so far it hasn't happened), several
parameters must be set in hibernate's config (rather than a
c3p0.properties file), and these parameters have hibernate
specific names. So, for hibernate users, it's
hibernate.c3p0.max_statements. maxStatementsPerConnection is
not hibernate-managed, so to set that, you must defined a
c3p0.properties file (or c3p0-config.xml), and set the
property c3p0.maxStatementsPerConnection. See the c3p0's
docs for the meaning of all parameters, and information on
which parameters must be set hibernate's way, and which (all
the rest) must be set c3p0's way in a hibernate app.

(Sorry for the confusion. I really do hope this annoyingness
gets resolved, but it's not something I can do unilaterally.)

smiles,
Steve

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Hugo - 2006-10-06

Logged In: YES
user_id=1613706

Ok. It's seems I messed up a little bit with my
configuration files.

I cleaned that, and FYI now I use the following configuration:

[hibernate.cfg.xml]
<property name="hibernate.c3p0.min_size">1</property>
<property name="hibernate.c3p0.max_size">100</property>
<property name="hibernate.c3p0.timeout">1200</property>
<property name="hibernate.c3p0.idle_test_period">600</property>
<property name="hibernate.c3p0.max_statements">0</property>

[c3p0.properties]
c3p0.maxStatementsPerConnection=0
c3p0.breakAfterAcquireFailure=true
c3p0.acquireRetryAttempts=3
c3p0.acquireIncrement=2
c3p0.automaticTestTable=C3P0TestTable

Maybe the error will disapear with this config...

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Nobody/Anonymous - 2006-10-18

Logged In: NO

Just to let you know that I still have the problem with the
parameters set this way.

For the moment I will desactivate the connection pool.

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

cached statements closing connections prematurely

Group

Searches

Help

#32 cached statements closing connections prematurely

Discussion