BUG #1410: Hibernate PerformanceTest is incredibly slow (in effect unusable)

The following bug has been logged online:

Bug reference: 1410
Logged by: Simon Nicholls
Email address: simon@mintsource.org
PostgreSQL version: PostgreSQL 8.0
Operating system: WindowsXP
Description: Hibernate PerformanceTest is incredibly slow (in effect
unusable)
Details:

Using WindowsXP, JDK1.5, Hibernate 3.0 beta1, & PostgreSQL 8.0.0-rc5-3, I
ran the Hibernate PerformanceTest. Whilst it runs fine for MSSql & MySQL
(thus I believe Hibernate is ok), PostgreSQL takes way too long to complete.
I've tried with all 3 versions of the PostgreSQL jdbc driver, & also the
updated jdbc builds on the web site, but that has made no difference.

I've included the JUnit output at the bottom, & here are the MySQL InnoDb
results - simply to give a general ball-park idea of test timings. I'm
running a 2.8 GHz P4 with 1Gb ram, & only the minimum software needed for
test (I believe). CPU usage is very high throughout the test. Thanks for all
the great work so far btw, & I hope this is something obvious.

MySQL Timings
-------------

Testsuite: org.hibernate.test.legacy.PerformanceTest
Tests run: 4, Failures: 0, Errors: 0, Time elapsed: 205.375 sec
------------- Standard Output ---------------
Objects: 2 - Hibernate: 109ms / Direct JDBC: 125ms = Ratio: 0.872
Objects: 4 - Hibernate: 109ms / Direct JDBC: 63ms = Ratio: 1.7301587
Objects: 8 - Hibernate: 157ms / Direct JDBC: 156ms = Ratio: 1.0064102
Objects: 16 - Hibernate: 109ms / Direct JDBC: 172ms = Ratio: 0.63372093
Objects: 32 - Hibernate: 156ms / Direct JDBC: 203ms = Ratio: 0.7684729
Objects: 64 - Hibernate: 234ms / Direct JDBC: 344ms = Ratio: 0.6802326
Objects: 128 - Hibernate: 359ms / Direct JDBC: 563ms = Ratio: 0.63765544
Objects: 256 - Hibernate: 672ms / Direct JDBC: 984ms = Ratio: 0.68292683
Objects: 512 - Hibernate: 1110ms / Direct JDBC: 1859ms = Ratio: 0.5970952
Objects: 1024 - Hibernate: 2032ms / Direct JDBC: 4047ms = Ratio: 0.50210035
Objects: 2048 - Hibernate: 4438ms / Direct JDBC: 7140ms = Ratio: 0.6215686

PostgreSQL Test Output
----------------------

Testsuite: org.hibernate.test.legacy.PerformanceTest
Tests run: 4, Failures: 0, Errors: 0, Time elapsed: 3,200.453 sec
------------- Standard Output ---------------
00:41:40,296 INFO Environment:443 - Hibernate 3.0 beta 1
00:41:40,312 INFO Environment:461 - loaded properties from resource
hibernate.properties: {hibernate.order_updates=true,
hibernate.connection.driver_class=org.postgresql.Driver,
hibernate.cglib.use_reflection_optimizer=true,
hibernate.cache.provider_class=org.hibernate.cache.HashtableCacheProvider,
hibernate.max_fetch_depth=1,
hibernate.dialect=org.hibernate.dialect.PostgreSQLDialect,
hibernate.jdbc.use_streams_for_binary=true,
hibernate.query.substitutions=yes 'Y', no 'N',
hibernate.proxool.pool_alias=pool1, hibernate.connection.username=postgres,
hibernate.cache.region_prefix=hibernate.test,
hibernate.connection.url=jdbc:postgresql:test,
hibernate.connection.password=snag1gas,
hibernate.jdbc.batch_versioned_data=true, hibernate.connection.pool_size=1}
00:41:40,312 INFO Environment:488 - using java.io streams to persist binary
types
00:41:40,312 INFO Environment:489 - using CGLIB reflection optimizer
00:41:40,312 INFO Environment:519 - using JDK 1.4 java.sql.Timestamp
handling
00:41:40,390 INFO Configuration:408 - Mapping resource:
org/hibernate/test/legacy/Simple.hbm.xml
00:41:40,625 INFO HbmBinder:445 - Mapping class:
org.hibernate.test.legacy.Simple -> Simple
00:41:40,765 INFO Dialect:90 - Using dialect:
org.hibernate.dialect.PostgreSQLDialect
00:41:40,765 INFO Configuration:780 - processing extends queue
00:41:40,765 INFO Configuration:784 - processing collection mappings
00:41:40,765 INFO Configuration:793 - processing association property
references
00:41:40,765 INFO Configuration:820 - processing foreign key constraints
00:41:40,765 INFO Dialect:90 - Using dialect:
org.hibernate.dialect.PostgreSQLDialect
00:41:40,781 INFO SettingsFactory:93 - Maximum outer join fetch depth: 1
00:41:40,781 INFO SettingsFactory:97 - Generate SQL with comments:
disabled
00:41:40,781 INFO SettingsFactory:101 - Order SQL updates by primary key:
enabled
00:41:40,781 INFO SettingsFactory:265 - Query translator:
org.hibernate.hql.classic.ClassicQueryTranslatorFactory
00:41:40,796 INFO SettingsFactory:109 - Query language substitutions:
{no='N', yes='Y'}
00:41:40,796 INFO DriverManagerConnectionProvider:41 - Using Hibernate
built-in connection pool (not for production use!)
00:41:40,796 INFO DriverManagerConnectionProvider:42 - Hibernate connection
pool size: 1
00:41:40,796 INFO DriverManagerConnectionProvider:45 - autocommit mode:
false
00:41:40,796 INFO DriverManagerConnectionProvider:80 - using driver:
org.postgresql.Driver at URL: jdbc:postgresql:test
00:41:40,796 INFO DriverManagerConnectionProvider:86 - connection
properties: {user=postgres, password=****}
00:41:40,921 INFO SettingsFactory:150 - JDBC batch size: 15
00:41:40,921 INFO SettingsFactory:153 - JDBC batch updates for versioned
data: enabled
00:41:40,937 INFO SettingsFactory:158 - Scrollable result sets: enabled
00:41:40,937 INFO SettingsFactory:166 - JDBC3 getGeneratedKeys(): disabled
00:41:40,937 INFO TransactionFactoryFactory:31 - Using default transaction
strategy (direct JDBC transactions)
00:41:40,937 INFO TransactionManagerLookupFactory:33 - No
TransactionManagerLookup configured (in JTA environment, use of read-write
or transactional second-level cache is not recommended)
00:41:40,937 INFO SettingsFactory:178 - Automatic flush during
beforeCompletion(): disabled
00:41:40,937 INFO SettingsFactory:181 - Automatic session close at end of
transaction: disabled
00:41:40,937 INFO SettingsFactory:252 - Cache provider:
org.hibernate.cache.HashtableCacheProvider
00:41:40,937 INFO SettingsFactory:189 - Second-level cache: enabled
00:41:40,937 INFO SettingsFactory:191 - Optimize cache for minimal puts:
disabled
00:41:40,937 INFO SettingsFactory:193 - Cache region prefix:
hibernate.test
00:41:40,953 INFO SettingsFactory:199 - Query cache: disabled
00:41:40,953 INFO SettingsFactory:210 - Statistics: disabled
00:41:40,953 INFO SettingsFactory:214 - Deleted entity synthetic identifier
rollback: disabled
00:41:41,046 INFO SessionFactoryImpl:133 - building session factory
00:41:41,265 INFO SessionFactoryObjectFactory:82 - Not binding factory to
JNDI, no JNDI name configured
00:41:41,265 INFO Dialect:90 - Using dialect:
org.hibernate.dialect.PostgreSQLDialect
00:41:41,265 INFO Configuration:780 - processing extends queue
00:41:41,265 INFO Configuration:784 - processing collection mappings
00:41:41,265 INFO Configuration:793 - processing association property
references
00:41:41,265 INFO Configuration:820 - processing foreign key constraints
00:41:41,265 INFO Configuration:780 - processing extends queue
00:41:41,265 INFO Configuration:784 - processing collection mappings
00:41:41,265 INFO Configuration:793 - processing association property
references
00:41:41,265 INFO Configuration:820 - processing foreign key constraints
00:41:41,265 INFO SchemaExport:100 - Running hbm2ddl schema export
00:41:41,281 INFO SchemaExport:121 - exporting generated schema to
database
00:41:41,281 INFO DriverManagerConnectionProvider:41 - Using Hibernate
built-in connection pool (not for production use!)
00:41:41,281 INFO DriverManagerConnectionProvider:42 - Hibernate connection
pool size: 1
00:41:41,281 INFO DriverManagerConnectionProvider:45 - autocommit mode:
false
00:41:41,281 INFO DriverManagerConnectionProvider:80 - using driver:
org.postgresql.Driver at URL: jdbc:postgresql:test
00:41:41,281 INFO DriverManagerConnectionProvider:86 - connection
properties: {user=postgres, password=****}
00:41:41,328 DEBUG SchemaExport:136 - alter table Simple drop constraint
FK939D1DD26527F10
00:41:41,453 DEBUG SchemaExport:136 - drop table Simple
00:41:41,500 DEBUG SchemaExport:154 - create table Simple (
id_ int8 not null,
name varchar(255),
address varchar(255),
count_ int4 not null unique,
date_ timestamp,
pay float4,
other int8,
primary key (id_)
)
00:41:41,656 DEBUG SchemaExport:154 - alter table Simple add constraint
FK939D1DD26527F10 foreign key (other) references Simple
00:41:41,718 INFO SchemaExport:166 - schema export complete
00:41:41,718 INFO DriverManagerConnectionProvider:147 - cleaning up
connection pool: jdbc:postgresql:test
00:41:41,718 INFO Dialect:90 - Using dialect:
org.hibernate.dialect.PostgreSQLDialect
00:41:41,734 INFO Configuration:780 - processing extends queue
00:41:41,734 INFO Configuration:784 - processing collection mappings
00:41:41,734 INFO Configuration:793 - processing association property
references
00:41:41,734 INFO Configuration:820 - processing foreign key constraints
00:41:41,734 INFO Configuration:780 - processing extends queue
00:41:41,734 INFO Configuration:784 - processing collection mappings
00:41:41,734 INFO Configuration:793 - processing association property
references
00:41:41,734 INFO Configuration:820 - processing foreign key constraints
00:41:41,734 INFO SessionFactoryImpl:356 - Checking 0 named queries
00:41:41,734 INFO DriverManagerConnectionProvider:41 - Using Hibernate
built-in connection pool (not for production use!)
00:41:41,734 INFO DriverManagerConnectionProvider:42 - Hibernate connection
pool size: 1
00:41:41,734 INFO DriverManagerConnectionProvider:45 - autocommit mode:
false
00:41:41,734 INFO DriverManagerConnectionProvider:80 - using driver:
org.postgresql.Driver at URL: jdbc:postgresql:test
00:41:41,734 INFO DriverManagerConnectionProvider:86 - connection
properties: {user=postgres, password=****}
00:41:42,218 INFO DriverManagerConnectionProvider:147 - cleaning up
connection pool: jdbc:postgresql:test
Hibernate: 240994ms / Direct JDBC: 274959ms = Ratio: 0.8764725
00:50:28,734 INFO DriverManagerConnectionProvider:147 - cleaning up
connection pool: jdbc:postgresql:test
00:50:28,796 INFO DriverManagerConnectionProvider:41 - Using Hibernate
built-in connection pool (not for production use!)
00:50:28,796 INFO DriverManagerConnectionProvider:42 - Hibernate connection
pool size: 1
00:50:28,796 INFO DriverManagerConnectionProvider:45 - autocommit mode:
false
00:50:28,796 INFO DriverManagerConnectionProvider:80 - using driver:
org.postgresql.Driver at URL: jdbc:postgresql:test
00:50:28,796 INFO DriverManagerConnectionProvider:86 - connection
properties: {user=postgres, password=****}
Objects: 2 - Hibernate: 311ms / Direct JDBC: 329ms = Ratio: 0.9452888
Objects: 4 - Hibernate: 515ms / Direct JDBC: 422ms = Ratio: 1.2203791
Objects: 8 - Hibernate: 750ms / Direct JDBC: 625ms = Ratio: 1.2
Objects: 16 - Hibernate: 1250ms / Direct JDBC: 984ms = Ratio: 1.2703252
Objects: 32 - Hibernate: 1999ms / Direct JDBC: 1751ms = Ratio: 1.1416334
Objects: 64 - Hibernate: 6953ms / Direct JDBC: 4203ms = Ratio: 1.6542946
Objects: 128 - Hibernate: 14061ms / Direct JDBC: 7892ms = Ratio: 1.7816776
00:52:24,953 INFO DriverManagerConnectionProvider:147 - cleaning up
connection pool: jdbc:postgresql:test
Objects: 256 - Hibernate: 29408ms / Direct JDBC: 17842ms = Ratio: 1.6482457
Objects: 512 - Hibernate: 65235ms / Direct JDBC: 38968ms = Ratio: 1.674066
Objects: 1024 - Hibernate: 158688ms / Direct JDBC: 90484ms = Ratio:
1.7537686
Objects: 2048 - Hibernate: 301546ms / Direct JDBC: 226048ms = Ratio:
1.333991
01:17:34,328 INFO DriverManagerConnectionProvider:147 - cleaning up
connection pool: jdbc:postgresql:test
Objects: 2 - Hibernate: 672
Objects: 4 - Hibernate: 1015
Objects: 8 - Hibernate: 1875
Objects: 16 - Hibernate: 2641
Objects: 32 - Hibernate: 5281
Objects: 64 - Hibernate: 9500
Objects: 128 - Hibernate: 17078
Objects: 256 - Hibernate: 33516
Objects: 512 - Hibernate: 82594
01:21:51,765 INFO DriverManagerConnectionProvider:147 - cleaning up
connection pool: jdbc:postgresql:test
Objects: 1024 - Hibernate: 152000
Objects: 2048 - Hibernate: 327562
01:28:08,218 INFO DriverManagerConnectionProvider:41 - Using Hibernate
built-in connection pool (not for production use!)
01:28:08,218 INFO DriverManagerConnectionProvider:42 - Hibernate connection
pool size: 1
01:28:08,218 INFO DriverManagerConnectionProvider:45 - autocommit mode:
false
01:28:08,218 INFO DriverManagerConnectionProvider:80 - using driver:
org.postgresql.Driver at URL: jdbc:postgresql:test
01:28:08,218 INFO DriverManagerConnectionProvider:86 - connection
properties: {user=postgres, password=****}
Objects: 2 Direct JDBC: 578
Objects: 4 Direct JDBC: 672
Objects: 8 Direct JDBC: 906
Objects: 16 Direct JDBC: 1782
Objects: 32 Direct JDBC: 3234
Objects: 64 Direct JDBC: 5344
Objects: 128 Direct JDBC: 11797
Objects: 256 Direct JDBC: 24078
Objects: 512 Direct JDBC: 54015
Objects: 1024 Direct JDBC: 110157
Objects: 2048 Direct JDBC: 199484
01:35:00,312 INFO DriverManagerConnectionProvider:147 - cleaning up
connection pool: jdbc:postgresql:test
------------- ---------------- ---------------

Testcase: testMany took 528.625 sec
Testcase: testSimultaneous took 1,625.61 sec
Testcase: testHibernateOnly took 633.812 sec
Testcase: testJdbcOnly took 412.172 sec