Why does hibernate update database twice?

kborkowski · **Posted:** Tue Nov 21, 2006 9:29 am

I have an example where Hibernate updates database twice - and I have no idea why. Does anybody knows the reason why the second update occures and what should I do to eliminate it? Here are some details (please, pay attention to the insert and update operations on the companies_archive table).

Hibernate version: 3.2.0

Mapped classes:

Code:

public class Company
{
   // Persistence layer requirement
   private Long id;
   private Integer version;
   
   // Archive requirement
   private Map<Integer, Company> archive = new HashMap<Integer, Company>();
   private Company currentVersion;
   
   // Main data
   private String name;
   
// Construction
   Company()
   { /* NOP */ }
   
   private Company(final Company original)
   {
      currentVersion = original;
      name = original.name;
   }
// END: Construction

// Getters and setters
// ...
// END: Getters and setters

// Interface methods
   public void updateName(final String name)
   {
      Company archiveVersion = new Company(this);
      archive.put(version, archiveVersion);
      
      this.name = name;
   }
// END: Interface methods

Mapping documents:

Code:

<!DOCTYPE hibernate-mapping PUBLIC
"-//Hibernate/Hibernate Mapping DTD 3.0//EN"
"http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd">
<hibernate-mapping package="test.hibernate.morethanonce">
  
  <class name="Company" table="companies" entity-name="Company">
    <id name="id" column="id" type="long">
      <generator class="sequence">
   <param name="sequence">database_level_id_generator</param>
      </generator>
    </id>
    
    <version name="version" column="version" type="integer"/>
    
    <map name="archive" lazy="true" cascade="all-delete-orphan">
      <key column="current_id" not-null="true"/>
      <map-key column="version" type="integer"/>
      <one-to-many entity-name="ArchivedCompany"/>
    </map>
    
    <property name="name" column="name" type="string"/>
  </class>
  
  
  <class name="Company" table="companies_archive" entity-name="ArchivedCompany">
    <id name="id" column="id" type="long">
      <generator class="sequence">
   <param name="sequence">database_level_id_generator</param>
      </generator>
    </id>
    
    <many-to-one name="currentVersion" column="current_id" not-null="true"
       insert="false" update="false" entity-name="Company"/>
    
    <property name="name" column="name" type="string"/>
  </class>
  
</hibernate-mapping>

Code between sessionFactory.openSession() and session.close():

Code:

      Company company = (Company)session.get("Company", 1L);
      company.updateName("Test_02");

Name and version of the database you are using: PostgreSQL, version: 8.1.5

The generated SQL (show_sql=true):

Code:

    select
        company0_.id as id0_0_,
        company0_.version as version0_0_,
        company0_.name as name0_0_ 
    from
        companies company0_ 
    where
        company0_.id=?


    select
        archive0_.current_id as current2_1_,
        archive0_.id as id1_,
        archive0_.version as version1_,
        archive0_.id as id1_0_,
        archive0_.current_id as current2_1_0_,
        archive0_.name as name1_0_ 
    from
        companies_archive archive0_ 
    where
        archive0_.current_id=?


    select
        nextval ('database_level_id_generator')


    insert 
    into
        companies_archive
        (name, current_id, version, id) 
    values
        (?, ?, ?, ?)


    update
        companies 
    set
        version=?,
        name=? 
    where
        id=? 
        and version=?


    update
        companies_archive 
    set
        current_id=?,
        version=? 
    where
        id=?

Debug level Hibernate log excerpt:

Code:

02:10,562  INFO Environment:500 - Hibernate 3.2.0
02:10,578  INFO Environment:533 - hibernate.properties not found
02:10,593  INFO Environment:667 - Bytecode provider name : cglib
02:10,593  INFO Environment:584 - using JDK 1.4 java.sql.Timestamp handling
02:10,640  INFO Configuration:1350 - configuring from resource: test/hibernate/morethanonce/hibernate.cfg.xml
02:10,640  INFO Configuration:1327 - Configuration resource: test/hibernate/morethanonce/hibernate.cfg.xml
02:10,718 DEBUG DTDEntityResolver:38 - trying to resolve system-id [http://hibernate.sourceforge.net/hibernate-configuration-3.0.dtd]
02:10,718 DEBUG DTDEntityResolver:40 - recognized hibernate namespace; attempting to resolve on classpath under org/hibernate/
02:10,718 DEBUG DTDEntityResolver:50 - located [http://hibernate.sourceforge.net/hibernate-configuration-3.0.dtd] in classpath
02:10,750 DEBUG Configuration:1311 - connection.driver_class=org.postgresql.Driver
02:10,750 DEBUG Configuration:1311 - connection.url=jdbc:postgresql://localhost/hibernate_tests
02:10,750 DEBUG Configuration:1311 - connection.username=hibernate_tests
02:10,765 DEBUG Configuration:1311 - connection.password=hibernate_tests
02:10,765 DEBUG Configuration:1311 - dialect=org.hibernate.dialect.PostgreSQLDialect
02:10,765 DEBUG Configuration:1311 - c3p0.min_size=5
02:10,765 DEBUG Configuration:1311 - c3p0.max_size=20
02:10,765 DEBUG Configuration:1311 - c3p0.timeout=300
02:10,765 DEBUG Configuration:1311 - c3p0.max_statement=50
02:10,765 DEBUG Configuration:1311 - c3p0.idle_test_period=3000
02:10,765 DEBUG Configuration:1311 - show_sql=true
02:10,765 DEBUG Configuration:1311 - format_sql=true
02:10,765 DEBUG Configuration:1311 - max_fetch_depth=3
02:10,765 DEBUG Configuration:1311 - generate_statistics=true
02:10,765 DEBUG Configuration:1311 - connection.isolation=2
02:10,765 DEBUG Configuration:1510 - null<-org.dom4j.tree.DefaultAttribute@ba9340 [Attribute: name resource value "test/hibernate/morethanonce/Company.hbm.xml"]
02:10,765  INFO Configuration:507 - Reading mappings from resource: test/hibernate/morethanonce/Company.hbm.xml
02:10,765 DEBUG DTDEntityResolver:38 - trying to resolve system-id [http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd]
02:10,765 DEBUG DTDEntityResolver:40 - recognized hibernate namespace; attempting to resolve on classpath under org/hibernate/
02:10,765 DEBUG DTDEntityResolver:50 - located [http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd] in classpath
02:10,890  INFO HbmBinder:300 - Mapping class: Company -> companies
02:10,890 DEBUG HbmBinder:1270 - Mapped property: id -> id
02:10,890 DEBUG HbmBinder:1270 - Mapped property: version -> version
02:10,906 DEBUG HbmBinder:1270 - Mapped property: archive
02:10,906 DEBUG HbmBinder:1270 - Mapped property: name -> name
02:10,906  INFO HbmBinder:300 - Mapping class: ArchivedCompany -> companies_archive
02:10,906 DEBUG HbmBinder:1270 - Mapped property: id -> id
02:10,984 DEBUG HbmBinder:1270 - Mapped property: currentVersion -> current_id
02:10,984 DEBUG HbmBinder:1270 - Mapped property: name -> name
02:10,984  INFO Configuration:1465 - Configured SessionFactory: null
02:10,984 DEBUG Configuration:1466 - properties: {show_sql=true, java.vendor=Sun Microsystems Inc., hibernate.connection.url=jdbc:postgresql://localhost/hibernate_tests, sun.management.compiler=HotSpot Client Compiler, c3p0.min_size=5, os.name=Windows XP, sun.boot.class.path=C:\Program Files\Sun\jdk1.5.0_09\jre\lib\rt.jar;C:\Program Files\Sun\jdk1.5.0_09\jre\lib\i18n.jar;C:\Program Files\Sun\jdk1.5.0_09\jre\lib\sunrsasign.jar;C:\Program Files\Sun\jdk1.5.0_09\jre\lib\jsse.jar;C:\Program Files\Sun\jdk1.5.0_09\jre\lib\jce.jar;C:\Program Files\Sun\jdk1.5.0_09\jre\lib\charsets.jar;C:\Program Files\Sun\jdk1.5.0_09\jre\classes, generate_statistics=true, sun.desktop=windows, hibernate.c3p0.max_size=20, java.vm.specification.vendor=Sun Microsystems Inc., hibernate.generate_statistics=true, c3p0.max_size=20, java.runtime.version=1.5.0_09-b03, hibernate.c3p0.min_size=5, user.name=kborkowski, log4j.configuration=test/hibernate/morethanonce/log4j.properties, connection.driver_class=org.postgresql.Driver, hibernate.c3p0.timeout=300, user.language=pl, sun.boot.library.path=C:\Program Files\Sun\jdk1.5.0_09\jre\bin, dialect=org.hibernate.dialect.PostgreSQLDialect, max_fetch_depth=3, java.version=1.5.0_09, user.timezone=Europe/Belgrade, sun.arch.data.model=32, java.endorsed.dirs=C:\Program Files\Sun\jdk1.5.0_09\jre\lib\endorsed, sun.cpu.isalist=pentium_pro+mmx pentium_pro pentium+mmx pentium i486 i386 i86, sun.jnu.encoding=Cp1250, file.encoding.pkg=sun.io, file.separator=\, java.specification.name=Java Platform API Specification, hibernate.format_sql=true, java.class.version=49.0, user.country=PL, connection.url=jdbc:postgresql://localhost/hibernate_tests, java.home=C:\Program Files\Sun\jdk1.5.0_09\jre, java.vm.info=mixed mode, os.version=5.1, c3p0.idle_test_period=3000, path.separator=;, connection.password=hibernate_tests, java.vm.version=1.5.0_09-b03, hibernate.max_fetch_depth=3, hibernate.connection.password=hibernate_tests, user.variant=, java.awt.printerjob=sun.awt.windows.WPrinterJob, sun.io.unicode.encoding=UnicodeLittle, awt.toolkit=sun.awt.windows.WToolkit, hibernate.connection.username=hibernate_tests, user.home=C:\Documents and Settings\kborkowski, java.specification.vendor=Sun Microsystems Inc., hibernate.c3p0.max_statement=50, java.library.path=C:\Program Files\Sun\jdk1.5.0_09\jre\bin;.;C:\WINDOWS\system32;C:\WINDOWS;C:\Program Files\Windows Resource Kits\Tools\;C:\MiKTeX\texmf\miktex\bin;C:\Program Files\ThinkPad\Utilities;C:\WINDOWS\system32;C:\WINDOWS;C:\WINDOWS\System32\Wbem;C:\Program Files\Intel\Wireless\Bin\;C:\Program Files\ATI Technologies\ATI Control Panel;C:\Program Files\PC-Doctor for Windows\;C:\WINDOWS\Downloaded Program Files;C:\IBMTOOLS\Python22;c:\Program Files\Sun\netbeans-5.5rc2\ide7\ant\bin\;C:\Program Files\Common Files\Adobe\AGL;C:\Program Files\GNU\GnuPG, java.vendor.url=http://java.sun.com/, hibernate.connection.driver_class=org.postgresql.Driver, connection.username=hibernate_tests, java.vm.vendor=Sun Microsystems Inc., hibernate.dialect=org.hibernate.dialect.PostgreSQLDialect, java.runtime.name=Java(TM) 2 Runtime Environment, Standard Edition, java.class.path=C:\_ALL_DATA\Resources\Developing\Java\hibernate-3.2\hibernate3.jar;C:\_ALL_DATA\Resources\Developing\Java\jdbc\postgresql-8.1-405.jdbc3.jar;C:\_ALL_DATA\Resources\Developing\Java\hibernate-3.2\lib\commons-collections-2.1.1.jar;C:\_ALL_DATA\Resources\Developing\Java\hibernate-3.2\lib\jdbc2_0-stdext.jar;C:\_ALL_DATA\Resources\Developing\Java\hibernate-3.2\lib\antlr-2.7.6.jar;C:\_ALL_DATA\Resources\Developing\Java\hibernate-3.2\lib\dom4j-1.6.1.jar;C:\_ALL_DATA\Resources\Developing\Java\hibernate-3.2\lib\commons-logging-1.0.4.jar;C:\_ALL_DATA\Resources\Developing\Java\hibernate-3.2\lib\jta.jar;C:\_ALL_DATA\Resources\Developing\Java\hibernate-3.2\lib\c3p0-0.9.0.jar;C:\_ALL_DATA\Resources\Developing\Java\hibernate-3.2\lib\asm-attrs.jar;C:\_ALL_DATA\Resources\Developing\Java\hibernate-3.2\lib\cglib-2.1.3.jar;C:\_ALL_DATA\Resources\Developing\Java\hibernate-3.2\lib\asm.jar;C:\_ALL_DATA\Resources\Developing\Java\logging-log4j-1.2.14\dist\lib\log4j-1.2.14.jar;C:\_ALL_DATA\Noktrim\Projects\Software\Developing\Java\Tests\HibernateTests\build\classes, hibernate.bytecode.use_reflection_optimizer=false, c3p0.timeout=300, java.vm.specification.name=Java Virtual Machine Specification, java.vm.specification.version=1.0, sun.cpu.endian=little, sun.os.patch.level=Dodatek Service Pack 2, connection.isolation=2, java.io.tmpdir=C:\DOCUME~1\KBORKO~1\USTAWI~1\Temp\, java.vendor.url.bug=http://java.sun.com/cgi-bin/bugreport.cgi, c3p0.max_statement=50, os.arch=x86, java.awt.graphicsenv=sun.awt.Win32GraphicsEnvironment, java.ext.dirs=C:\Program Files\Sun\jdk1.5.0_09\jre\lib\ext, user.dir=C:\_ALL_DATA\Noktrim\Projects\Software\Developing\Java\Tests\HibernateTests, hibernate.c3p0.idle_test_period=3000, line.separator=
, java.vm.name=Java HotSpot(TM) Client VM, file.encoding=Cp1250, format_sql=true, java.specification.version=1.5, hibernate.connection.isolation=2, hibernate.show_sql=true}
02:11,000 DEBUG Configuration:1209 - Preparing to build session factory with filters : {}
02:11,000 DEBUG Configuration:1044 - processing extends queue
02:11,000 DEBUG Configuration:1048 - processing collection mappings
02:11,000 DEBUG CollectionSecondPass:41 - Second pass for collection: Company.archive
02:11,000  INFO HbmBinder:2375 - Mapping collection: Company.archive -> companies_archive
02:11,015 DEBUG CollectionSecondPass:57 - Mapped collection key: current_id, index: version, one-to-many: ArchivedCompany
02:11,015 DEBUG Configuration:1059 - processing native query and ResultSetMapping mappings
02:11,015 DEBUG Configuration:1067 - processing association property references
02:11,015 DEBUG Configuration:1089 - processing foreign key constraints
02:11,015 DEBUG Configuration:1172 - resolving reference to class: Company
02:11,031  INFO C3P0ConnectionProvider:50 - C3P0 using driver: org.postgresql.Driver at URL: jdbc:postgresql://localhost/hibernate_tests
02:11,031  INFO C3P0ConnectionProvider:51 - Connection properties: {user=hibernate_tests, password=****}
02:11,031  INFO C3P0ConnectionProvider:54 - autocommit mode: false
02:11,093  INFO MLog:80 - MLog clients using log4j logging.
02:11,125  INFO C3P0Registry:77 - Initializing c3p0-0.9.0 [built 11-July-2005 00:43:29 -0400; debug? true; trace: 10]
02:11,281  INFO C3P0ConnectionProvider:111 - JDBC isolation level: READ_COMMITTED
02:11,296  INFO PoolBackedDataSource:257 - Initializing c3p0 pool... com.mchange.v2.c3p0.PoolBackedDataSource@2acc65 [ connectionPoolDataSource -> com.mchange.v2.c3p0.WrapperConnectionPoolDataSource@16921fd [ acquireIncrement -> 1, acquireRetryAttempts -> 30, acquireRetryDelay -> 1000, autoCommitOnClose -> false, automaticTestTable -> null, breakAfterAcquireFailure -> false, checkoutTimeout -> 0, connectionTesterClassName -> com.mchange.v2.c3p0.impl.DefaultConnectionTester, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, identityToken -> 16921fd, idleConnectionTestPeriod -> 3000, initialPoolSize -> 5, maxIdleTime -> 300, maxPoolSize -> 20, maxStatements -> 0, maxStatementsPerConnection -> 0, minPoolSize -> 5, nestedDataSource -> com.mchange.v2.c3p0.DriverManagerDataSource@1581593 [ description -> null, driverClass -> null, factoryClassLocation -> null, identityToken -> 1581593, jdbcUrl -> jdbc:postgresql://localhost/hibernate_tests, properties -> {user=******, password=******} ], preferredTestQuery -> null, propertyCycle -> 300, testConnectionOnCheckin -> false, testConnectionOnCheckout -> false, usesTraditionalReflectiveProxies -> false ], factoryClassLocation -> null, identityToken -> 2acc65, numHelperThreads -> 3 ]
02:11,328 DEBUG BasicResourcePool:942 - awaitAvailable(): [unknown]
02:11,328 DEBUG BasicResourcePool:1159 - trace com.mchange.v2.resourcepool.BasicResourcePool@766a24 [managed: 0, unused: 0, excluded: 0]
02:11,468 DEBUG BasicResourcePool:1159 - trace com.mchange.v2.resourcepool.BasicResourcePool@766a24 [managed: 1, unused: 1, excluded: 0]
02:11,468 DEBUG BasicResourcePool:1081 - resource age is okay: com.mchange.v2.c3p0.impl.NewPooledConnection@340101 ---> age: 0   max: 300000 [com.mchange.v2.resourcepool.BasicResourcePool@766a24]
02:11,468 DEBUG BasicResourcePool:1159 - trace com.mchange.v2.resourcepool.BasicResourcePool@766a24 [managed: 1, unused: 0, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@340101)
02:11,531  INFO SettingsFactory:81 - RDBMS: PostgreSQL, version: 8.1.5
02:11,531  INFO SettingsFactory:82 - JDBC driver: PostgreSQL Native Driver, version: PostgreSQL 8.1 JDBC3 with SSL (build 405)
02:11,531 DEBUG BasicResourcePool:1159 - trace com.mchange.v2.resourcepool.BasicResourcePool@766a24 [managed: 1, unused: 0, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@340101)
02:11,562  INFO Dialect:141 - Using dialect: org.hibernate.dialect.PostgreSQLDialect
02:11,562  INFO TransactionFactoryFactory:31 - Using default transaction strategy (direct JDBC transactions)
02:11,562  INFO TransactionManagerLookupFactory:33 - No TransactionManagerLookup configured (in JTA environment, use of read-write or transactional second-level cache is not recommended)
02:11,562  INFO SettingsFactory:134 - Automatic flush during beforeCompletion(): disabled
02:11,562  INFO SettingsFactory:138 - Automatic session close at end of transaction: disabled
02:11,578  INFO SettingsFactory:145 - JDBC batch size: 15
02:11,578  INFO SettingsFactory:148 - JDBC batch updates for versioned data: disabled
02:11,578  INFO SettingsFactory:153 - Scrollable result sets: enabled
02:11,578 DEBUG SettingsFactory:157 - Wrap result sets: disabled
02:11,578  INFO SettingsFactory:161 - JDBC3 getGeneratedKeys(): disabled
02:11,578  INFO SettingsFactory:169 - Connection release mode: auto
02:11,578  INFO SettingsFactory:193 - Maximum outer join fetch depth: 3
02:11,578  INFO SettingsFactory:196 - Default batch fetch size: 1
02:11,578  INFO SettingsFactory:200 - Generate SQL with comments: disabled
02:11,578  INFO SettingsFactory:204 - Order SQL updates by primary key: disabled
02:11,593 DEBUG BasicResourcePool:1159 - trace com.mchange.v2.resourcepool.BasicResourcePool@766a24 [managed: 2, unused: 2, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@340101)
02:11,656 DEBUG BasicResourcePool:1159 - trace com.mchange.v2.resourcepool.BasicResourcePool@766a24 [managed: 3, unused: 3, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@340101)
02:11,656  INFO SettingsFactory:369 - Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory
02:11,656  INFO ASTQueryTranslatorFactory:24 - Using ASTQueryTranslatorFactory
02:11,687 DEBUG BasicResourcePool:1159 - trace com.mchange.v2.resourcepool.BasicResourcePool@766a24 [managed: 4, unused: 4, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@340101)
02:11,687  INFO SettingsFactory:212 - Query language substitutions: {}
02:11,687  INFO SettingsFactory:217 - JPA-QL strict compliance: disabled
02:11,687  INFO SettingsFactory:222 - Second-level cache: enabled
02:11,687  INFO SettingsFactory:226 - Query cache: disabled
02:11,687  INFO SettingsFactory:356 - Cache provider: org.hibernate.cache.NoCacheProvider
02:11,703 DEBUG BasicResourcePool:1159 - trace com.mchange.v2.resourcepool.BasicResourcePool@766a24 [managed: 5, unused: 5, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@340101)
02:11,703  INFO SettingsFactory:241 - Optimize cache for minimal puts: disabled
02:11,703  INFO SettingsFactory:250 - Structured second-level cache entries: disabled
02:11,718 DEBUG SQLExceptionConverterFactory:52 - Using dialect defined converter
02:11,718  INFO SettingsFactory:270 - Echoing all SQL to stdout
02:11,718  INFO SettingsFactory:277 - Statistics: enabled
02:11,718  INFO SettingsFactory:281 - Deleted entity synthetic identifier rollback: disabled
02:11,718  INFO SettingsFactory:296 - Default entity-mode: pojo
02:11,796  INFO SessionFactoryImpl:161 - building session factory
02:11,796 DEBUG SessionFactoryImpl:173 - Session factory constructed with filter configurations : {}
02:11,796 DEBUG SessionFactoryImpl:177 - instantiating session factory with properties: {java.vendor=Sun Microsystems Inc., show_sql=true, hibernate.connection.url=jdbc:postgresql://localhost/hibernate_tests, sun.management.compiler=HotSpot Client Compiler, c3p0.min_size=5, os.name=Windows XP, sun.boot.class.path=C:\Program Files\Sun\jdk1.5.0_09\jre\lib\rt.jar;C:\Program Files\Sun\jdk1.5.0_09\jre\lib\i18n.jar;C:\Program Files\Sun\jdk1.5.0_09\jre\lib\sunrsasign.jar;C:\Program Files\Sun\jdk1.5.0_09\jre\lib\jsse.jar;C:\Program Files\Sun\jdk1.5.0_09\jre\lib\jce.jar;C:\Program Files\Sun\jdk1.5.0_09\jre\lib\charsets.jar;C:\Program Files\Sun\jdk1.5.0_09\jre\classes, generate_statistics=true, sun.desktop=windows, hibernate.c3p0.max_size=20, java.vm.specification.vendor=Sun Microsystems Inc., hibernate.generate_statistics=true, c3p0.max_size=20, java.runtime.version=1.5.0_09-b03, hibernate.c3p0.min_size=5, user.name=kborkowski, log4j.configuration=test/hibernate/morethanonce/log4j.properties, connection.driver_class=org.postgresql.Driver, hibernate.c3p0.timeout=300, user.language=pl, sun.boot.library.path=C:\Program Files\Sun\jdk1.5.0_09\jre\bin, dialect=org.hibernate.dialect.PostgreSQLDialect, max_fetch_depth=3, java.version=1.5.0_09, user.timezone=Europe/Belgrade, sun.arch.data.model=32, java.endorsed.dirs=C:\Program Files\Sun\jdk1.5.0_09\jre\lib\endorsed, sun.cpu.isalist=pentium_pro+mmx pentium_pro pentium+mmx pentium i486 i386 i86, sun.jnu.encoding=Cp1250, file.encoding.pkg=sun.io, file.separator=\, java.specification.name=Java Platform API Specification, hibernate.format_sql=true, java.class.version=49.0, user.country=PL, connection.url=jdbc:postgresql://localhost/hibernate_tests, java.home=C:\Program Files\Sun\jdk1.5.0_09\jre, java.vm.info=mixed mode, os.version=5.1, path.separator=;, c3p0.idle_test_period=3000, connection.password=hibernate_tests, java.vm.version=1.5.0_09-b03, hibernate.max_fetch_depth=3, hibernate.connection.password=hibernate_tests, user.variant=, java.awt.printerjob=sun.awt.windows.WPrinterJob, sun.io.unicode.encoding=UnicodeLittle, awt.toolkit=sun.awt.windows.WToolkit, hibernate.connection.username=hibernate_tests, user.home=C:\Documents and Settings\kborkowski, java.specification.vendor=Sun Microsystems Inc., hibernate.c3p0.max_statement=50, java.library.path=C:\Program Files\Sun\jdk1.5.0_09\jre\bin;.;C:\WINDOWS\system32;C:\WINDOWS;C:\Program Files\Windows Resource Kits\Tools\;C:\MiKTeX\texmf\miktex\bin;C:\Program Files\ThinkPad\Utilities;C:\WINDOWS\system32;C:\WINDOWS;C:\WINDOWS\System32\Wbem;C:\Program Files\Intel\Wireless\Bin\;C:\Program Files\ATI Technologies\ATI Control Panel;C:\Program Files\PC-Doctor for Windows\;C:\WINDOWS\Downloaded Program Files;C:\IBMTOOLS\Python22;c:\Program Files\Sun\netbeans-5.5rc2\ide7\ant\bin\;C:\Program Files\Common Files\Adobe\AGL;C:\Program Files\GNU\GnuPG, java.vendor.url=http://java.sun.com/, hibernate.connection.driver_class=org.postgresql.Driver, connection.username=hibernate_tests, java.vm.vendor=Sun Microsystems Inc., hibernate.dialect=org.hibernate.dialect.PostgreSQLDialect, java.runtime.name=Java(TM) 2 Runtime Environment, Standard Edition, java.class.path=C:\_ALL_DATA\Resources\Developing\Java\hibernate-3.2\hibernate3.jar;C:\_ALL_DATA\Resources\Developing\Java\jdbc\postgresql-8.1-405.jdbc3.jar;C:\_ALL_DATA\Resources\Developing\Java\hibernate-3.2\lib\commons-collections-2.1.1.jar;C:\_ALL_DATA\Resources\Developing\Java\hibernate-3.2\lib\jdbc2_0-stdext.jar;C:\_ALL_DATA\Resources\Developing\Java\hibernate-3.2\lib\antlr-2.7.6.jar;C:\_ALL_DATA\Resources\Developing\Java\hibernate-3.2\lib\dom4j-1.6.1.jar;C:\_ALL_DATA\Resources\Developing\Java\hibernate-3.2\lib\commons-logging-1.0.4.jar;C:\_ALL_DATA\Resources\Developing\Java\hibernate-3.2\lib\jta.jar;C:\_ALL_DATA\Resources\Developing\Java\hibernate-3.2\lib\c3p0-0.9.0.jar;C:\_ALL_DATA\Resources\Developing\Java\hibernate-3.2\lib\asm-attrs.jar;C:\_ALL_DATA\Resources\Developing\Java\hibernate-3.2\lib\cglib-2.1.3.jar;C:\_ALL_DATA\Resources\Developing\Java\hibernate-3.2\lib\asm.jar;C:\_ALL_DATA\Resources\Developing\Java\logging-log4j-1.2.14\dist\lib\log4j-1.2.14.jar;C:\_ALL_DATA\Noktrim\Projects\Software\Developing\Java\Tests\HibernateTests\build\classes, hibernate.bytecode.use_reflection_optimizer=false, c3p0.timeout=300, java.vm.specification.name=Java Virtual Machine Specification, java.vm.specification.version=1.0, sun.cpu.endian=little, sun.os.patch.level=Dodatek Service Pack 2, connection.isolation=2, java.io.tmpdir=C:\DOCUME~1\KBORKO~1\USTAWI~1\Temp\, java.vendor.url.bug=http://java.sun.com/cgi-bin/bugreport.cgi, c3p0.max_statement=50, java.awt.graphicsenv=sun.awt.Win32GraphicsEnvironment, os.arch=x86, java.ext.dirs=C:\Program Files\Sun\jdk1.5.0_09\jre\lib\ext, user.dir=C:\_ALL_DATA\Noktrim\Projects\Software\Developing\Java\Tests\HibernateTests, hibernate.c3p0.idle_test_period=3000, line.separator=
, java.vm.name=Java HotSpot(TM) Client VM, file.encoding=Cp1250, format_sql=true, java.specification.version=1.5, hibernate.connection.isolation=2, hibernate.show_sql=true}
02:12,000 DEBUG AbstractEntityPersister:2673 - Static SQL for entity: ArchivedCompany
02:12,000 DEBUG AbstractEntityPersister:2678 -  Version select: select id from companies_archive where id =?
02:12,000 DEBUG AbstractEntityPersister:2681 -  Snapshot select: select archivedco_.id, archivedco_.name as name1_ from companies_archive archivedco_ where archivedco_.id=?
02:12,000 DEBUG AbstractEntityPersister:2684 -  Insert 0: insert into companies_archive (name, current_id, version, id) values (?, ?, ?, ?)
02:12,015 DEBUG AbstractEntityPersister:2685 -  Update 0: update companies_archive set name=? where id=?
02:12,015 DEBUG AbstractEntityPersister:2686 -  Delete 0: delete from companies_archive where id=?
02:12,015 DEBUG AbstractEntityPersister:2673 - Static SQL for entity: Company
02:12,015 DEBUG AbstractEntityPersister:2678 -  Version select: select version from companies where id =?
02:12,015 DEBUG AbstractEntityPersister:2681 -  Snapshot select: select company_.id, company_.version as version0_, company_.name as name0_ from companies company_ where company_.id=?
02:12,015 DEBUG AbstractEntityPersister:2684 -  Insert 0: insert into companies (version, name, id) values (?, ?, ?)
02:12,015 DEBUG AbstractEntityPersister:2685 -  Update 0: update companies set version=?, name=? where id=? and version=?
02:12,015 DEBUG AbstractEntityPersister:2686 -  Delete 0: delete from companies where id=? and version=?
02:12,031 DEBUG AbstractCollectionPersister:548 - Static SQL for collection: Company.archive
02:12,031 DEBUG AbstractCollectionPersister:550 -  Row insert: update companies_archive set current_id=?, version=? where id=?
02:12,031 DEBUG AbstractCollectionPersister:556 -  Row delete: update companies_archive set current_id=null, version=null where current_id=? and id=?
02:12,031 DEBUG AbstractCollectionPersister:559 -  One-shot delete: update companies_archive set current_id=null, version=null where current_id=?
02:12,062 DEBUG EntityLoader:79 - Static select for entity ArchivedCompany: select archivedco0_.id as id1_0_, archivedco0_.current_id as current2_1_0_, archivedco0_.name as name1_0_ from companies_archive archivedco0_ where archivedco0_.id=?
02:12,062 DEBUG EntityLoader:79 - Static select for entity ArchivedCompany: select archivedco0_.id as id1_0_, archivedco0_.current_id as current2_1_0_, archivedco0_.name as name1_0_ from companies_archive archivedco0_ where archivedco0_.id=?
02:12,062 DEBUG EntityLoader:79 - Static select for entity ArchivedCompany: select archivedco0_.id as id1_0_, archivedco0_.current_id as current2_1_0_, archivedco0_.name as name1_0_ from companies_archive archivedco0_ where archivedco0_.id=? for update
02:12,062 DEBUG EntityLoader:79 - Static select for entity ArchivedCompany: select archivedco0_.id as id1_0_, archivedco0_.current_id as current2_1_0_, archivedco0_.name as name1_0_ from companies_archive archivedco0_ where archivedco0_.id=? for update
02:12,062 DEBUG EntityLoader:79 - Static select for entity ArchivedCompany: select archivedco0_.id as id1_0_, archivedco0_.current_id as current2_1_0_, archivedco0_.name as name1_0_ from companies_archive archivedco0_ where archivedco0_.id=? for update
02:12,062 DEBUG EntityLoader:34 - Static select for action ACTION_MERGE on entity ArchivedCompany: select archivedco0_.id as id1_0_, archivedco0_.current_id as current2_1_0_, archivedco0_.name as name1_0_ from companies_archive archivedco0_ where archivedco0_.id=?
02:12,062 DEBUG EntityLoader:34 - Static select for action ACTION_REFRESH on entity ArchivedCompany: select archivedco0_.id as id1_0_, archivedco0_.current_id as current2_1_0_, archivedco0_.name as name1_0_ from companies_archive archivedco0_ where archivedco0_.id=?
02:12,062 DEBUG EntityLoader:79 - Static select for entity Company: select company0_.id as id0_0_, company0_.version as version0_0_, company0_.name as name0_0_ from companies company0_ where company0_.id=?
02:12,062 DEBUG EntityLoader:79 - Static select for entity Company: select company0_.id as id0_0_, company0_.version as version0_0_, company0_.name as name0_0_ from companies company0_ where company0_.id=?
02:12,062 DEBUG EntityLoader:79 - Static select for entity Company: select company0_.id as id0_0_, company0_.version as version0_0_, company0_.name as name0_0_ from companies company0_ where company0_.id=? for update
02:12,093 DEBUG EntityLoader:79 - Static select for entity Company: select company0_.id as id0_0_, company0_.version as version0_0_, company0_.name as name0_0_ from companies company0_ where company0_.id=? for update
02:12,093 DEBUG EntityLoader:79 - Static select for entity Company: select company0_.id as id0_0_, company0_.version as version0_0_, company0_.name as name0_0_ from companies company0_ where company0_.id=? for update
02:12,109 DEBUG EntityLoader:34 - Static select for action ACTION_MERGE on entity Company: select company0_.id as id0_1_, company0_.version as version0_1_, company0_.name as name0_1_, archive1_.current_id as current2_3_, archive1_.id as id3_, archive1_.version as version3_, archive1_.id as id1_0_, archive1_.current_id as current2_1_0_, archive1_.name as name1_0_ from companies company0_ left outer join companies_archive archive1_ on company0_.id=archive1_.current_id where company0_.id=?
02:12,109 DEBUG EntityLoader:34 - Static select for action ACTION_REFRESH on entity Company: select company0_.id as id0_1_, company0_.version as version0_1_, company0_.name as name0_1_, archive1_.current_id as current2_3_, archive1_.id as id3_, archive1_.version as version3_, archive1_.id as id1_0_, archive1_.current_id as current2_1_0_, archive1_.name as name1_0_ from companies company0_ left outer join companies_archive archive1_ on company0_.id=archive1_.current_id where company0_.id=?
02:12,109 DEBUG OneToManyLoader:64 - Static select for one-to-many Company.archive: select archive0_.current_id as current2_1_, archive0_.id as id1_, archive0_.version as version1_, archive0_.id as id1_0_, archive0_.current_id as current2_1_0_, archive0_.name as name1_0_ from companies_archive archive0_ where archive0_.current_id=?
02:12,109 DEBUG SessionFactoryObjectFactory:39 - initializing class SessionFactoryObjectFactory
02:12,109 DEBUG SessionFactoryObjectFactory:76 - registered: 402881b20f0a9bfb010f0a9bfc8d0000 (unnamed)
02:12,109  INFO SessionFactoryObjectFactory:82 - Not binding factory to JNDI, no JNDI name configured
02:12,109 DEBUG SessionFactoryImpl:308 - instantiated session factory
02:12,125 DEBUG SessionFactoryImpl:390 - Checking 0 named HQL queries
02:12,125 DEBUG SessionFactoryImpl:410 - Checking 0 named SQL queries
02:12,156 DEBUG SessionImpl:220 - opened session at timestamp: 11641141321
02:12,156 DEBUG JDBCTransaction:54 - begin
02:12,156 DEBUG ConnectionManager:415 - opening JDBC connection
02:12,156 DEBUG BasicResourcePool:1081 - resource age is okay: com.mchange.v2.c3p0.impl.NewPooledConnection@340101 ---> age: 610   max: 300000 [com.mchange.v2.resourcepool.BasicResourcePool@766a24]
02:12,156 DEBUG BasicResourcePool:1159 - trace com.mchange.v2.resourcepool.BasicResourcePool@766a24 [managed: 5, unused: 4, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@340101)
02:12,156 DEBUG JDBCTransaction:59 - current autocommit status: false
02:12,156 DEBUG JDBCContext:210 - after transaction begin
02:12,171 DEBUG DefaultLoadEventListener:169 - loading entity: [Company#1]
02:12,171 DEBUG DefaultLoadEventListener:328 - attempting to resolve: [Company#1]
02:12,171 DEBUG DefaultLoadEventListener:368 - object not resolved in any cache: [Company#1]
02:12,171 DEBUG AbstractEntityPersister:2970 - Fetching entity: [Company#1]
02:12,171 DEBUG Loader:1776 - loading entity: [Company#1]
02:12,171 DEBUG AbstractBatcher:358 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
02:12,171 DEBUG SQL:393 - 
    select
        company0_.id as id0_0_,
        company0_.version as version0_0_,
        company0_.name as name0_0_ 
    from
        companies company0_ 
    where
        company0_.id=?
Hibernate: 
    select
        company0_.id as id0_0_,
        company0_.version as version0_0_,
        company0_.name as name0_0_ 
    from
        companies company0_ 
    where
        company0_.id=?
02:12,171 DEBUG AbstractBatcher:476 - preparing statement
02:12,187 DEBUG LongType:80 - binding '1' to parameter: 1
02:12,203 DEBUG AbstractBatcher:374 - about to open ResultSet (open ResultSets: 0, globally: 0)
02:12,203 DEBUG Loader:682 - processing result set
02:12,203 DEBUG Loader:687 - result set row: 0
02:12,203 DEBUG Loader:1164 - result row: EntityKey[Company#1]
02:12,203 DEBUG Loader:1346 - Initializing object from ResultSet: [Company#1]
02:12,203 DEBUG AbstractEntityPersister:1966 - Hydrating entity: [Company#1]
02:12,203 DEBUG IntegerType:122 - returning '0' as column: version0_0_
02:12,203 DEBUG StringType:122 - returning 'Test_01' as column: name0_0_
02:12,218 DEBUG TwoPhaseLoad:75 - Version: 0
02:12,218 DEBUG Loader:709 - done processing result set (1 rows)
02:12,218 DEBUG AbstractBatcher:381 - about to close ResultSet (open ResultSets: 1, globally: 1)
02:12,218 DEBUG AbstractBatcher:366 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
02:12,218 DEBUG AbstractBatcher:525 - closing statement
02:12,218 DEBUG Loader:839 - total objects hydrated: 1
02:12,218 DEBUG TwoPhaseLoad:107 - resolving associations for [Company#1]
02:12,218 DEBUG CollectionLoadContext:141 - creating collection wrapper:[Company.archive#1]
02:12,234 DEBUG TwoPhaseLoad:206 - done materializing entity [Company#1]
02:12,234 DEBUG StatefulPersistenceContext:748 - initializing non-lazy collections
02:12,234 DEBUG Loader:1807 - done entity load
02:12,234 DEBUG DefaultInitializeCollectionEventListener:41 - initializing collection [Company.archive#1]
02:12,234 DEBUG DefaultInitializeCollectionEventListener:47 - checking second-level cache
02:12,234 DEBUG DefaultInitializeCollectionEventListener:59 - collection not cached
02:12,234 DEBUG Loader:1910 - loading collection: [Company.archive#1]
02:12,234 DEBUG AbstractBatcher:358 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
02:12,234 DEBUG SQL:393 - 
    select
        archive0_.current_id as current2_1_,
        archive0_.id as id1_,
        archive0_.version as version1_,
        archive0_.id as id1_0_,
        archive0_.current_id as current2_1_0_,
        archive0_.name as name1_0_ 
    from
        companies_archive archive0_ 
    where
        archive0_.current_id=?
Hibernate: 
    select
        archive0_.current_id as current2_1_,
        archive0_.id as id1_,
        archive0_.version as version1_,
        archive0_.id as id1_0_,
        archive0_.current_id as current2_1_0_,
        archive0_.name as name1_0_ 
    from
        companies_archive archive0_ 
    where
        archive0_.current_id=?
02:12,234 DEBUG AbstractBatcher:476 - preparing statement
02:12,234 DEBUG LongType:80 - binding '1' to parameter: 1
02:12,234 DEBUG AbstractBatcher:374 - about to open ResultSet (open ResultSets: 0, globally: 0)
02:12,234 DEBUG Loader:1040 - result set contains (possibly empty) collection: [Company.archive#1]
02:12,250 DEBUG CollectionLoadContext:84 - uninitialized collection: initializing
02:12,250 DEBUG Loader:682 - processing result set
02:12,250 DEBUG Loader:709 - done processing result set (0 rows)
02:12,250 DEBUG AbstractBatcher:381 - about to close ResultSet (open ResultSets: 1, globally: 1)
02:12,250 DEBUG AbstractBatcher:366 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
02:12,250 DEBUG AbstractBatcher:525 - closing statement
02:12,250 DEBUG Loader:839 - total objects hydrated: 0
02:12,250 DEBUG CollectionLoadContext:262 - 1 collections were found in result set for role: Company.archive
02:12,250 DEBUG CollectionLoadContext:206 - collection fully initialized: [Company.archive#1]
02:12,250 DEBUG CollectionLoadContext:272 - 1 collections initialized for role: Company.archive
02:12,250 DEBUG StatefulPersistenceContext:748 - initializing non-lazy collections
02:12,265 DEBUG Loader:1934 - done loading collection
02:12,265 DEBUG DefaultInitializeCollectionEventListener:61 - collection initialized
02:12,265 DEBUG JDBCTransaction:103 - commit
02:12,265 DEBUG SessionImpl:337 - automatically flushing session
02:12,265 DEBUG AbstractFlushingEventListener:58 - flushing session
02:12,265 DEBUG AbstractFlushingEventListener:111 - processing flush-time cascades
02:12,265 DEBUG Cascade:115 - processing cascade ACTION_SAVE_UPDATE for: Company
02:12,265 DEBUG Cascade:291 - cascade ACTION_SAVE_UPDATE for collection: Company.archive
02:12,265 DEBUG CascadingAction:216 - cascading to saveOrUpdate: ArchivedCompany
02:12,265 DEBUG AbstractSaveEventListener:489 - transient instance of: ArchivedCompany
02:12,265 DEBUG DefaultSaveOrUpdateEventListener:161 - saving transient instance
02:12,265 DEBUG AbstractBatcher:358 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
02:12,265 DEBUG SQL:393 - 
    select
        nextval ('database_level_id_generator')
Hibernate: 
    select
        nextval ('database_level_id_generator')
02:12,265 DEBUG AbstractBatcher:476 - preparing statement
02:12,281 DEBUG SequenceGenerator:82 - Sequence identifier generated: 2
02:12,281 DEBUG AbstractBatcher:366 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
02:12,281 DEBUG AbstractBatcher:525 - closing statement
02:12,281 DEBUG AbstractSaveEventListener:113 - generated identifier: 2, using strategy: org.hibernate.id.SequenceGenerator
02:12,281 DEBUG AbstractSaveEventListener:152 - saving [ArchivedCompany#2]
02:12,281 DEBUG Cascade:306 - done cascade ACTION_SAVE_UPDATE for collection: Company.archive
02:12,281 DEBUG Cascade:317 - deleting orphans for collection: Company.archive
02:12,281 DEBUG Cascade:327 - done deleting orphans for collection: Company.archive
02:12,281 DEBUG Cascade:150 - done processing cascade ACTION_SAVE_UPDATE for: Company
02:12,281 DEBUG AbstractFlushingEventListener:154 - dirty checking collections
02:12,281 DEBUG CollectionEntry:177 - Collection dirty: [Company.archive#1]
02:12,281 DEBUG AbstractFlushingEventListener:171 - Flushing entities and processing referenced collections
02:12,296 DEBUG AbstractEntityPersister:3116 - Company.name is dirty
02:12,296 DEBUG DefaultFlushEntityEventListener:229 - Updating entity: [Company#1]
02:12,296 DEBUG Versioning:27 - Incrementing: 0 to 1
02:12,296 DEBUG Collections:176 - Collection found: [Company.archive#1], was: [Company.archive#1] (initialized)
02:12,296 DEBUG AbstractFlushingEventListener:210 - Processing unreferenced collections
02:12,296 DEBUG AbstractFlushingEventListener:224 - Scheduling collection removes/(re)creates/updates
02:12,296 DEBUG AbstractFlushingEventListener:85 - Flushed: 1 insertions, 1 updates, 0 deletions to 2 objects
02:12,296 DEBUG AbstractFlushingEventListener:91 - Flushed: 0 (re)creations, 1 updates, 0 removals to 1 collections
02:12,296 DEBUG Printer:83 - listing entities:
02:12,296 DEBUG Printer:90 - test.hibernate.morethanonce.Company
02:12,296 DEBUG Printer:90 - test.hibernate.morethanonce.Company
02:12,296 DEBUG AbstractFlushingEventListener:290 - executing flush
02:12,296 DEBUG ConnectionManager:463 - registering flush begin
02:12,296 DEBUG AbstractEntityPersister:2139 - Inserting entity: [ArchivedCompany#2]
02:12,312 DEBUG AbstractBatcher:358 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
02:12,312 DEBUG SQL:393 - 
    insert 
    into
        companies_archive
        (name, current_id, version, id) 
    values
        (?, ?, ?, ?)
Hibernate: 
    insert 
    into
        companies_archive
        (name, current_id, version, id) 
    values
        (?, ?, ?, ?)
02:12,312 DEBUG AbstractBatcher:476 - preparing statement
02:12,312 DEBUG AbstractEntityPersister:1927 - Dehydrating entity: [ArchivedCompany#2]
02:12,312 DEBUG StringType:80 - binding 'Test_01' to parameter: 1
02:12,312 DEBUG LongType:80 - binding '1' to parameter: 2
02:12,312 DEBUG IntegerType:80 - binding '0' to parameter: 3
02:12,312 DEBUG LongType:80 - binding '2' to parameter: 4
02:12,312 DEBUG AbstractBatcher:44 - Executing batch size: 1
02:12,312 DEBUG AbstractBatcher:366 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
02:12,312 DEBUG AbstractBatcher:525 - closing statement
02:12,312 DEBUG AbstractEntityPersister:2274 - Updating entity: [Company#1]
02:12,312 DEBUG AbstractEntityPersister:2276 - Existing version: 0 -> New version: 1
02:12,312 DEBUG AbstractBatcher:358 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
02:12,312 DEBUG SQL:393 - 
    update
        companies 
    set
        version=?,
        name=? 
    where
        id=? 
        and version=?
Hibernate: 
    update
        companies 
    set
        version=?,
        name=? 
    where
        id=? 
        and version=?
02:12,328 DEBUG AbstractBatcher:476 - preparing statement
02:12,328 DEBUG AbstractEntityPersister:1927 - Dehydrating entity: [Company#1]
02:12,328 DEBUG IntegerType:80 - binding '1' to parameter: 1
02:12,328 DEBUG StringType:80 - binding 'Test_02' to parameter: 2
02:12,328 DEBUG LongType:80 - binding '1' to parameter: 3
02:12,328 DEBUG IntegerType:80 - binding '0' to parameter: 4
02:12,343 DEBUG AbstractBatcher:366 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
02:12,343 DEBUG AbstractBatcher:525 - closing statement
02:12,343 DEBUG AbstractCollectionPersister:1515 - Updating rows of collection: Company.archive#1
02:12,343 DEBUG AbstractCollectionPersister:1522 - done updating rows: 0 updated
02:12,343 DEBUG AbstractCollectionPersister:1313 - Inserting rows of collection: [Company.archive#1]
02:12,343 DEBUG AbstractBatcher:358 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
02:12,343 DEBUG SQL:393 - 
    update
        companies_archive 
    set
        current_id=?,
        version=? 
    where
        id=?
Hibernate: 
    update
        companies_archive 
    set
        current_id=?,
        version=? 
    where
        id=?
02:12,343 DEBUG AbstractBatcher:476 - preparing statement
02:12,343 DEBUG LongType:80 - binding '1' to parameter: 1
02:12,343 DEBUG IntegerType:80 - binding '0' to parameter: 2
02:12,343 DEBUG LongType:80 - binding '2' to parameter: 3
02:12,343 DEBUG AbstractCollectionPersister:1390 - done inserting rows: 1 inserted
02:12,359 DEBUG AbstractBatcher:44 - Executing batch size: 1
02:12,359 DEBUG AbstractBatcher:366 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
02:12,359 DEBUG AbstractBatcher:525 - closing statement
02:12,359 DEBUG ConnectionManager:472 - registering flush end
02:12,359 DEBUG AbstractFlushingEventListener:321 - post flush
02:12,359 DEBUG JDBCContext:201 - before transaction completion
02:12,359 DEBUG SessionImpl:393 - before transaction completion
02:12,421 DEBUG JDBCTransaction:116 - committed JDBC Connection
02:12,421 DEBUG JDBCContext:215 - after transaction completion
02:12,421 DEBUG ConnectionManager:398 - aggressively releasing JDBC connection
02:12,421 DEBUG ConnectionManager:435 - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
02:12,421 DEBUG BasicResourcePool:1159 - trace com.mchange.v2.resourcepool.BasicResourcePool@766a24 [managed: 5, unused: 4, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@340101)
02:12,421 DEBUG SessionImpl:422 - after transaction completion
02:12,421 DEBUG SessionImpl:273 - closing session
02:12,421 DEBUG ConnectionManager:369 - connection already null in cleanup : no action

Problem: Why does Hibernate generate an update operation on the companies_archive table when the insert statement was performed on this table earlier? What should I do to elimane this update operation?

gopalsaha · **Joined:** Tue Feb 24, 2004 11:42 am **Posts:** 56

You have
<map name="archive" lazy="true" cascade="all-delete-orphan">
<key column="current_id" not-null="true"/>
<map-key column="version" type="integer"/>
<one-to-many entity-name="ArchivedCompany"/>
</map>

try this
<map name="archive" inverse="true" lazy="true" cascade="all-delete-orphan">
<key column="current_id" not-null="true"/>
<map-key column="version" type="integer"/>
<one-to-many entity-name="ArchivedCompany"/>
</map>

the inverse="true" will stop it. its because the way the relationship is managed
hope this helps and Please do rate

kborkowski · **Posted:** Tue Nov 21, 2006 1:11 pm

Dear gopalsaha,

I've done as you said and it seems that this is not a solution. Now Hibernate doesn't perform any kind of operation on the "companies_archive" table.

You suggested that I should use an "inverse" attribute, but I would like to remind you that we have a paragraph 7.4.1. in the "Hibernate Reference Documentation (Version: 3.2.0.ga)" where it is said that:

Quote:

If you use a List (or other indexed collection) you need to set the key column of the foreign key to not null,
and let Hibernate manage the association from the collections side to maintain the index of each element
(making the other side virtually inverse by setting update="false" and insert="false")

If you have any other idea, please let me know.

Best regards

gopalsaha · **Joined:** Tue Feb 24, 2004 11:42 am **Posts:** 56

I have run your stuff against oracle db and the log is

Hibernate: select company0_.ID as ID2_0_, company0_.version as version2_0_, company0_.name as name2_0_ from companies company0_ where company0_.ID=?
22-Nov-2006 13:11:47 org.hibernate.cfg.SettingsFactory buildSettings
INFO: Deleted entity synthetic identifier rollback: disabled
22-Nov-2006 13:11:47 org.hibernate.cfg.SettingsFactory buildSettings
INFO: Default entity-mode: pojo
22-Nov-2006 13:11:47 org.hibernate.impl.SessionFactoryImpl <init>
INFO: building session factory
22-Nov-2006 13:11:47 net.sf.ehcache.config.ConfigurationFactory parseConfiguration
WARNING: No configuration found. Configuring ehcache from ehcache-failsafe.xml found in the classpath: jar:file:/C:/Documents%20and%20Settings/GSaha/.maven/repository/ehcache/jars/ehcache-1.2.2.jar!/ehcache-failsafe.xml
22-Nov-2006 13:11:48 org.hibernate.impl.SessionFactoryObjectFactory addInstance
INFO: Not binding factory to JNDI, no JNDI name configured
Hibernate: select archive0_.current_id as current2_1_, archive0_.ID as ID1_, archive0_.version as version1_, archive0_.ID as ID3_0_, archive0_.current_id as current2_3_0_, archive0_.name as name3_0_ from companies_archive archive0_ where archive0_.current_id=?
Hibernate: select hibernate_sequence.nextval from dual
Hibernate: insert into companies_archive (name, current_id, version, ID) values (?, ?, ?, ?)
Hibernate: update companies set version=?, name=? where ID=? and version=?
Hibernate: update companies_archive set current_id=?, version=? where ID=?

Now the answer to the question why the second update

The second update is to update the version in the companies_archieve table and you cannot stop it.
it will insert a new record in the companies archieve because thats what you are asking your code to do when u call updatename

and yes i misjudged your question first time and said about inverse

Hope this helps and if so please do rate

kborkowski · **Posted:** Wed Nov 22, 2006 10:39 am

Dear gopalsaha,

You would see that the update to the companies_acrhive table does not make any sense, if you would take a second look at the log from my first post in this thread. It is because the values set with the insert command are correct and the update statement just only overrides them with exactly the same values.

Considering the whole talk about the automatic dirty checking, cascading save and transactional write-behind (see the chapter 2.1. "Hello World with Hibernate" from the "Hibernate in Action") I think that the one of these is very probable:

I've produced incorrect code
there is a bug in Hibernate
the whole talk about the... is just only a marketing

One way or another I think that the thread must go on because I still don't know the answer.

Anyway I want to thank you for your help. I'm looking forward to receiving your suggestions and ideas.

Best regards

Marjon · **Joined:** Wed Nov 22, 2006 1:07 pm **Posts:** 1

Hi kborkowski ,

I had a similar problem.
I added update="false" to the properties in my mapping file, and now it only updates once. But, I'm using native SQL (stored procedures), so I'm not sure it will work in your case. It's worth a try though.

Hope this helps,