I didn't researched fully yet about Hibernate and Hibernate Annotations bugs, but this is quite interesting.

Scenario:

I've created a sample instance of ItemTax entity to be added as a criteria's example instance for Hibernate to search from the database. I've already done this for about 5 times. All other statements were successful using this approach, but when I called the Criteria.list() for the sixth time, my program just hangs up. When I debug my program, Hibernate calls up CriteriaImpl.list() method. Here's where the actual hanging up occurred:



If I were to view this line internally, here's what I've found:

in AbstractBatcher.prepareQueryStatement() method:


On instiation of the PreparedStatement, my program hangs up. At this current situation, Eclipse (v 3.2) shows that 17 threads in total. The AWT-EventQueue-0 (main thread) has the status "Stepping". Total of 6 Timers included. 4 threads for the EHCache. 3 ThreadPoolAsynchronousRunner$PoolThread running.

Hibernate version: 3.2 cr2
Hibernate Annotation version: 3.2.0.CR1

Mapping documents:

Parts entity:
@OneToMany(
fetch = FetchType.LAZY,
cascade = {CascadeType.PERSIST, CascadeType.MERGE},
targetEntity = ItemTax.class,
mappedBy = "itemId"
)
public List<ItemTax> getPartTax() {
return partTax;
}

ItemTax entity:

@ManyToOne(
fetch = FetchType.LAZY,
cascade = {CascadeType.PERSIST, CascadeType.MERGE},
targetEntity = Parts.class
)
@JoinColumn(name = "item_id", nullable = false, unique = false)
@Max(11)
public Parts getItemId() {
return itemId;
}

@ManyToOne(
fetch = FetchType.LAZY,
cascade = {CascadeType.PERSIST, CascadeType.MERGE, CascadeType.ALL},
targetEntity = Tax.class
)
@JoinColumn(name = "tax_id", nullable = false, unique = false)
@Max(11)
public Tax getTaxId() {
return taxId;
}

Tax entity:

@OneToMany(
fetch = FetchType.LAZY,
cascade = {CascadeType.PERSIST, CascadeType.MERGE},
targetEntity = ItemTax.class,
mappedBy = "taxId"
)
public List<ItemTax> getItemTax() {
return itemTax;
}


Code between sessionFactory.openSession() and session.close():

Criteria crit = getSession().createCriteria(getPersistentClass());
Example example = Example.create(exampleInstance);
for (String exclude : excludeProperty) {
example.excludeProperty(exclude);
}
crit.add(example);
return crit.list();


Full stack trace of any exception that occurs:NO EXCEPTIONS THROWN

Name and version of the database you are using:
MySQL 5.0.22-Debian_1.dotdeb.1
MySQL Connector/J 5.0.3 GA

The generated SQL (show_sql=true):

Hibernate:
select
tax0_.id as id8_0_,
tax0_.control as control8_0_,
tax0_.notes as notes8_0_,
tax0_.chart_id as chart4_8_0_,
tax0_.rate as rate8_0_,
tax0_.taxgroup as taxgroup8_0_,
tax0_.taxnumber as taxnumber8_0_
from
ck_tax tax0_
where
tax0_.id=?


Last Debug level Hibernate log excerpt:

07:24:50,072 DEBUG AbstractBatcher:476 - preparing statement
07:24:50,102 DEBUG GooGooStatementCache:381 - cxnStmtMgr.statementSet( com.mysql.jdbc.Connection@13de2bd ).size(): 2
07:24:50,112 DEBUG GooGooStatementCache:117 - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 19; checked out: 1; num connections: 6; num keys: 19
07:24:50,112 DEBUG IntegerType:80 - binding '10445' to parameter: 1
07:24:50,122 DEBUG AbstractBatcher:374 - about to open ResultSet (open ResultSets: 0, globally: 0)
07:24:50,122 DEBUG Loader:682 - processing result set
07:24:50,122 DEBUG Loader:687 - result set row: 0
07:24:50,122 DEBUG Loader:1164 - result row: EntityKey[com.manageduptime.erp.entity.Tax#10445]
07:24:50,142 DEBUG Loader:1347 - Initializing object from ResultSet: [com.manageduptime.erp.entity.Tax#10445]
07:24:50,142 DEBUG AbstractEntityPersister:1944 - Hydrating entity: [com.manageduptime.erp.entity.Tax#10445]
07:24:50,162 DEBUG IntegerType:122 - returning '100' as column: control8_0_
07:24:50,172 DEBUG StringType:116 - returning null as column: notes8_0_
07:24:50,172 DEBUG IntegerType:122 - returning '0' as column: chart4_8_0_
07:24:50,172 DEBUG DoubleType:122 - returning '0.08' as column: rate8_0_
07:24:50,172 DEBUG StringType:122 - returning 'ar' as column: taxgroup8_0_
07:24:50,172 DEBUG StringType:122 - returning 'CA PST collected on sales (from customer)' as column: taxnumber8_0_
07:24:50,182 DEBUG Loader:709 - done processing result set (1 rows)
07:24:50,182 DEBUG AbstractBatcher:381 - about to close ResultSet (open ResultSets: 1, globally: 1)
07:24:50,182 DEBUG AbstractBatcher:366 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
07:24:50,192 DEBUG AbstractBatcher:525 - closing statement
07:24:50,192 DEBUG GooGooStatementCache:171 - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 19; checked out: 0; num connections: 6; num keys: 19
07:24:50,192 DEBUG Loader:839 - total objects hydrated: 1
07:24:50,192 DEBUG TwoPhaseLoad:107 - resolving associations for [com.manageduptime.erp.entity.Tax#10445]
07:24:50,202 DEBUG CollectionLoadContext:141 - creating collection wrapper:[com.manageduptime.erp.entity.Tax.itemTax#10445]
07:24:50,202 DEBUG TwoPhaseLoad:206 - done materializing entity [com.manageduptime.erp.entity.Tax#10445]
07:24:50,202 DEBUG StatefulPersistenceContext:748 - initializing non-lazy collections
07:24:50,202 DEBUG Loader:1808 - done entity load
07:24:50,202 DEBUG SessionImpl:222 - opened session at timestamp: 4743591895867392
07:24:50,212 DEBUG SessionImpl:222 - opened session at timestamp: 4743591895908352
07:24:50,222 DEBUG DefaultLoadEventListener:154 - loading entity: [com.manageduptime.erp.entity.Parts#30010]
07:24:50,222 DEBUG DefaultLoadEventListener:235 - creating new proxy for entity
07:24:50,242 DEBUG JDBCContext:226 - after autocommit
07:24:50,242 DEBUG ConnectionManager:398 - aggressively releasing JDBC connection
07:24:50,242 DEBUG SessionImpl:424 - after transaction completion
07:33:15,939 DEBUG AbstractBatcher:358 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
07:33:30,740 DEBUG ConnectionManager:415 - opening JDBC connection
07:33:30,760 DEBUG BasicResourcePool:942 - awaitAvailable(): com.mchange.v2.c3p0.impl.NewPooledConnection@1cd427a
07:33:30,780 DEBUG BasicResourcePool:1159 - trace com.mchange.v2.resourcepool.BasicResourcePool@1249e1a [managed: 6, unused: 0, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@1cd427a)

Hi. It looks very much like you are simply exhausting the Connection pool. Your last log entries shows a c3p0 pool with all Connections checked out, and a thread awaiting a Connection. The code that you excerpt from AbstractBatcher shows where Connections are being checked out from the connection pool. It'd be good to understand where they are being checked in. [It should be a call somewhere to connectionManager.closeConnection( conn ) or something like that.]

Others here can comment on hibernate best practices... I'm a hibernate neophyte. But one way or another, you'll want to modify your application so that it doesn't need to have more than maxPoolSize Connections checked out at once. You can resolve this by allowing the Connection pool to grow much larger than 6 Connections. Or, probably better, you can modify your application so that multiple Connections aren't checked out in performing a set of operations in which no Connections are returned to the pool until all operations have completed.

Good luck!
Steve

Does Hibernate's C3P0 connection pooling uses the maximum number of connections on multiple SQL queries? I know Hibernate uses multithreading.

By the way, thanks for the tip. But what I did was I used ScrollableResults of Hibernate and setCacheable(true). What matters now is how I parse the returned results.

Thanks again!

Well swaldman, I guess you're right. Exhausting connection to database hangs up my program. All that remains running is this:

03:25:09,768 DEBUG BasicResourcePool:1286 - Checking for expired resources - Thu Sep 14 03:25:09 GMT+08:00 2006 [com.mchange.v2.resourcepool.BasicResourcePool@180f96c]
03:25:11,020 DEBUG BasicResourcePool:1286 - Checking for expired resources - Thu Sep 14 03:25:11 GMT+08:00 2006 [com.mchange.v2.resourcepool.BasicResourcePool@180f96c]
03:25:12,272 DEBUG BasicResourcePool:1286 - Checking for expired resources - Thu Sep 14 03:25:12 GMT+08:00 2006 [com.mchange.v2.resourcepool.BasicResourcePool@180f96c]
03:25:13,523 DEBUG BasicResourcePool:1286 - Checking for expired resources - Thu Sep 14 03:25:13 GMT+08:00 2006 [com.mchange.v2.resourcepool.BasicResourcePool@180f96c]
03:25:14,775 DEBUG BasicResourcePool:1286 - Checking for expired resources - Thu Sep 14 03:25:14 GMT+08:00 2006 [com.mchange.v2.resourcepool.BasicResourcePool@180f96c]
03:25:16,047 DEBUG BasicResourcePool:1286 - Checking for expired resources - Thu Sep 14 03:25:16 GMT+08:00 2006 [com.mchange.v2.resourcepool.BasicResourcePool@180f96c]
03:25:17,299 DEBUG BasicResourcePool:1286 - Checking for expired resources - Thu Sep 14 03:25:17 GMT+08:00 2006 [com.mchange.v2.resourcepool.BasicResourcePool@180f96c]
03:25:18,551 DEBUG BasicResourcePool:1286 - Checking for expired resources - Thu Sep 14 03:25:18 GMT+08:00 2006 [com.mchange.v2.resourcepool.BasicResourcePool@180f96c]
03:25:19,802 DEBUG BasicResourcePool:1286 - Checking for expired resources - Thu Sep 14 03:25:19 GMT+08:00 2006 [com.mchange.v2.resourcepool.BasicResourcePool@180f96c]
03:25:21,054 DEBUG BasicResourcePool:1286 - Checking for expired resources - Thu Sep 14 03:25:21 GMT+08:00 2006 [com.mchange.v2.resourcepool.BasicResourcePool@180f96c]
03:25:22,306 DEBUG BasicResourcePool:1286 - Checking for expired resources - Thu Sep 14 03:25:22 GMT+08:00 2006 [com.mchange.v2.resourcepool.BasicResourcePool@180f96c]
03:25:23,558 DEBUG BasicResourcePool:1286 - Checking for expired resources - Thu Sep 14 03:25:23 GMT+08:00 2006 [com.mchange.v2.resourcepool.BasicResourcePool@180f96c]
03:25:24,810 DEBUG BasicResourcePool:1286 - Checking for expired resources - Thu Sep 14 03:25:24 GMT+08:00 2006 [com.mchange.v2.resourcepool.BasicResourcePool@180f96c]
03:25:26,061 DEBUG BasicResourcePool:1286 - Checking for expired resources - Thu Sep 14 03:25:26 GMT+08:00 2006 [com.mchange.v2.resourcepool.BasicResourcePool@180f96c]

When I use the MySQL Administrator GUI admin program, I found out that although C3P0 reuse some of the available connections from the pool, more other were being left in the sleeping state. Prior to this, what C3P0 is doing is that it creates new instances of connection to manage. Therefore, more were being left unused.

Please, anyone, how can I resolve this issue?

Debug application, application code must close all unsed connections ("session.close()" closes connection too).

Increasing the connection pool capacity doesn't work for me. I tried looking for an alternative, and I found out that Hibernate supports Apache Commons DBCP. DBCP has a mechanism that when all connections are not available, it does not reuse it. Instead, DBCP disconnects all the connections, then creates 1-2 connections or whichever is needed.

Thanks for you help!