Slow JBoss startup, possibly related to DataSource pointing to Heroku Postgres

Question

I am observing a slow JBoss startup. Specifically there is a freeze in the startup when deploying my application, it seems during Hibernate initialisation:

22:43:00,066 DEBUG [org.hibernate.cfg.Configuration] (ServerService Thread Pool -- 48) Creating tables' unique integer identifiers
22:43:00,066 DEBUG [org.hibernate.cfg.Configuration] (ServerService Thread Pool -- 48) Processing foreign key constraints
22:43:00,075 INFO  [org.hibernate.service.jdbc.connections.internal.ConnectionProviderInitiator] (ServerService Thread Pool -- 48) HHH000130: Instantiating explicit connection provider: org.hibernate.ejb.connection.InjectedDataSourceConnectionProvider
22:43:00,105 DEBUG [org.jboss.jca.core.connectionmanager.pool.idle.IdleRemover] (ServerService Thread Pool -- 48) Register pool: SemaphoreArrayListManagedConnectionPool@33ff5ccd[pool=HerokuPostgreSQLDS] (interval=1800000)
22:43:00,105 DEBUG [org.jboss.jca.core.connectionmanager.pool.idle.IdleRemover] (ServerService Thread Pool -- 48) About to notify thread: old next: 1384811880105, new next: 1384811880105
22:43:00,106 DEBUG [org.jboss.jca.core.connectionmanager.pool.idle.IdleRemover] (IdleRemover) Notifying pools, interval: 900000
22:43:00,107 DEBUG [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (ServerService Thread Pool -- 48) HerokuPostgreSQLDS: getConnection(null, null) [0/10]
22:43:00,109 DEBUG [org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory] (ServerService Thread Pool -- 48) Driver loaded and instance created:org.postgresql.Driver@10340285
22:43:01,311 DEBUG [org.hibernate.engine.jdbc.internal.JdbcServicesImpl] (ServerService Thread Pool -- 48) Database ->
       name : PostgreSQL
    version : 9.1.9
      major : 9
      minor : 1
22:43:01,311 DEBUG [org.hibernate.engine.jdbc.internal.JdbcServicesImpl] (ServerService Thread Pool -- 48) Driver ->
       name : PostgreSQL Native Driver
    version : PostgreSQL 9.1 JDBC4 (build 901)
      major : 9
      minor : 1
22:43:01,312 DEBUG [org.hibernate.engine.jdbc.internal.JdbcServicesImpl] (ServerService Thread Pool -- 48) JDBC version : 4.0
22:43:27,744 DEBUG [org.apache.catalina.session] (ContainerBackgroundProcessor[StandardEngine[jboss.web]]) Start expire sessions StandardManager at 1384811007744 sessioncount 0
22:43:27,744 DEBUG [org.apache.catalina.session] (ContainerBackgroundProcessor[StandardEngine[jboss.web]]) End expire sessions StandardManager processingTime 0 expired sessions: 0
22:43:37,982 DEBUG [org.jboss.ejb.client.txn] (Periodic Recovery) Send recover request for transaction origin node identifier 1 to EJB receiver with node name rocket
22:43:47,987 DEBUG [org.jboss.ejb.client.txn] (Periodic Recovery) Send recover request for transaction origin node identifier 1 to EJB receiver with node name rocket
22:43:59,686 INFO  [org.hibernate.dialect.Dialect] (ServerService Thread Pool -- 48) HHH000400: Using dialect: org.hibernate.dialect.PostgreSQL82Dialect
22:43:59,697 INFO  [org.hibernate.engine.jdbc.internal.LobCreatorBuilder] (ServerService Thread Pool -- 48) HHH000424: Disabling contextual LOB creation as createClob() method threw error : java.lang.reflect.InvocationTargetException
22:43:59,699 DEBUG [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (ServerService Thread Pool -- 48) HerokuPostgreSQLDS: returnConnection(7bf7b5fc, false) [1/10]
22:43:59,709 DEBUG [org.hibernate.cfg.SettingsFactory] (ServerService Thread Pool -- 48) Automatic flush during beforeCompletion(): disabled

Between 22:43:01 and 22:43:59 is a long freeze which I do not understand. Can somebody help me to understand this freeze?

I am experimenting with using a Heroku Postgres Database with a JavaEE Application deployed to JBoss.

I have configured a datasource in standalone.xml like this:

       <subsystem xmlns="urn:jboss:domain:datasources:1.1">
            <datasources>
                <datasource jndi-name="java:jboss/datasources/HerokuPostgreSQLDS" pool-name="HerokuPostgreSQLDS" enabled="true" use-java-context="true" use-ccm="true">
                    <connection-url>${env.HEROKU_POSTGRESQL_DB_URL}</connection-url>
                    <driver>postgresql</driver>
                    <pool>
                        <min-pool-size>1</min-pool-size>
                        <max-pool-size>10</max-pool-size>
                        <prefill>false</prefill>
                        <flush-strategy>IdleConnections</flush-strategy>
                    </pool>
                </datasource>
                <drivers>
                    <driver name="postgresql" module="org.postgresql">
                        <xa-datasource-class>org.postgresql.xa.PGXADataSource</xa-datasource-class>
                    </driver>
                </drivers>
            </datasources>
        </subsystem>

I have set the environment variable HEROKU_POSTGRESQL_DB_URL to something like:

jdbc:postgresql://ec2-23-21-204-85.compute-1.amazonaws.com:5432/mydatabase?user=myuser&password=mypassword0&ssl=true&sslfactory=org.postgresql.ssl.NonValidatingFactory

Once the server has started, everything is working fine.

I think it takes so long to initialise the DataSource to Heroku. But why? When I connect to the Database directly from a standalone Java Program using plain JDBC, everything is fast ... Can I somehow speed up the creation of the datasource? I also tried not to specify an <xa-datasource-class> but a plain driver class like <xa-datasource-class>org.postgresql.Driver</xa-datasource-class>. But that did result in the same behavior ...

Is anybody else using a Java EE datasource in JBoss that points to Heroku? Is it normal that it takes so long?

For completeness, here is my persistence-unit (from persistence.xml):

<persistence-unit name="admin" transaction-type="JTA">
    <jta-data-source>java:jboss/datasources/HerokuPostgreSQLDS</jta-data-source>
    <class>org.jbfirst.entities.BCUser</class>
    <properties>
        <property name="hibernate.show_sql" value="true" />
        <!--<property name="hibernate.hbm2ddl.auto" value="create" />-->
    </properties>
</persistence-unit>

how does your persistence.xml / hibernate.cfg.xml config look like? — Tomaz Cerar, Nov 18 '13 at 13:05
@ctomc I don't think that it matters, since I think it takes the time during initialisation of the datasource itself and not for the initialisation of the persistence unit ... but maybe I am wrong ... So I added the persistence.xml to the question above. — jbandi, Nov 18 '13 at 22:11

score 3 · Answer 1 · edited May 23 '17 at 11:54

I had the same problem, it occurs because hibernate try to determine dialect from connection meta data. To avoid this process, set the following properties in your persistence.xml:

<property name="hibernate.dialect" value="org.hibernate.dialect.PostgreSQLDialect" />
<property name="hibernate.temp.use_jdbc_metadata_defaults" value="false" />

See also: Hibernate Slow to Acquire Postgres Connection

brettw · Answer 2 · 2013-11-18T02:08:57.187

2

Are you cleanly shutting down your JBoss instance? All of the threads I could find related to slow periodic recovery had to do with unclean shutdown and startup. I also suggest updated to the very latest PostgreSQL JDBC driver, as there has been at least one fix related to transaction recovery.

edited Nov 18 '13 at 02:08

answered Nov 18 '13 at 02:02

brettw

10,664
2
42
59

Thanks. I updated the question: I am now using the latest version of the PostgreSQL Driver (9.1-901-1.jdbc4). Same behaviour... – jbandi Nov 18 '13 at 22:05
Actually I don't think it's related to the periodic recovery. I think it's just coincidence that the recovery happens during the initialisation of the datasource... I suspect the problem is that it takes so long to create the datasource ... – jbandi Nov 18 '13 at 22:08
1

I don't think it is the periodic recovery, but it seems unlikely to be the DataSource initialization either. The pool minimum is set to 1, and establishing an ssl connection to the remote host shouldn't take more than a few seconds at most. I am thinking that there is a lot more Hibernate initialization running that is not logged. I would try turning up logging to TRACE level to see if you can discover what else is happening at the time of the pause. – brettw Nov 19 '13 at 00:22

Slow JBoss startup, possibly related to DataSource pointing to Heroku Postgres

2 Answers2