StackOverflow2013

Note that there are some explanatory texts on larger screens.

plurals

POHibernate Slow to Acquire Postgres Connection
text
Body
copied!<p>I'm having a really difficult time debugging this problem. Whenever I try to establish a connection with postgres, it takes a whole minute. After the connection is established, everything is fine. I've tried disabling all the mappings and not loading any, but still the connection takes a long time to aquire. I've also tried disabling validation, no difference. When I use a simple a simple JDBC connection, it's instantaneous. Hibernate is doing something which takes considerable amount of time and I can't seem to narrow it down. Any input is greatly appreciated!</p> <p>Postgres Driver:</p> <pre><code>postgresql-9.1-901.jdbc4.jar </code></pre> <p>Configuration settings:</p> <pre><code><hibernate-configuration> <session-factory>  <property name="dialect">org.hibernate.dialect.PostgreSQLDialect</property> <property name="connection.driver_class">org.postgresql.Driver</property> <property name="connection.url">jdbc:postgresql://xxxx.com:5432/xxxxx</property> <property name="connection.username">xxxxxxx</property> <property name="connection.password">xxxxxxx</property> </session-factory> </hibernate-configuration> </code></pre> <p>Additional settings in code:</p> <pre><code> config.setProperty("hibernate.hbm2ddl.auto", hbm2ddlMode); //config.setProperty("hibernate.cache.use_query_cache", "true"); config.setProperty("hibernate.cache.use_second_level_cache", "true"); //config.setProperty("hibernate.cache.region.factory_class", "net.sf.ehcache.hibernate.EhCacheRegionFactory"); config.setProperty("hibernate.cache.provider_class", "org.hibernate.cache.EhCacheProvider"); //config.setProperty("hibernate.cache.provider_class", "org.hibernate.cache.NoCacheProvider"); config.setProperty("hibernate.jdbc.fetch_size", "100"); config.setProperty("hibernate.jdbc.batch_size", "30"); config.setProperty("hibernate.jdbc.use_scrollable_resultset", "true"); config.setProperty("hibernate.connection.provider_class", "org.hibernate.connection.C3P0ConnectionProvider"); config.setProperty("hibernate.c3p0.acquire_increment", "1"); config.setProperty("hibernate.c3p0.idle_test_period", "0"); config.setProperty("hibernate.c3p0.min_size", "1"); config.setProperty("hibernate.c3p0.max_size", "2"); config.setProperty("hibernate.c3p0.timeout", "0"); config.setProperty("javax.persistence.validation.mode", "none"); </code></pre> <p>Here's the segment of code where the delay occurs:</p> <pre><code>private SessionFactory buildSessionFactory() throws Exception { ServiceRegistry serviceRegistry = new ServiceRegistryBuilder().applySettings(config.getProperties()).buildServiceRegistry(); //Building session takes a whole minute without mappings!!! sessionFactory = config.buildSessionFactory(serviceRegistry); validateConnection(); return sessionFactory; } </code></pre> <p>Here's the log results:</p> <pre><code>[main] 2012-04-09 10:40:32,823 110391 INFO C3P0ConnectionProvider - HHH000046: Connection properties: {user=hgaidb_test, password=****} [main] 2012-04-09 10:40:32,823 110391 INFO C3P0ConnectionProvider - HHH000006: Autocommit mode: false [main] 2012-04-09 10:40:34,100 111668 DEBUG JdbcServicesImpl - Database -> name : PostgreSQL version : 8.3.3 major : 8 minor : 3 [main] 2012-04-09 10:40:34,101 111669 DEBUG JdbcServicesImpl - Driver -> name : PostgreSQL Native Driver version : PostgreSQL 9.1 JDBC4 (build 901) major : 9 minor : 1 ******************************************************************************* // 1 MINUTE DELAY ******************************************************************************* [main] 2012-04-09 10:40:34,102 111670 DEBUG JdbcServicesImpl - JDBC version : 4. 0 [main] 2012-04-09 10:41:21,632 159200 INFO Dialect - HHH000400: Using dialect: org.hibernate.dialect.PostgreSQLDialect ******************************************************************************* [main] 2012-04-09 10:41:21,669 159237 INFO LobCreatorBuilder - HHH000424: Disab ling contextual LOB creation as createClob() method threw error : java.lang.refl ect.InvocationTargetException [main] 2012-04-09 10:41:21,814 159382 DEBUG SettingsFactory - Automatic flush du ring beforeCompletion(): disabled [main] 2012-04-09 10:41:21,814 159382 DEBUG SettingsFactory - Automatic session close at end of transaction: disabled [main] 2012-04-09 10:41:21,815 159383 DEBUG SettingsFactory - JDBC batch size: 3 0 [main] 2012-04-09 10:41:21,816 159384 DEBUG SettingsFactory - JDBC batch updates for versioned data: disabled [main] 2012-04-09 10:41:21,816 159384 DEBUG SettingsFactory - Scrollable result sets: enabled [main] 2012-04-09 10:41:21,817 159385 DEBUG SettingsFactory - Wrap result sets: disabled [main] 2012-04-09 10:41:21,818 159386 DEBUG SettingsFactory - JDBC3 getGenerated Keys(): enabled [main] 2012-04-09 10:41:21,818 159386 DEBUG SettingsFactory - JDBC result set fe tch size: 100 [main] 2012-04-09 10:41:21,819 159387 DEBUG SettingsFactory - Connection release mode: auto [main] 2012-04-09 10:41:21,819 159387 INFO TransactionFactoryInitiator - HHH000 399: Using default transaction strategy (direct JDBC transactions) [main] 2012-04-09 10:41:21,844 159412 DEBUG SettingsFactory - Default batch fetc h size: 1 [main] 2012-04-09 10:41:21,844 159412 DEBUG SettingsFactory - Generate SQL with comments: disabled [main] 2012-04-09 10:41:21,845 159413 DEBUG SettingsFactory - Order SQL updates by primary key: disabled [main] 2012-04-09 10:41:21,846 159414 DEBUG SettingsFactory - Order SQL inserts for batching: disabled [main] 2012-04-09 10:41:21,846 159414 DEBUG SettingsFactory - Query translator: org.hibernate.hql.internal.ast.ASTQueryTranslatorFactory [main] 2012-04-09 10:41:21,867 159435 INFO ASTQueryTranslatorFactory - HHH00039 7: Using ASTQueryTranslatorFactory [main] 2012-04-09 10:41:21,867 159435 DEBUG SettingsFactory - Query language sub stitutions: {} [main] 2012-04-09 10:41:21,867 159435 DEBUG SettingsFactory - JPA-QL strict comp liance: disabled [main] 2012-04-09 10:41:21,868 159436 DEBUG SettingsFactory - Second-level cache : enabled [main] 2012-04-09 10:41:21,868 159436 DEBUG SettingsFactory - Query cache: disab led [main] 2012-04-09 10:41:21,869 159437 DEBUG SettingsFactory - Cache region facto ry : org.hibernate.cache.internal.NoCachingRegionFactory [main] 2012-04-09 10:41:21,872 159440 DEBUG SettingsFactory - org.hibernate.cach e.internal.NoCachingRegionFactory did not provide constructor accepting java.uti l.Properties; attempting no-arg constructor. [main] 2012-04-09 10:41:21,873 159441 DEBUG SettingsFactory - Optimize cache for minimal puts: disabled [main] 2012-04-09 10:41:21,873 159441 DEBUG SettingsFactory - Structured second- level cache entries: disabled [main] 2012-04-09 10:41:21,873 159441 DEBUG SettingsFactory - Statistics: disabl ed [main] 2012-04-09 10:41:21,874 159442 DEBUG SettingsFactory - Deleted entity syn thetic identifier rollback: disabled [main] 2012-04-09 10:41:21,874 159442 DEBUG SettingsFactory - Default entity-mod e: pojo [main] 2012-04-09 10:41:21,875 159443 DEBUG SettingsFactory - Named query checki ng : enabled [main] 2012-04-09 10:41:21,875 159443 DEBUG SettingsFactory - Check Nullability in Core (should be disabled when Bean Validation is on): enabled [main] 2012-04-09 10:41:21,876 159444 DEBUG SettingsFactory - multi-tenancy stra tegy : NONE </code></pre> <p>I've done a little more research on this, stepping through the debugger. I don't have all the source in my classpath, but i can still see the variables. Durring that one minute wait, Hibernate is querying the pg_catalog.pg_type table:</p> <pre><code>[SELECT typname FROM pg_catalog.pg_type WHERE oid = , ] </code></pre> <p>Here's a screenshot:</p> <p><img src="https://i.stack.imgur.com/DKiBX.jpg" alt="DebugWindow"></p>

Querying!

Guidance

An individual column

Larger individual text columns get their own page to allow for proper reading.

SQuiL has stopped working due to an internal error.

If you are curious you may find further information in the browser console, which is accessible through the devtools (F12).

Reload