최대 절전 모드에서 Postgres 연결 획득 속도가 느림

최대 절전 모드에서 Postgres 연결 획득 속도가 느림

---

이 문제를 디버깅하는 데 정말 어려움을 겪고 있습니다. postgres와 연결하려고 할 때마다 1 분 정도 걸립니다. 연결이 설정되면 모든 것이 정상입니다. 모든 매핑을 비활성화하고로드하지 않으려 고했지만 여전히 연결을 가져 오는 데 오랜 시간이 걸립니다. 나는 또한 유효성 검사를 비활성화하려고 시도했지만 차이는 없습니다. 간단한 JDBC 연결을 사용하면 즉각적입니다. Hibernate는 상당한 시간이 걸리는 작업을 수행하고 있으며 범위를 좁힐 수 없습니다. 어떤 입력이라도 대단히 감사합니다!

Postgres 드라이버 :

postgresql-9.1-901.jdbc4.jar

구성 설정 :

<hibernate-configuration>
    <session-factory>
    <!-- properties -->
        <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>

코드의 추가 설정 :

    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");

지연이 발생하는 코드 세그먼트는 다음과 같습니다.

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;
    }

로그 결과는 다음과 같습니다.

[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

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:

[SELECT typname FROM pg_catalog.pg_type WHERE oid = , ]

Here's a screenshot:

---

I fixed it =) I really had to root around to find the answer for this one. Basically, it comes down to loading metadata and the JDBC driver. It's loading ALL META DATA, including comments beside sql columns and other various constructs, which are not needed for operation. I don't know why this is on by default but you should definitely turn this feature off unless you explicitly need it:

config.setProperty("hibernate.temp.use_jdbc_metadata_defaults","false");

Instant connection now!

The only info I could find on this is in code:

107     // 'hibernate.temp.use_jdbc_metadata_defaults' is a temporary magic value.
108     // The need for it is intended to be alleviated with future development, thus it is
109     // not defined as an Environment constant...
110     //
111     // it is used to control whether we should consult the JDBC metadata to determine
112     // certain Settings default values; it is useful to *not* do this when the database
113     // may not be available (mainly in tools usage).
114     boolean useJdbcMetadata = ConfigurationHelper.getBoolean( "hibernate.temp.use_jdbc_metadata_defaults", configValues, true );

http://grepcode.com/file/repo1.maven.org/maven2/org.hibernate/hibernate-core/4.1.1.Final/org/hibernate/engine/jdbc/internal/JdbcServicesImpl.java#JdbcServicesImpl

---

I had to also enable hibernate.jdbc.use_get_generated_keys otherwise Identity generation strategy was throwing an exception. Before it was enabled automatically based on metadata received from DB. So my whole solution was to add the following two lines to persistence.xml:

<property name="hibernate.jdbc.use_get_generated_keys" value="true" />
<property name="hibernate.temp.use_jdbc_metadata_defaults" value="false" />

---

Almost 7 years later and this is still an issue...

Turning the "temp" key off helps but it's a nuisance to enable properties one-by-one that would be auto-configured (see other answers).

In case of Oracle and Teradata I didn't notice such a slowdown so I digged deep and found where the slowest part is: https://github.com/pgjdbc/pgjdbc/blob/master/pgjdbc/src/main/java/org/postgresql/jdbc/PgDatabaseMetaData.java#L2237

This resultSet has in my case 372 rows (types). Then, for each driver fires couple of calls from https://github.com/pgjdbc/pgjdbc/blob/master/pgjdbc/src/main/java/org/postgresql/jdbc/TypeInfoCache.java#L204 which results in tons of SQL statements against the DB.

No idea how to speed this up right now, luckily it's needed once and then it's cached.

---

One postgresql server can contain multiple databases. Unfortunatelly you can not hide other-database metadatas to one connection, thats why the metadata-reading takes long time by the jdbc-driver!

Seperate theese databases into different postgres-servers and the performance of metadata-reading will be increased!

Read how to seperate on centos.

---

I had issues with scrollable result set so I had to add the 3rd parameter, see below:

<property name="hibernate.temp.use_jdbc_metadata_defaults">false</property>
<property name="hibernate.jdbc.use_get_generated_keys">true</property>
<property name="hibernate.jdbc.use_scrollable_resultset">true</property>

---

This sounds vaguely like a problem we saw in Ruby on Rails. You might look for a similar cause to what I described here:

http://archives.postgresql.org/pgsql-performance/2009-11/msg00128.php

In short, that problem was caused by explicit registration of the JDBC driver from multiple ClassLoader contexts.

참고URL : https://stackoverflow.com/questions/10075081/hibernate-slow-to-acquire-postgres-connection