title: Slow Hibernate/C3P0 handling of non-slow Postgres SELECT
body: <p>A certain indexed SELECT query against a Postgres database takes a highly variable amount of time - from 50 msecs to multiple seconds, and very occasionally minutes, even under the lightest load.</p>
  
  <p>Our Postgres query log records anything over 10 msecs, but <strong>never</strong> records any of these. The EXPLAIN output suggests the query isn't particularly efficient, nonetheless it shouldn't be slow in this tiny database (000s of records), and we're trusting the Postgres logs.</p>
  
  <p>With our applications logs set to report <strong>all</strong> Hibernate, C3P0, and Spring/Spring Data logging (see version numbers at end), the evidence suggests this is very much a Hibernate/C3P0 issue, however, all the evidence from the logs suggests the pool size and utilisation is fine for the time being. Unfortunately we cannot drill down any further.</p>
  
  <p>Can you suggest an explanation for the 26 second gap?</p>
  
  <pre><code>10:19:29.149 DEBUG org.hibernate.SQL [I=9534] - select eventrepor0_.consortium_id as consorti1_3_3_, eventrepor0_.customer_resource_id as customer6_3_3_, eventrepor0_.item_type_id as item2_3_3_, eventrepor0_.reporting_date as reportin3_3_3_, eventrepor0_.event_subtype as event4_3_3_, eventrepor0_.event_count as event5_3_3_, customerre1_.id as id1_2_0_, customerre1_.customer_id as customer2_2_0_, customerre1_.resource_id as resource3_2_0_, resource2_.id as id1_8_1_, resource2_.data_type_id as data2_8_1_, resource2_.platform_id as platform5_8_1_, resource2_.prop_id as prop3_8_1_, resource2_.title as title4_8_1_, resource2_1_.doi as doi1_6_1_, resource2_1_.isbn as isbn2_6_1_, resource2_1_.online_issn as online3_6_1_, resource2_1_.print_issn as print4_6_1_, resource2_1_.publisher as publishe5_6_1_, resource2_1_.yop as yop6_6_1_, case when resource2_1_.id is not null then 1 when resource2_.id is not null then 0 end as clazz_1_, platform3_.id as id1_4_2_, platform3_.api_key as api2_4_2_, platform3_.platform_name as platform3_4_2_, hostnames4_.platform_id as platform1_4_5_, hostnames4_.hostname as hostname2_5_5_ from event_report eventrepor0_ inner join customer_resource customerre1_ on eventrepor0_.customer_resource_id=customerre1_.id left outer join resource resource2_ on customerre1_.resource_id=resource2_.id left outer join published_resource resource2_1_ on resource2_.id=resource2_1_.id left outer join platform platform3_ on resource2_.platform_id=platform3_.id left outer join platform_hostnames hostnames4_ on platform3_.id=hostnames4_.platform_id where eventrepor0_.consortium_id=? and eventrepor0_.customer_resource_id=? and eventrepor0_.item_type_id=? and eventrepor0_.reporting_date=? and eventrepor0_.event_subtype=?
  10:19:29.149 DEBUG c.m.v.a.ThreadPoolAsynchronousRunner [I=9534] - com.mchange.v2.async.ThreadPoolAsynchronousRunner@4ffa2724: Adding task to queue -- com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask@31e6b320
  10:19:29.149 DEBUG c.m.v.c3p0.stmt.GooGooStatementCache [I=9534] - CULLING: update event_report set event_count=event_count+1 where customer_resource_id=? and item_type_id=? and event_subtype=? and reporting_date=? and consortium_id=?
  10:19:29.149 DEBUG c.m.v.a.ThreadPoolAsynchronousRunner [I=9534] - com.mchange.v2.async.ThreadPoolAsynchronousRunner@4ffa2724: Adding task to queue -- com.mchange.v2.c3p0.stmt.GooGooStatementCache$StatementDestructionManager$1UncheckedStatementCloseTask@20fa1378
  10:19:29.149 DEBUG c.m.v.c3p0.stmt.GooGooStatementCache [I=9534] - cxnStmtMgr.statementSet( org.postgresql.jdbc4.Jdbc4Connection@38e040d2 ).size(): 5
  10:19:29.150 DEBUG c.m.v.c3p0.stmt.GooGooStatementCache [I=9534] - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 20; checked out: 5; num connections: 6; num keys: 20
  10:19:29.150 TRACE o.h.e.j.internal.JdbcCoordinatorImpl [I=9534] - Registering statement [com.mchange.v2.c3p0.impl.NewProxyPreparedStatement@7cc20161]
  10:19:29.150 TRACE o.h.e.j.internal.JdbcCoordinatorImpl [I=9534] - Registering last query statement [com.mchange.v2.c3p0.impl.NewProxyPreparedStatement@7cc20161]
  10:19:29.150 TRACE o.h.type.descriptor.sql.BasicBinder [I=9534] - binding parameter [1] as [VARCHAR] - 
  10:19:29.150 TRACE o.h.type.descriptor.sql.BasicBinder [I=9534] - binding parameter [2] as [BIGINT] - 47
  10:19:29.150 TRACE org.hibernate.type.EnumType [I=9534] - Binding [SEARCH_REG] to parameter: [3]
  10:19:29.150 TRACE o.h.type.descriptor.sql.BasicBinder [I=9534] - binding parameter [4] as [TIMESTAMP] - Tue Jul 16 00:00:00 BST 2013
  10:19:29.151 TRACE o.h.type.descriptor.sql.BasicBinder [I=9534] - binding parameter [5] as [VARCHAR] - 
  10:19:29.151 TRACE org.hibernate.loader.Loader [I=9534] - Bound [6] parameters total
  [... massive gap ...]
  10:19:55.644 TRACE o.h.e.j.internal.JdbcCoordinatorImpl [I=9534] - Registering result set [com.mchange.v2.c3p0.impl.NewProxyResultSet@fa7b109]
  </code></pre>
  
  <p>A note on concurrency: there is a great deal of variability even when only one request: 50 - 300 msecs end-to-end, but when one user submits a batch of about 100 of these lookups (probably 10-20 run concurrently), there's a high probability that a few will take 5-10 seconds. And yet the C3P0 stats are never any worse than:</p>
  
  <pre><code>com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 20; checked out: 6; num connections: 6; num keys: 20
  </code></pre>
  
  <p>These are pretty powerful servers, so there's no obvious disk, network, or CPU activity. We use NewRelic to monitor.</p>
  
  <p>Our DataSource setup:</p>
  
  <pre><code>ComboPooledDataSource dataSource = new com.mchange.v2.c3p0.ComboPooledDataSource();
  dataSource.setInitialPoolSize(5);
  dataSource.setMaxPoolSize(20);
  dataSource.setMinPoolSize(5);
  dataSource.setMaxStatements(20);
  dataSource.setIdleConnectionTestPeriod(3600);
  dataSource.setTestConnectionOnCheckin( Boolean.TRUE.toString() );
  dataSource.setPreferredTestQuery("select 1");
  </code></pre>
  
  <p>JPA properties:</p>
  
  <pre><code>props.put("hibernate.dialect", "org.hibernate.dialect.PostgreSQL82Dialect");
  props.put("hibernate.show_sql", "false");
  props.put("generate_statistics", "false");
  props.put("javax.persistence.sharedCache.mode", "ENABLE_SELECTIVE");
  props.put("javax.persistence.validation.mode", "NONE");
  props.put("hibernate.cache.use_second_level_cache", "false");
  props.put("hibernate.cache.region.factory_class", "org.hibernate.cache.impl.NoCachingRegionFactory");
  props.put("hibernate.hbm2ddl.auto", "false");
  </code></pre>
  
  <p>Versions: Postgres 9.1.7 with latest 9.2 JDBC driver; Hibernate 4.2.3.Final; C3P0 0.9.2.1; Spring 3.2.2.RELEASE; Spring Data JPA 1.1.0; Tomcat 7; JDK 1.7</p>
  
  <hr>
  
  <p><strong>Update</strong> - the C3P0 properties we're currently using (after switch to use <code>maxStatementsPerConnection</code>) </p>
  
  <p><code>c.m.v.c.i.AbstractPoolBackedDataSource [] - Initializing c3p0 pool... com.mchange.v2.c3p0.ComboPooledDataSource [ acquireIncrement -&gt; 3, acquireRetryAttempts -&gt; 30, acquireRetryDelay -&gt; 1000, autoCommitOnClose -&gt; false, automaticTestTable -&gt; null, breakAfterAcquireFailure -&gt; false, checkoutTimeout -&gt; 0, connectionCustomizerClassName -&gt; null, connectionTesterClassName -&gt; com.mchange.v2.c3p0.impl.DefaultConnectionTester, dataSourceName -&gt; 2s05p58v1s6oref13lw967|538ab4bc, debugUnreturnedConnectionStackTraces -&gt; false, description -&gt; null, driverClass -&gt; org.postgresql.Driver, factoryClassLocation -&gt; null, forceIgnoreUnresolvedTransactions -&gt; false, identityToken -&gt; 2s05p58v1s6oref13lw967|538ab4bc, idleConnectionTestPeriod -&gt; 1800, initialPoolSize -&gt; 5, jdbcUrl -&gt; jdbc:postgresql://******, maxAdministrativeTaskTime -&gt; 0, maxConnectionAge -&gt; 0, maxIdleTime -&gt; 0, maxIdleTimeExcessConnections -&gt; 0, maxPoolSize -&gt; 20, maxStatements -&gt; 0, maxStatementsPerConnection -&gt; 20, minPoolSize -&gt; 5, numHelperThreads -&gt; 3, preferredTestQuery -&gt; select 1, properties -&gt; {user=******, password=******}, propertyCycle -&gt; 0, statementCacheNumDeferredCloseThreads -&gt; 0, testConnectionOnCheckin -&gt; true, testConnectionOnCheckout -&gt; false, unreturnedConnectionTimeout -&gt; 0, userOverrides -&gt; {}, usesTraditionalReflectiveProxies -&gt; false ]</code></p>