Hi, we started watching the generated SQL and noticed that sometimes
the same columns are mentioned twice in the queries, like ref_a_id and id_b in this example:
Code:
select
clbcollect0_.ref_a_id as ref2_1_,
clbcollect0_.id_b as id1_1_,
clbcollect0_.id_b as id1_1_0_,
clbcollect0_.ref_a_id as ref2_1_0_,
clbcollect0_.attrib_b as attrib3_1_0_
from ...
This seems to happen for one-to-many relations. Can this be avoided so as to use less bandwidth by not transferring the same data twice?
Hibernate version: 3.2.6.ga
Mapping documents:Code:
// File ClzA.hbm.xml
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE hibernate-mapping PUBLIC
"-//Hibernate/Hibernate Mapping DTD 3.0//EN"
"http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd">
<hibernate-mapping default-lazy="false"
>
<class
mutable="true"
name="com.example.hib3dupcol.ClzA"
table="tab_a"
>
<id
name="idA"
column="id" >
<generator class="increment" />
</id>
<property
name="name"
type="java.lang.String"
update="false"
insert="true"
>
<column
name="name"
not-null="true"
/>
</property>
<bag
name="clBCollection"
lazy="true"
inverse="true"
cascade="save-update"
>
<key
column="ref_a_id"
/>
<one-to-many
class="com.example.hib3dupcol.ClzB"
/>
</bag>
</class>
</hibernate-mapping>
Code:
// File ClzB.hbm.xml
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE hibernate-mapping PUBLIC
"-//Hibernate/Hibernate Mapping DTD 3.0//EN"
"http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd">
<hibernate-mapping default-lazy="false"
>
<class
mutable="true"
name="com.example.hib3dupcol.ClzB"
table="tab_b"
>
<id
name="idB"
column="id_b" >
<generator class="increment" />
</id>
<many-to-one
name="clA"
class="com.example.hib3dupcol.ClzA"
cascade="save-update"
outer-join="auto"
update="true"
insert="true"
>
<column
name="ref_a_id"
not-null="true"
/>
</many-to-one>
<property
name="attribB"
type="java.lang.String"
update="false"
insert="false"
>
<column
name="attrib_b"
not-null="true"
/>
</property>
</class>
</hibernate-mapping>
Code between sessionFactory.openSession() and session.close():Code:
ClzA findA1 = (ClzA) newSession.get(ClzA.class, idA1);
System.out.println("collection size is " + findA1.getClBCollection().size());
Full stack trace of any exception that occurs: No exception occursName and version of the database you are using: MySQL 4.1
The generated SQL (show_sql=true):Code:
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.SQL --
select
clza0_.id as id0_0_,
clza0_.name as name0_0_
from
testdb.tab_a clza0_
where
clza0_.id=?
Hibernate:
select
clza0_.id as id0_0_,
clza0_.name as name0_0_
from
testdb.tab_a clza0_
where
clza0_.id=?
Code:
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.SQL --
select
clbcollect0_.ref_a_id as ref2_1_,
clbcollect0_.id_b as id1_1_,
clbcollect0_.id_b as id1_1_0_,
clbcollect0_.ref_a_id as ref2_1_0_,
clbcollect0_.attrib_b as attrib3_1_0_
from
testdb.tab_b clbcollect0_
where
clbcollect0_.ref_a_id=?
Hibernate:
select
clbcollect0_.ref_a_id as ref2_1_,
clbcollect0_.id_b as id1_1_,
clbcollect0_.id_b as id1_1_0_,
clbcollect0_.ref_a_id as ref2_1_0_,
clbcollect0_.attrib_b as attrib3_1_0_
from
testdb.tab_b clbcollect0_
where
clbcollect0_.ref_a_id=?
Debug level Hibernate log excerpt:Code:
2008-04-22 10:48:45,524 [main] INFO com.example.hib3dupcol.Main -- finding ClzA with id 1
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.impl.SessionImpl -- opened session at timestamp: 12088541255
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.event.def.DefaultLoadEventListener -- loading entity: [com.example.hib3dupcol.ClzA#1]
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.event.def.DefaultLoadEventListener -- attempting to resolve: [com.example.hib3dupcol.ClzA#1]
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.event.def.DefaultLoadEventListener -- object not resolved in any cache: [com.example.hib3dupcol.ClzA#1]
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.persister.entity.AbstractEntityPersister -- Fetching entity: [com.example.hib3dupcol.ClzA#1]
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.loader.Loader -- loading entity: [com.example.hib3dupcol.ClzA#1]
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.jdbc.AbstractBatcher -- about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.jdbc.ConnectionManager -- opening JDBC connection
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.connection.DriverManagerConnectionProvider -- total checked-out connections: 0
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.connection.DriverManagerConnectionProvider -- using pooled JDBC connection, pool size: 0
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.SQL --
select
clza0_.id as id0_0_,
clza0_.name as name0_0_
from
testdb.tab_a clza0_
where
clza0_.id=?
Hibernate:
select
clza0_.id as id0_0_,
clza0_.name as name0_0_
from
testdb.tab_a clza0_
where
clza0_.id=?
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.jdbc.AbstractBatcher -- preparing statement
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.type.LongType -- binding '1' to parameter: 1
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.jdbc.AbstractBatcher -- about to open ResultSet (open ResultSets: 0, globally: 0)
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.loader.Loader -- processing result set
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.loader.Loader -- result set row: 0
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.loader.Loader -- result row: EntityKey[com.example.hib3dupcol.ClzA#1]
2008-04-22 10:48:45,524 [main] INFO com.example.hib3dupcol.ClzA -- setting IdA=1
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.loader.Loader -- Initializing object from ResultSet: [com.example.hib3dupcol.ClzA#1]
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.persister.entity.AbstractEntityPersister -- Hydrating entity: [com.example.hib3dupcol.ClzA#1]
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.type.StringType -- returning 'x1' as column: name0_0_
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.loader.Loader -- done processing result set (1 rows)
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.jdbc.AbstractBatcher -- about to close ResultSet (open ResultSets: 1, globally: 1)
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.jdbc.AbstractBatcher -- about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.jdbc.AbstractBatcher -- closing statement
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.loader.Loader -- total objects hydrated: 1
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.engine.TwoPhaseLoad -- resolving associations for [com.example.hib3dupcol.ClzA#1]
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.engine.loading.LoadContexts -- creating collection wrapper:[com.example.hib3dupcol.ClzA.clBCollection#1]
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.engine.TwoPhaseLoad -- done materializing entity [com.example.hib3dupcol.ClzA#1]
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.engine.StatefulPersistenceContext -- initializing non-lazy collections
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.loader.Loader -- done entity load
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.jdbc.JDBCContext -- after autocommit
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.jdbc.ConnectionManager -- aggressively releasing JDBC connection
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.jdbc.ConnectionManager -- releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.connection.DriverManagerConnectionProvider -- returning connection to pool, pool size: 1
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.event.def.DefaultInitializeCollectionEventListener -- initializing collection [com.example.hib3dupcol.ClzA.clBCollection#1]
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.event.def.DefaultInitializeCollectionEventListener -- checking second-level cache
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.event.def.DefaultInitializeCollectionEventListener -- collection not cached
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.loader.Loader -- loading collection: [com.example.hib3dupcol.ClzA.clBCollection#1]
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.jdbc.AbstractBatcher -- about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.jdbc.ConnectionManager -- opening JDBC connection
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.connection.DriverManagerConnectionProvider -- total checked-out connections: 0
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.connection.DriverManagerConnectionProvider -- using pooled JDBC connection, pool size: 0
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.SQL --
select
clbcollect0_.ref_a_id as ref2_1_,
clbcollect0_.id_b as id1_1_,
clbcollect0_.id_b as id1_1_0_,
clbcollect0_.ref_a_id as ref2_1_0_,
clbcollect0_.attrib_b as attrib3_1_0_
from
testdb.tab_b clbcollect0_
where
clbcollect0_.ref_a_id=?
Hibernate:
select
clbcollect0_.ref_a_id as ref2_1_,
clbcollect0_.id_b as id1_1_,
clbcollect0_.id_b as id1_1_0_,
clbcollect0_.ref_a_id as ref2_1_0_,
clbcollect0_.attrib_b as attrib3_1_0_
from
testdb.tab_b clbcollect0_
where
clbcollect0_.ref_a_id=?
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.jdbc.AbstractBatcher -- preparing statement
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.type.LongType -- binding '1' to parameter: 1
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.jdbc.AbstractBatcher -- about to open ResultSet (open ResultSets: 0, globally: 0)
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.loader.Loader -- result set contains (possibly empty) collection: [com.example.hib3dupcol.ClzA.clBCollection#1]
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.engine.loading.LoadContexts -- constructing collection load context for result set [com.mysql.jdbc.ResultSet@ce2187]
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.engine.loading.CollectionLoadContext -- starting attempt to find loading collection [[com.example.hib3dupcol.ClzA.clBCollection#1]]
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.engine.loading.CollectionLoadContext -- collection not yet initialized; initializing
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.loader.Loader -- processing result set
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.loader.Loader -- result set row: 0
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.type.LongType -- returning '1' as column: id1_1_0_
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.loader.Loader -- result row: EntityKey[com.example.hib3dupcol.ClzB#1]
2008-04-22 10:48:45,524 [main] INFO com.example.hib3dupcol.ClzB -- Setting idB=1
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.loader.Loader -- Initializing object from ResultSet: [com.example.hib3dupcol.ClzB#1]
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.persister.entity.AbstractEntityPersister -- Hydrating entity: [com.example.hib3dupcol.ClzB#1]
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.type.LongType -- returning '1' as column: ref2_1_0_
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.type.StringType -- returning '' as column: attrib3_1_0_
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.type.LongType -- returning '1' as column: ref2_1_
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.loader.Loader -- found row of collection: [com.example.hib3dupcol.ClzA.clBCollection#1]
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.engine.loading.CollectionLoadContext -- starting attempt to find loading collection [[com.example.hib3dupcol.ClzA.clBCollection#1]]
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.engine.loading.LoadContexts -- attempting to locate loading collection entry [CollectionKey[com.example.hib3dupcol.ClzA.clBCollection#1]] in any result-set context
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.engine.loading.LoadContexts -- collection [CollectionKey[com.example.hib3dupcol.ClzA.clBCollection#1]] located in load context
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.engine.loading.CollectionLoadContext -- found loading collection bound to current result set processing; reading row
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.type.LongType -- returning '1' as column: id1_1_
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.event.def.DefaultLoadEventListener -- loading entity: [com.example.hib3dupcol.ClzB#1]
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.event.def.DefaultLoadEventListener -- attempting to resolve: [com.example.hib3dupcol.ClzB#1]
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.event.def.DefaultLoadEventListener -- resolved object in session cache: [com.example.hib3dupcol.ClzB#1]
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.loader.Loader -- done processing result set (1 rows)
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.jdbc.AbstractBatcher -- about to close ResultSet (open ResultSets: 1, globally: 1)
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.jdbc.AbstractBatcher -- about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.jdbc.AbstractBatcher -- closing statement
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.loader.Loader -- total objects hydrated: 1
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.engine.TwoPhaseLoad -- resolving associations for [com.example.hib3dupcol.ClzB#1]
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.event.def.DefaultLoadEventListener -- loading entity: [com.example.hib3dupcol.ClzA#1]
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.event.def.DefaultLoadEventListener -- attempting to resolve: [com.example.hib3dupcol.ClzA#1]
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.event.def.DefaultLoadEventListener -- resolved object in session cache: [com.example.hib3dupcol.ClzA#1]
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.engine.TwoPhaseLoad -- done materializing entity [com.example.hib3dupcol.ClzB#1]
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.engine.loading.LoadContexts -- attempting to locate loading collection entry [CollectionKey[com.example.hib3dupcol.ClzA.clBCollection#1]] in any result-set context
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.engine.loading.LoadContexts -- collection [CollectionKey[com.example.hib3dupcol.ClzA.clBCollection#1]] located in load context
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.engine.loading.CollectionLoadContext -- removing collection load entry [org.hibernate.engine.loading.LoadingCollectionEntry<rs=com.mysql.jdbc.ResultSet@ce2187, coll=[com.example.hib3dupcol.ClzA.clBCollection#1]>@15253d5]
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.engine.loading.CollectionLoadContext -- 1 collections were found in result set for role: com.example.hib3dupcol.ClzA.clBCollection
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.engine.loading.CollectionLoadContext -- ending loading collection [org.hibernate.engine.loading.LoadingCollectionEntry<rs=com.mysql.jdbc.ResultSet@ce2187, coll=[com.example.hib3dupcol.ClzA.clBCollection#1]>@15253d5]
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.engine.loading.CollectionLoadContext -- collection fully initialized: [com.example.hib3dupcol.ClzA.clBCollection#1]
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.engine.loading.CollectionLoadContext -- 1 collections initialized for role: com.example.hib3dupcol.ClzA.clBCollection
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.engine.StatefulPersistenceContext -- initializing non-lazy collections
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.loader.Loader -- done loading collection
2008-04-22 10:48:45,524 [main] DEBUG org.hibernate.event.def.DefaultInitializeCollectionEventListener -- collection initialized
collection size is 1