Hi all,

I have a couple of classes:

public class Parent {
Long id;
String name;

List children;
}

public class Child {
Long id;
String name;
}

my parent class mapping is the following:

<class name="Parent" table="parent">
<id name="id" type="long" column="id">
<generator class="sequence">
<param name="sequence">parent_seq</param>
</generator>
</id>

<property name="name" type="string" column="name"/>
<list name="children" cascade="all" lazy="false">
<key column="parent_id"/>
<index column="position"/>
<one-to-many class="Child"/>
</list>
</class>

I created a very simple graph:

Parent parent = new Parent("John");
Child child = new Child("George");
List children = new ArrayList();
children.add(child);
parent.setChildren(children);

When I call session.save(parent) hibernate executes 5(!) SQL statements:

insert into parent....
insert into child...
update parent....
update child...
update child set parent_id....

I understand the purpose of statements 1,2 and 5. But why does it execute 3 and 4?

Any advice would be appreciated!!!

Emmanuel,

Thanks much!!! I've seen this article before but it seems it is not the case because the article is about bidirectional associations. In my case Child DOESN'T HAVE reference to parent.

Could you plase explain why Hibernate executes queries 3 and 4. They don't do anything and are analogous to inserts 1 and 2.

Thanks again for you courtesy!!!

Can you show the full mapping, the logs, the real code executed (from open() to close()).

My real parent class mapping in the following

<class name="FinancialStatement" table="financial_statement">
<id name="id" type="long" column="id">
<generator class="sequence">
<param name="sequence">financial_statement_seq</param>
</generator>
</id>

<version name="version" column="version" type="int"/>
<list name="financialItemList" cascade="all" lazy="false">
<key column="financial_statement_id"/>
<index column="position"/>
<one-to-many class="FinancialItem"/>
</list>
</class>

Child class is

<class name="FinancialItem" table="financial_item">
<id name="id" type="long" column="id">
<generator class="sequence">
<param name="sequence">financial_item_seq</param>
</generator>
</id>

<version name="version" column="version" type="int"/>
<property name="source" column="source" type="string"/>
<property name="reason" column="reason" type="string"/>
<property name="included" column="included" type="boolean"/>
..........
</class>

It is very difficult to show the real code (there is very complex infrastructure of wrapper classes) but basically I just open session, save FinancialStatement with one FinancialItem and close the session.

The log is

testing: class FinancialStatement
13:03:13,863 INFO Environment:432 - Hibernate 2.1 rc1
13:03:13,878 INFO Environment:466 - loaded properties from resource hibernate.properties: {hibernate.cglib.use_reflection_optimizer=false, hibernate.dialect=net.sf.hibernate.dialect.DB2Dialect}
13:03:13,894 INFO Environment:504 - JVM does not support LinkedHasMap, LinkedHashSet - ordered maps and sets disabled
13:03:13,925 INFO Environment:507 - using workaround for JVM bug in java.sql.Timestamp
13:03:13,941 INFO Configuration:287 - Mapping resource: FinancialStatement.hbm.xml
13:03:14,050 DEBUG DTDEntityResolver:20 - trying to locate http://hibernate.sourceforge.net/hibern ... ng-2.0.dtd in classpath under net/sf/hibernate/
13:03:14,066 DEBUG DTDEntityResolver:29 - found http://hibernate.sourceforge.net/hibern ... ng-2.0.dtd in classpath
13:03:14,394 INFO Binder:196 - Mapping class: FinancialStatement -> financial_statement
13:03:14,519 DEBUG Binder:418 - Mapped property: id -> id, type: long
13:03:14,535 DEBUG Binder:418 - Mapped property: version -> version, type: integer
13:03:14,597 DEBUG Binder:418 - Mapped property: auditInfo -> create_date, update_date, create_id, update_id, type: AuditInfoType
13:03:14,628 DEBUG Binder:418 - Mapped property: financialItemList, type: java.util.List
13:03:14,644 INFO Configuration:287 - Mapping resource: FinancialItem.hbm.xml
13:03:14,675 DEBUG DTDEntityResolver:20 - trying to locate http://hibernate.sourceforge.net/hibern ... ng-2.0.dtd in classpath under net/sf/hibernate/
13:03:14,706 DEBUG DTDEntityResolver:29 - found http://hibernate.sourceforge.net/hibern ... ng-2.0.dtd in classpath
13:03:15,331 INFO Binder:196 - Mapping class: FinancialItem -> financial_item
13:03:15,363 DEBUG Binder:418 - Mapped property: id -> id, type: long
13:03:15,378 DEBUG Binder:418 - Mapped property: version -> version, type: integer
13:03:15,394 DEBUG Binder:418 - Mapped property: auditInfo -> create_date, update_date, create_id, update_id, type: AuditInfoType
13:03:15,410 DEBUG Binder:418 - Mapped property: source -> source, type: string
13:03:15,441 DEBUG Binder:418 - Mapped property: reason -> reason, type: string
13:03:15,456 DEBUG Binder:418 - Mapped property: included -> included, type: boolean
13:03:15,488 DEBUG Binder:418 - Mapped property: description -> description, type: string
13:03:15,503 DEBUG Binder:418 - Mapped property: overrideIndicator -> override_indicator, type: boolean
13:03:15,535 DEBUG Binder:418 - Mapped property: deferredIndicator -> deferred_indicator, type: boolean
13:03:15,550 DEBUG Binder:418 - Mapped property: rentalIndicator -> rental_indicator, type: boolean
13:03:15,581 DEBUG Binder:418 - Mapped property: incomeDetailList, type: java.util.Collection
13:03:15,597 DEBUG Binder:418 - Mapped property: expenseDetailList, type: java.util.Collection
13:03:15,628 DEBUG Binder:418 - Mapped property: assetDetailList, type: java.util.Collection
13:03:15,644 DEBUG Binder:418 - Mapped property: liabilityDetailList, type: java.util.Collection
13:03:15,660 INFO Configuration:287 - Mapping resource: FinancialItemDetail.hbm.xml
13:03:15,691 DEBUG DTDEntityResolver:20 - trying to locate http://hibernate.sourceforge.net/hibern ... ng-2.0.dtd in classpath under net/sf/hibernate/
13:03:15,722 DEBUG DTDEntityResolver:29 - found http://hibernate.sourceforge.net/hibern ... ng-2.0.dtd in classpath
13:03:15,769 INFO Binder:196 - Mapping class: FinancialItemDetail -> financial_item_detail
13:03:15,800 DEBUG Binder:418 - Mapped property: id -> id, type: long
13:03:15,816 DEBUG Binder:418 - Mapped property: version -> version, type: integer
13:03:15,847 DEBUG Binder:418 - Mapped property: auditInfo -> create_date, update_date, create_id, update_id, type: AuditInfoType
13:03:15,878 DEBUG Binder:418 - Mapped property: amount -> amount, type: CurrencyType
13:03:15,910 DEBUG Binder:418 - Mapped property: reasonForChange -> reason_for_change, type: string
13:03:15,941 DEBUG Binder:418 - Mapped property: description -> description, type: string
13:03:15,956 DEBUG Binder:418 - Mapped property: payoffAmount -> payoff_amount, type: CurrencyType
13:03:16,035 INFO Binder:142 - Mapping subclass: BalanceSheetDetail -> financial_item_detail
13:03:16,050 DEBUG Binder:418 - Mapped property: expenseDetailList, type: java.util.Collection
13:03:16,081 INFO Binder:142 - Mapping subclass: AssetDetail -> financial_item_detail
13:03:16,097 DEBUG Binder:418 - Mapped property: incomeDetailList, type: java.util.Collection
13:03:16,113 INFO Binder:142 - Mapping subclass: LiabilityDetail -> financial_item_detail
13:03:16,144 DEBUG Binder:418 - Mapped property: creditLimit -> credit_limit, type: CurrencyType
13:03:16,160 INFO Binder:142 - Mapping subclass: IncomeStatementDetail -> financial_item_detail
13:03:16,175 DEBUG Binder:418 - Mapped property: frequency -> frequency, type: string
13:03:16,206 INFO Binder:142 - Mapping subclass: ExpenseDetail -> financial_item_detail
13:03:16,222 DEBUG Binder:418 - Mapped property: estimatedIndicator -> estimated_indicator, type: boolean
13:03:16,253 INFO Binder:142 - Mapping subclass: IncomeDetail -> financial_item_detail
13:03:16,269 DEBUG Binder:418 - Mapped property: nonTaxable -> non_taxable, type: boolean
13:03:16,285 DEBUG Binder:418 - Mapped property: netIndicator -> net_indicator, type: boolean
13:03:16,316 INFO Configuration:565 - processing one-to-many association mappings
13:03:16,331 DEBUG Binder:1279 - Second pass for collection: FinancialStatement.financialItemList
13:03:16,363 INFO Binder:1102 - Mapping collection: FinancialStatement.financialItemList -> financial_item
13:03:16,378 DEBUG Binder:1291 - Mapped collection key: financial_statement_id, index: position, one-to-many: FinancialItem
13:03:16,410 DEBUG Binder:1279 - Second pass for collection: FinancialItem.incomeDetailList
13:03:16,425 INFO Binder:1102 - Mapping collection: FinancialItem.incomeDetailList -> financial_item_detail
13:03:16,456 DEBUG Binder:1291 - Mapped collection key: financial_item_id, one-to-many: IncomeDetail
13:03:16,472 DEBUG Binder:1279 - Second pass for collection: FinancialItem.expenseDetailList
13:03:16,503 INFO Binder:1102 - Mapping collection: FinancialItem.expenseDetailList -> financial_item_detail
13:03:16,519 DEBUG Binder:1291 - Mapped collection key: financial_item_id, one-to-many: ExpenseDetail
13:03:16,550 DEBUG Binder:1279 - Second pass for collection: FinancialItem.assetDetailList
13:03:16,566 INFO Binder:1102 - Mapping collection: FinancialItem.assetDetailList -> financial_item_detail
13:03:16,597 DEBUG Binder:1291 - Mapped collection key: financial_item_id, one-to-many: AssetDetail
13:03:16,613 DEBUG Binder:1279 - Second pass for collection: FinancialItem.liabilityDetailList
13:03:16,644 INFO Binder:1102 - Mapping collection: FinancialItem.liabilityDetailList -> financial_item_detail
13:03:16,660 DEBUG Binder:1291 - Mapped collection key: financial_item_id, one-to-many: LiabilityDetail
13:03:16,691 DEBUG Binder:1279 - Second pass for collection: BalanceSheetDetail.expenseDetailList
13:03:16,722 INFO Binder:1102 - Mapping collection: BalanceSheetDetail.expenseDetailList -> financial_item_detail
13:03:16,738 DEBUG Binder:1291 - Mapped collection key: parent_id, one-to-many: ExpenseDetail
13:03:16,769 DEBUG Binder:1279 - Second pass for collection: AssetDetail.incomeDetailList
13:03:16,785 INFO Binder:1102 - Mapping collection: AssetDetail.incomeDetailList -> financial_item_detail
13:03:16,816 DEBUG Binder:1291 - Mapped collection key: parent_id, one-to-many: IncomeDetail
13:03:16,831 INFO Configuration:574 - processing one-to-one association property references
13:03:16,863 INFO Configuration:599 - processing foreign key constraints
13:03:16,878 DEBUG Configuration:609 - resolving reference to class: AssetDetail
13:03:16,910 DEBUG Configuration:609 - resolving reference to class: FinancialItem
13:03:16,925 DEBUG Configuration:609 - resolving reference to class: BalanceSheetDetail
13:03:16,941 DEBUG Configuration:609 - resolving reference to class: FinancialStatement
13:03:17,003 INFO Dialect:82 - Using dialect: net.sf.hibernate.dialect.DB2Dialect
13:03:17,019 INFO SettingsFactory:62 - Use outer join fetching: true
13:03:17,050 INFO ConnectionProviderFactory:53 - Initializing connection provider: org.springframework.orm.hibernate.LocalDataSourceConnectionProvider
13:03:17,081 INFO TransactionManagerLookupFactory:33 - No TransactionManagerLookup configured (in JTA environment, use of process level read-write cache is not recommended)
13:03:17,425 INFO SettingsFactory:89 - Use scrollable result sets: true
13:03:17,441 INFO SettingsFactory:99 - Query language substitutions: {}
13:03:17,472 INFO SettingsFactory:110 - cache provider: net.sf.ehcache.hibernate.Provider
13:03:17,519 INFO Configuration:1038 - instantiating and configuring caches
13:03:17,691 INFO SessionFactoryImpl:118 - building session factory
13:03:17,722 DEBUG SessionFactoryImpl:124 - instantiating session factory with properties: {java.assistive=ON, java.runtime.name=Java(TM) 2 Runtime Environment, Standard Edition, sun.boot.library.path=C:\Program Files\IBM\WebSphere Studio\eclipse\jre\bin, java.vm.version=1.3.1, java.vm.vendor=IBM Corporation, java.vendor.url=http://www.ibm.com/, path.separator=;, java.vm.name=Classic VM, file.encoding.pkg=sun.io, use_outer_join=true, java.vm.specification.name=Java Virtual Machine Specification, user.dir=C:\codebase\BK_CLO\workspace\BankCLOBusinessObjectModelTest, java.runtime.version=1.3.1, java.fullversion=J2RE 1.3.1 IBM Windows 32 build cn131-20020710 (JIT enabled: jitc), java.awt.graphicsenv=sun.awt.Win32GraphicsEnvironment, os.arch=x86, java.io.tmpdir=C:\DOCUME~1\dk65861\LOCALS~1\Temp\, line.separator=
, java.vm.specification.vendor=Sun Microsystems Inc., java.awt.fonts=, os.name=Windows XP, java.library.path=C:\Program Files\IBM\WebSphere Studio\eclipse\jre\bin;.;C:\WINDOWS\System32;C:\WINDOWS;C:\orant\bin;C:\Perl\bin\;C:\WINDOWS\system32;C:\WINDOWS;C:\WINDOWS\System32\Wbem;C:\Program Files\IBM\Personal Communications\;C:\Program Files\IBM\Trace Facility\;c:\Program Files\Starbase\StarGate SDK\Lib;C:\WINDOWS\System32\;C:\WINDOWS\;C:\Program Files\Rational\common;C:\Program Files\Rational\Rose\TopLink\;C:\Program Files\Oracle\jre\1.1.8\bin;C:\Program Files\Microsoft SQL Server\80\Tools\BINN;C:\Ant\Bin;C:\SQLlib\BIN;C:\SQLlib\FUNCTION;C:\SQLlib\SAMPLES\REPL;C:\SQLlib\HELP;C:\IBM\IMNNQ, java.specification.name=Java Platform API Specification, java.class.version=46.0, invokedviajava=, os.version=5.1, user.home=C:\Documents and Settings\dk65861, user.timezone=America/Chicago, java.awt.printerjob=sun.awt.windows.WPrinterJob, file.encoding=Cp1252, java.specification.version=1.3, show_sql=true, user.name=dk65861, java.class.path=C:/Program Files/IBM/WebSphere Studio/eclipse/plugins/org.eclipse.jdt.junit_2.0.1/junitsupport.jar;C:\codebase\BK_CLO\workspace\BankCLOPersistenceManagement\build;C:\www\inf\third_party\Spring-M-4\spring.jar;C:\www\inf\third_party\aop-alliance\aopalliance.jar;C:\codebase\BK_CLO\workspace\BankCLOPersistenceManagement\build;C:\codebase\BK_CLO\workspace\BankCLOCommon\build;C:\SQLlib\java12\db2java.zip;C:\www\inf\third_party\Spring-M-4\spring.jar;C:\www\inf\third_party\hibernate-2.1\hibernate2.jar;C:\www\inf\third_party\hibernate-2.1\lib\ant.jar;C:\www\inf\third_party\hibernate-2.1\lib\c3p0.jar;C:\www\inf\third_party\hibernate-2.1\lib\cglib2.jar;C:\www\inf\third_party\hibernate-2.1\lib\commons-beanutils.jar;C:\www\inf\third_party\hibernate-2.1\lib\commons-collections.jar;C:\www\inf\third_party\hibernate-2.1\lib\commons-dbcp.jar;C:\www\inf\third_party\hibernate-2.1\lib\commons-lang.jar;C:\www\inf\third_party\hibernate-2.1\lib\commons-logging.jar;C:\www\inf\third_party\hibernate-2.1\lib\commons-pool.jar;C:\www\inf\third_party\hibernate-2.1\lib\concurrent.jar;C:\www\inf\third_party\hibernate-2.1\lib\connector.jar;C:\www\inf\third_party\hibernate-2.1\lib\dom4j.jar;C:\www\inf\third_party\hibernate-2.1\lib\ehcache.jar;C:\www\inf\third_party\hibernate-2.1\lib\hibernate-tools.jar;C:\www\inf\third_party\hibernate-2.1\lib\jaas.jar;C:\www\inf\third_party\hibernate-2.1\lib\jcs.jar;C:\www\inf\third_party\hibernate-2.1\lib\jdbc2_0-stdext.jar;C:\www\inf\third_party\hibernate-2.1\lib\jgroups.jar;C:\www\inf\third_party\hibernate-2.1\lib\jta.jar;C:\www\inf\third_party\hibernate-2.1\lib\junit.jar;C:\www\inf\third_party\hibernate-2.1\lib\log4j-1.2.8.jar;C:\www\inf\third_party\hibernate-2.1\lib\odmg.jar;C:\www\inf\third_party\hibernate-2.1\lib\optional.jar;C:\www\inf\third_party\hibernate-2.1\lib\oscache.jar;C:\www\inf\third_party\hibernate-2.1\lib\proxool.jar;C:\www\inf\third_party\hibernate-2.1\lib\swarmcache.jar;C:\www\inf\third_party\hibernate-2.1\lib\xalan.jar;C:\www\inf\third_party\hibernate-2.1\lib\xerces.jar;C:\www\inf\third_party\hibernate-2.1\lib\xml-apis.jar, java.vm.specification.version=1.0, java.home=C:\Program Files\IBM\WebSphere Studio\eclipse\jre, hibernate.dialect=net.sf.hibernate.dialect.DB2Dialect, user.language=en, java.specification.vendor=Sun Microsystems Inc., awt.toolkit=sun.awt.windows.WToolkit, hibernate.cglib.use_reflection_optimizer=false, java.vm.info=J2RE 1.3.1 IBM Windows 32 build cn131-20020710 (JIT enabled: jitc), java.version=1.3.1, java.ext.dirs=C:\Program Files\IBM\WebSphere Studio\eclipse\jre\lib\ext, sun.boot.class.path=C:\Program Files\IBM\WebSphere Studio\eclipse\jre\lib\rt.jar, java.vendor=IBM Corporation, file.separator=\, hibernate.connection.provider_class=org.springframework.orm.hibernate.LocalDataSourceConnectionProvider, java.vendor.url.bug=, java.compiler=jitc, sun.io.unicode.encoding=UnicodeLittle, user.region=US}
13:03:18,941 DEBUG SessionFactoryObjectFactory:39 - initializing class SessionFactoryObjectFactory
13:03:18,988 DEBUG SessionFactoryObjectFactory:76 - registered: 8a86a72afab042e300fab042e89d0000 (unnamed)
13:03:19,035 INFO SessionFactoryObjectFactory:82 - no JNDI name configured
13:03:19,081 DEBUG SessionFactoryImpl:190 - instantiated session factory
13:03:19,191 DEBUG SessionImpl:526 - opened session
13:03:19,238 DEBUG JDBCTransaction:37 - begin
13:03:19,269 DEBUG JDBCTransaction:41 - current autocommit status:true
13:03:19,300 DEBUG JDBCTransaction:43 - disabling autocommit
Init before persistence time: 6578
13:03:19,331 DEBUG BatcherImpl:192 - about to open: 0 open PreparedStatements, 0 open ResultSets
13:03:19,363 DEBUG BatcherImpl:226 - prepared statement get: values nextval for financial_statement_seq
13:03:19,394 DEBUG BatcherImpl:232 - preparing statement
13:03:19,441 DEBUG SequenceGenerator:80 - Sequence identifier generated: 24
13:03:19,472 DEBUG BatcherImpl:199 - done closing: 0 open PreparedStatements, 0 open ResultSets
13:03:19,503 DEBUG BatcherImpl:245 - closing statement
13:03:19,535 DEBUG SessionImpl:784 - saving [FinancialStatement#24]
13:03:19,566 DEBUG Cascades:497 - processing cascades for: FinancialStatement
13:03:19,597 DEBUG Cascades:506 - done processing cascades for: FinancialStatement
13:03:19,660 DEBUG Cascades:497 - processing cascades for: FinancialStatement
13:03:19,691 DEBUG Cascades:524 - cascading to collection: FinancialStatement.financialItemList
13:03:19,722 DEBUG Cascades:113 - cascading to saveOrUpdate()
13:03:19,753 DEBUG Cascades:396 - version unsaved-value strategy UNDEFINED
13:03:19,785 DEBUG Cascades:341 - id unsaved-value strategy NULL
13:03:19,831 DEBUG SessionImpl:1316 - saveOrUpdate() unsaved instance
13:03:19,863 DEBUG BatcherImpl:192 - about to open: 0 open PreparedStatements, 0 open ResultSets
13:03:19,910 DEBUG BatcherImpl:226 - prepared statement get: values nextval for financial_item_seq
13:03:19,941 DEBUG BatcherImpl:232 - preparing statement
13:03:19,988 DEBUG SequenceGenerator:80 - Sequence identifier generated: 21
13:03:20,019 DEBUG BatcherImpl:199 - done closing: 0 open PreparedStatements, 0 open ResultSets
13:03:20,066 DEBUG BatcherImpl:245 - closing statement
13:03:20,113 DEBUG SessionImpl:784 - saving [FinancialItem#21]
13:03:20,144 DEBUG Cascades:497 - processing cascades for: FinancialItem
13:03:20,191 DEBUG Cascades:506 - done processing cascades for: FinancialItem
13:03:20,222 DEBUG Cascades:497 - processing cascades for: FinancialItem
13:03:20,269 DEBUG Cascades:524 - cascading to collection: FinancialItem.incomeDetailList
13:03:20,300 DEBUG Cascades:524 - cascading to collection: FinancialItem.expenseDetailList
13:03:20,347 DEBUG Cascades:524 - cascading to collection: FinancialItem.assetDetailList
13:03:20,394 DEBUG Cascades:524 - cascading to collection: FinancialItem.liabilityDetailList
13:03:20,441 DEBUG Cascades:506 - done processing cascades for: FinancialItem
13:03:20,472 DEBUG Cascades:506 - done processing cascades for: FinancialStatement
Persistence time: 1172
13:03:20,503 DEBUG SessionImpl:2188 - flushing session
13:03:20,535 DEBUG Cascades:497 - processing cascades for: FinancialStatement
13:03:20,566 DEBUG Cascades:524 - cascading to collection: FinancialStatement.financialItemList
13:03:20,613 DEBUG Cascades:113 - cascading to saveOrUpdate()
13:03:20,644 DEBUG SessionImpl:1301 - saveOrUpdate() persistent instance
13:03:20,691 DEBUG Cascades:506 - done processing cascades for: FinancialStatement
13:03:20,722 DEBUG Cascades:497 - processing cascades for: FinancialItem
13:03:20,753 DEBUG Cascades:524 - cascading to collection: FinancialItem.incomeDetailList
13:03:20,785 DEBUG Cascades:524 - cascading to collection: FinancialItem.expenseDetailList
13:03:20,816 DEBUG Cascades:524 - cascading to collection: FinancialItem.assetDetailList
13:03:20,863 DEBUG Cascades:524 - cascading to collection: FinancialItem.liabilityDetailList
13:03:20,894 DEBUG Cascades:506 - done processing cascades for: FinancialItem
13:03:20,925 DEBUG SessionImpl:2316 - Flushing entities and processing referenced collections
13:03:20,972 DEBUG WrapVisitor:76 - Wrapped collection in role: FinancialStatement.financialItemList
13:03:21,003 DEBUG AbstractEntityPersister:269 - FinancialStatement.financialItemList is dirty
13:03:21,035 DEBUG SessionImpl:2410 - Updating entity: [FinancialStatement#24]
13:03:21,066 DEBUG Versioning:26 - Incrementing: 0 to 1
13:03:21,097 DEBUG SessionImpl:2763 - Collection found: [FinancialStatement.financialItemList#24], was: [<unreferenced>]
13:03:21,128 DEBUG WrapVisitor:76 - Wrapped collection in role: FinancialItem.incomeDetailList
13:03:21,160 DEBUG WrapVisitor:76 - Wrapped collection in role: FinancialItem.expenseDetailList
13:03:21,191 DEBUG WrapVisitor:76 - Wrapped collection in role: FinancialItem.assetDetailList
13:03:21,222 DEBUG WrapVisitor:76 - Wrapped collection in role: FinancialItem.liabilityDetailList
13:03:21,253 DEBUG AbstractEntityPersister:269 - FinancialItem.incomeDetailList is dirty
13:03:21,285 DEBUG AbstractEntityPersister:269 - FinancialItem.expenseDetailList is dirty
13:03:21,316 DEBUG AbstractEntityPersister:269 - FinancialItem.assetDetailList is dirty
13:03:21,347 DEBUG AbstractEntityPersister:269 - FinancialItem.liabilityDetailList is dirty
13:03:21,378 DEBUG SessionImpl:2410 - Updating entity: [FinancialItem#21]
13:03:21,410 DEBUG Versioning:26 - Incrementing: 0 to 1
13:03:21,441 DEBUG SessionImpl:2763 - Collection found: [FinancialItem.incomeDetailList#21], was: [<unreferenced>]
13:03:21,472 DEBUG SessionImpl:2763 - Collection found: [FinancialItem.expenseDetailList#21], was: [<unreferenced>]
13:03:21,503 DEBUG SessionImpl:2763 - Collection found: [FinancialItem.assetDetailList#21], was: [<unreferenced>]
13:03:21,535 DEBUG SessionImpl:2763 - Collection found: [FinancialItem.liabilityDetailList#21], was: [<unreferenced>]
13:03:21,581 DEBUG SessionImpl:2659 - Processing unreferenced collections
13:03:21,597 DEBUG SessionImpl:2673 - Scheduling collection removes/(re)creates/updates
13:03:21,644 DEBUG SessionImpl:2212 - Flushed: 2 insertions, 2 updates, 0 deletions to 2 objects
13:03:21,675 DEBUG SessionImpl:2217 - Flushed: 5 (re)creations, 0 updates, 0 removals to 5 collections
13:03:21,706 DEBUG Printer:75 - listing entities:
13:03:21,738 DEBUG Printer:82 - FinancialStatement{auditInfo=AuditInfo@51e34443, version=1, financialItemList=[FinancialItem#21], id=24}
13:03:21,769 DEBUG Printer:82 - FinancialItem{source=null, id=21, incomeDetailList=[], expenseDetailList=[], deferredIndicator=false, reason=null, overrideIndicator=false, version=1, assetDetailList=[], included=true, liabilityDetailList=[], rentalIndicator=false, description=my description, auditInfo=AuditInfo@27e78443}
13:03:21,800 DEBUG SessionImpl:2253 - executing flush
13:03:21,816 DEBUG EntityPersister:499 - Inserting entity: [FinancialStatement#24]
13:03:21,847 DEBUG EntityPersister:500 - Version: 0
13:03:21,894 DEBUG BatcherImpl:192 - about to open: 0 open PreparedStatements, 0 open ResultSets
13:03:21,925 DEBUG BatcherImpl:226 - prepared statement get: insert into financial_statement (version, create_date, update_date, create_id, update_id, id) values (?, ?, ?, ?, ?, ?)
13:03:21,956 DEBUG BatcherImpl:232 - preparing statement
13:03:22,003 DEBUG EntityPersister:389 - Dehydrating entity: [FinancialStatement#24]
13:03:22,035 DEBUG IntegerType:46 - binding '0' to parameter: 1
13:03:22,066 DEBUG TimestampType:41 - binding null to parameter: 2
13:03:22,097 DEBUG TimestampType:41 - binding null to parameter: 3
13:03:22,144 DEBUG StringType:41 - binding null to parameter: 4
13:03:22,175 DEBUG StringType:41 - binding null to parameter: 5
13:03:22,222 DEBUG LongType:46 - binding '24' to parameter: 6
13:03:22,253 DEBUG EntityPersister:499 - Inserting entity: [FinancialItem#21]
13:03:22,285 DEBUG EntityPersister:500 - Version: 0
13:03:22,316 DEBUG BatcherImpl:199 - done closing: 0 open PreparedStatements, 0 open ResultSets
13:03:22,347 DEBUG BatcherImpl:245 - closing statement
13:03:22,394 DEBUG BatcherImpl:192 - about to open: 0 open PreparedStatements, 0 open ResultSets
13:03:22,425 DEBUG BatcherImpl:226 - prepared statement get: insert into financial_item (version, create_date, update_date, create_id, update_id, source, reason, included, description, override_indicator, deferred_indicator, rental_indicator, id) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
13:03:22,456 DEBUG BatcherImpl:232 - preparing statement
13:03:22,503 DEBUG EntityPersister:389 - Dehydrating entity: [FinancialItem#21]
13:03:22,535 DEBUG IntegerType:46 - binding '0' to parameter: 1
13:03:22,566 DEBUG TimestampType:41 - binding null to parameter: 2
13:03:22,613 DEBUG TimestampType:41 - binding null to parameter: 3
13:03:22,644 DEBUG StringType:41 - binding null to parameter: 4
13:03:22,675 DEBUG StringType:41 - binding null to parameter: 5
13:03:22,706 DEBUG StringType:41 - binding null to parameter: 6
13:03:22,769 DEBUG StringType:41 - binding null to parameter: 7
13:03:22,800 DEBUG BooleanType:46 - binding 'true' to parameter: 8
13:03:22,831 DEBUG StringType:46 - binding 'my description' to parameter: 9
13:03:22,863 DEBUG BooleanType:46 - binding 'false' to parameter: 10
13:03:22,894 DEBUG BooleanType:46 - binding 'false' to parameter: 11
13:03:22,941 DEBUG BooleanType:46 - binding 'false' to parameter: 12
13:03:22,972 DEBUG LongType:46 - binding '21' to parameter: 13
13:03:23,003 DEBUG BatcherImpl:199 - done closing: 0 open PreparedStatements, 0 open ResultSets
13:03:23,050 DEBUG BatcherImpl:245 - closing statement
13:03:23,081 DEBUG EntityPersister:673 - Updating entity: [FinancialStatement#24]
13:03:23,113 DEBUG EntityPersister:674 - Existing version: 0 -> New version: 1
13:03:23,144 DEBUG BatcherImpl:192 - about to open: 0 open PreparedStatements, 0 open ResultSets
13:03:23,175 DEBUG BatcherImpl:226 - prepared statement get: update financial_statement set version=?, create_date=?, update_date=?, create_id=?, update_id=? where id=? and version=?
13:03:23,206 DEBUG BatcherImpl:232 - preparing statement
13:03:23,238 DEBUG EntityPersister:389 - Dehydrating entity: [FinancialStatement#24]
13:03:23,269 DEBUG IntegerType:46 - binding '1' to parameter: 1
13:03:23,300 DEBUG TimestampType:41 - binding null to parameter: 2
13:03:23,347 DEBUG TimestampType:41 - binding null to parameter: 3
13:03:23,378 DEBUG StringType:41 - binding null to parameter: 4
13:03:23,410 DEBUG StringType:41 - binding null to parameter: 5
13:03:23,441 DEBUG LongType:46 - binding '24' to parameter: 6
13:03:23,472 DEBUG IntegerType:46 - binding '0' to parameter: 7
13:03:23,519 DEBUG BatcherImpl:199 - done closing: 0 open PreparedStatements, 0 open ResultSets
13:03:23,550 DEBUG BatcherImpl:245 - closing statement
13:03:23,581 DEBUG EntityPersister:673 - Updating entity: [FinancialItem#21]
13:03:23,613 DEBUG EntityPersister:674 - Existing version: 0 -> New version: 1
13:03:23,644 DEBUG BatcherImpl:192 - about to open: 0 open PreparedStatements, 0 open ResultSets
13:03:23,675 DEBUG BatcherImpl:226 - prepared statement get: update financial_item set version=?, create_date=?, update_date=?, create_id=?, update_id=?, source=?, reason=?, included=?, description=?, override_indicator=?, deferred_indicator=?, rental_indicator=? where id=? and version=?
13:03:23,722 DEBUG BatcherImpl:232 - preparing statement
13:03:23,753 DEBUG EntityPersister:389 - Dehydrating entity: [FinancialItem#21]
13:03:23,785 DEBUG IntegerType:46 - binding '1' to parameter: 1
13:03:23,816 DEBUG TimestampType:41 - binding null to parameter: 2
13:03:23,847 DEBUG TimestampType:41 - binding null to parameter: 3
13:03:23,878 DEBUG StringType:41 - binding null to parameter: 4
13:03:23,925 DEBUG StringType:41 - binding null to parameter: 5
13:03:23,956 DEBUG StringType:41 - binding null to parameter: 6
13:03:23,988 DEBUG StringType:41 - binding null to parameter: 7
13:03:24,035 DEBUG BooleanType:46 - binding 'true' to parameter: 8
13:03:24,066 DEBUG StringType:46 - binding 'my description' to parameter: 9
13:03:24,097 DEBUG BooleanType:46 - binding 'false' to parameter: 10
13:03:24,128 DEBUG BooleanType:46 - binding 'false' to parameter: 11
13:03:24,160 DEBUG BooleanType:46 - binding 'false' to parameter: 12
13:03:24,191 DEBUG LongType:46 - binding '21' to parameter: 13
13:03:24,238 DEBUG IntegerType:46 - binding '0' to parameter: 14
13:03:24,269 DEBUG BatcherImpl:199 - done closing: 0 open PreparedStatements, 0 open ResultSets
13:03:24,300 DEBUG BatcherImpl:245 - closing statement
13:03:24,332 DEBUG BasicCollectionPersister:524 - Inserting collection: [FinancialStatement.financialItemList#24]
13:03:24,363 DEBUG BatcherImpl:192 - about to open: 0 open PreparedStatements, 0 open ResultSets
13:03:24,394 DEBUG BatcherImpl:226 - prepared statement get: update financial_item set financial_statement_id=?, position=? where id=?
13:03:24,441 DEBUG BatcherImpl:232 - preparing statement
13:03:24,472 DEBUG LongType:46 - binding '24' to parameter: 1
13:03:24,503 DEBUG LongType:46 - binding '21' to parameter: 3
13:03:24,535 DEBUG IntegerType:46 - binding '0' to parameter: 2
13:03:24,566 DEBUG BasicCollectionPersister:546 - done inserting collection: 1 rows inserted
13:03:24,597 DEBUG BasicCollectionPersister:524 - Inserting collection: [FinancialItem.incomeDetailList#21]
13:03:24,628 DEBUG BasicCollectionPersister:555 - collection was empty
13:03:24,660 DEBUG BasicCollectionPersister:524 - Inserting collection: [FinancialItem.expenseDetailList#21]
13:03:24,691 DEBUG BasicCollectionPersister:555 - collection was empty
13:03:24,722 DEBUG BasicCollectionPersister:524 - Inserting collection: [FinancialItem.assetDetailList#21]
13:03:24,753 DEBUG BasicCollectionPersister:555 - collection was empty
13:03:24,785 DEBUG BasicCollectionPersister:524 - Inserting collection: [FinancialItem.liabilityDetailList#21]
13:03:24,816 DEBUG BasicCollectionPersister:555 - collection was empty
13:03:24,863 DEBUG BatcherImpl:199 - done closing: 0 open PreparedStatements, 0 open ResultSets
13:03:24,894 DEBUG BatcherImpl:245 - closing statement
13:03:24,925 DEBUG SessionImpl:2703 - post flush
13:03:24,957 DEBUG JDBCTransaction:59 - commit
13:03:24,988 DEBUG SessionImpl:2188 - flushing session
13:03:25,019 DEBUG Cascades:497 - processing cascades for: FinancialStatement
13:03:25,050 DEBUG Cascades:524 - cascading to collection: FinancialStatement.financialItemList
13:03:25,097 DEBUG Cascades:113 - cascading to saveOrUpdate()
13:03:25,128 DEBUG SessionImpl:1301 - saveOrUpdate() persistent instance
13:03:25,175 DEBUG Cascades:506 - done processing cascades for: FinancialStatement
13:03:25,207 DEBUG Cascades:497 - processing cascades for: FinancialItem
13:03:25,238 DEBUG Cascades:524 - cascading to collection: FinancialItem.incomeDetailList
13:03:25,285 DEBUG Cascades:524 - cascading to collection: FinancialItem.expenseDetailList
13:03:25,316 DEBUG Cascades:524 - cascading to collection: FinancialItem.assetDetailList
13:03:25,347 DEBUG Cascades:524 - cascading to collection: FinancialItem.liabilityDetailList
13:03:25,394 DEBUG Cascades:506 - done processing cascades for: FinancialItem
13:03:25,425 DEBUG SessionImpl:2316 - Flushing entities and processing referenced collections
13:03:25,457 DEBUG SessionImpl:2763 - Collection found: [FinancialStatement.financialItemList#24], was: [FinancialStatement.financialItemList#24]
13:03:25,488 DEBUG SessionImpl:2763 - Collection found: [FinancialItem.incomeDetailList#21], was: [FinancialItem.incomeDetailList#21]
13:03:25,535 DEBUG SessionImpl:2763 - Collection found: [FinancialItem.expenseDetailList#21], was: [FinancialItem.expenseDetailList#21]
13:03:25,566 DEBUG SessionImpl:2763 - Collection found: [FinancialItem.assetDetailList#21], was: [FinancialItem.assetDetailList#21]
13:03:25,597 DEBUG SessionImpl:2763 - Collection found: [FinancialItem.liabilityDetailList#21], was: [FinancialItem.liabilityDetailList#21]
13:03:25,644 DEBUG SessionImpl:2659 - Processing unreferenced collections
13:03:25,675 DEBUG SessionImpl:2673 - Scheduling collection removes/(re)creates/updates
13:03:25,707 DEBUG SessionImpl:2212 - Flushed: 0 insertions, 0 updates, 0 deletions to 2 objects
13:03:25,738 DEBUG SessionImpl:2217 - Flushed: 0 (re)creations, 0 updates, 0 removals to 5 collections
13:03:25,769 DEBUG Printer:75 - listing entities:
13:03:25,800 DEBUG Printer:82 - FinancialStatement{auditInfo=AuditInfo@51e34443, version=1, financialItemList=[FinancialItem#21], id=24}
13:03:25,832 DEBUG Printer:82 - FinancialItem{source=null, id=21, incomeDetailList=[], expenseDetailList=[], deferredIndicator=false, reason=null, overrideIndicator=false, version=1, assetDetailList=[], included=true, liabilityDetailList=[], rentalIndicator=false, description=my description, auditInfo=AuditInfo@27e78443}
13:03:25,863 DEBUG SessionImpl:2253 - executing flush
13:03:25,894 DEBUG SessionImpl:2703 - post flush
13:03:25,941 DEBUG SessionImpl:556 - transaction completion
13:03:25,972 DEBUG JDBCTransaction:103 - re-enabling autocommit
13:03:26,003 DEBUG SessionImpl:544 - closing session
13:03:26,035 DEBUG SessionImpl:3182 - disconnecting session
13:03:26,066 DEBUG SessionImpl:556 - transaction completion
Close after persistence time 5594

Emmanuel,

I just figured out why it happens.

If optimistic locking is on (version property is defined in the mapping) Hibernate makes the parent dirty if the child is dirty.

Is it possible to switch it off?

Thanks

No there is no such capabilities.
Are you *sure* changing child will update parent version ? I think you've updated the collection and thus parent version is updated.

Emmanuel,

you are right - I didn't express what I wanted correctly. I'll try to do it again:))

Suppose we create (in memory) parent object which contains collection of child objects. None of the objects in the that mini-graph is persisted yet. Our mapping for collection of children has cascade="all" attribute. Also parent mapping has <version> element so optimistic locking is on. In this case when we persist this graph by calling session.save(parent) Hibernate does the following:

1) inserts parent
2) inserts each child
3) updates parent increments version
4) updates each child sets parent id

So in this case update 3) is definitely unnecessary. This update would make sense is parent existed before we call save.

In this example we have just one extra update which is not a big deal.
But in the case we persist big graph number of extra updates could be big.

Can you please advice?

Appreciate,
Andrey

Hum, it may due to the Hibernate choice of copying values for insert when calling save(). Gavin could confirm.

Emmanuel,

thanks a lot! Yes, it would be interesting to hear Gavin's explanation. Again, in my opinion the problem is that Hibernate does not make a difference between the cases when we insert parent and children or just insert children. The desired behavior would be the followng:

1) when we insert parent and insert in the same save() call children Hibernate SHOULD NOT increment parent's version
2) when we just insert children Hibernate SHOULD increment parent's version

Does it sound reasonable?

It is documented that for a non-bidirectional collection (ie. inverse="false"), changes to the collection cause the parent's version to be incremented. This is quite reasonable.

Gavin,

thanks for your reply. I agree - it is reasonable what you said. But in my opinion there is a difference between two cases - 1) parent existed before we change (insert) collection (it means that parent was inserted in some previous session.save(parent) call); 2) we insert parent and collection of children in the same session.save(parent). In the second case the update which increments parent's version becomes obsolete, because the parent has just been inserted.

But the probem, IMHO, is that Hibernate immediately forgets that it has just inserted parent and treats the situation like described in scenario 1) above.

Could you please advice,
Andrey

I think you are running 2.1.1, instead of the latest version!