Two class Person and Address have bidirectional one-to-one association relationship. For aoid N+1 Select problem, Set FetchMode join in Criteria of quering Person. Why there are actually two query to database, Please help!

Hibernate version:
Hibernate 3.2.6

Mapping documents:
Person.hbm.xml
<?xml version="1.0"?>
<!DOCTYPE hibernate-mapping PUBLIC
"-//Hibernate/Hibernate Mapping DTD 3.0//EN"
"http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd">
<hibernate-mapping>
<class name="Person" table="person">
<id name="id" column="personId">
<generator class="native" />
</id>
<property name="name"
type="string"
unique="true"
not-null="true"/>
<many-to-one name="address"
class="Address"
column="addressId"
unique="true"
not-null="true"/>
</class>
</hibernate-mapping>

Address.hbm.xml
<?xml version="1.0"?>
<!DOCTYPE hibernate-mapping PUBLIC
"-//Hibernate/Hibernate Mapping DTD 3.0//EN"
"http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd">
<hibernate-mapping package="cn.ait.wfves.model">
<class name="Address" table="address">
<id name="id" column="addressId">
<generator class="native" />
</id>
<one-to-one name="person"
class="Person"
property-ref="address"/>
</class>
</hibernate-mapping>

Code between sessionFactory.openSession() and session.close():
Criteria crit = getSession().createCriteria(Person.class)
.setFetchMode("address", FetchMode.JOIN)
.add(Restrictions.eq("name", name));
return crit.list();

Full stack trace of any exception that occurs:
no any exception occurs.

Name and version of the database you are using:
Derby 10.3.2.1

The generated SQL (show_sql=true):
see stack trace

Debug level Hibernate log excerpt:
...
09:37:32,062 DEBUG JDBCTransaction:54 - begin
09:37:32,062 DEBUG ConnectionManager:421 - opening JDBC connection
09:37:32,062 DEBUG DriverManagerConnectionProvider:93 - total checked-out connections: 0
09:37:32,062 DEBUG DriverManagerConnectionProvider:99 - using pooled JDBC connection, pool size: 0
09:37:32,062 DEBUG JDBCTransaction:59 - current autocommit status: false
09:37:32,062 DEBUG JDBCContext:214 - after transaction begin
09:37:32,062 DEBUG HibernateTest:31 - Executing inTransaction() supplement
09:37:32,062 DEBUG HibernateTest:33 - Running test
09:37:32,078 DEBUG ThreadLocalSessionContext:300 - allowing proxied method [createCriteria] to proceed to real session
09:37:32,140 DEBUG AbstractBatcher:366 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
09:37:32,140 DEBUG SQL:401 -
select
this_.personId as personId0_1_,
this_.name as name0_1_,
this_.addressId as addressId0_1_,
address2_.addressId as addressId1_0_
from
person this_
inner join
address address2_
on this_.addressId=address2_.addressId
where
this_.name=?
Hibernate:
select
this_.personId as personId0_1_,
this_.name as name0_1_,
this_.addressId as addressId0_1_,
address2_.addressId as addressId1_0_
from
person this_
inner join
address address2_
on this_.addressId=address2_.addressId
where
this_.name=?
09:37:32,140 DEBUG AbstractBatcher:484 - preparing statement
09:37:33,656 DEBUG StringType:133 - binding 'anonymous' to parameter: 1
09:37:33,687 DEBUG AbstractBatcher:382 - about to open ResultSet (open ResultSets: 0, globally: 0)
09:37:33,687 DEBUG Loader:694 - processing result set
09:37:33,703 DEBUG Loader:699 - result set row: 0
09:37:33,703 DEBUG LongType:172 - returning '524288' as column: addressId1_0_
09:37:33,703 DEBUG LongType:172 - returning '557056' as column: personId0_1_
09:37:33,703 DEBUG Loader:1173 - result row: EntityKey[Address#524288], EntityKey
[Person#557056]
09:37:33,703 DEBUG Loader:1355 - Initializing object from ResultSet: [Address#524288]
09:37:33,734 DEBUG AbstractEntityPersister:2036 - Hydrating entity: [Address#524288]
09:37:33,734 DEBUG Loader:1355 - Initializing object from ResultSet: [Person#557056]
09:37:33,734 DEBUG AbstractEntityPersister:2036 - Hydrating entity: [Person#557056]
09:37:33,734 DEBUG StringType:172 - returning 'anonymous' as column: name0_1_
09:37:33,750 DEBUG LongType:172 - returning '524288' as column: addressId0_1_
09:37:33,781 DEBUG Loader:721 - done processing result set (1 rows)
09:37:33,781 DEBUG AbstractBatcher:389 - about to close ResultSet (open ResultSets: 1, globally: 1)
09:37:33,781 DEBUG AbstractBatcher:374 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
09:37:33,781 DEBUG AbstractBatcher:533 - closing statement
09:37:33,781 DEBUG Loader:851 - total objects hydrated: 2
09:37:33,781 DEBUG TwoPhaseLoad:111 - resolving associations for [Address#524288]
09:37:33,796 DEBUG Loader:1852 - loading entity: [Person#524288]
09:37:33,796 DEBUG AbstractBatcher:366 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
09:37:33,796 DEBUG SQL:401 -
select
person0_.personId as personId0_0_,
person0_.name as name0_0_,
person0_.addressId as addressId0_0_
from
person person0_
where
person0_.addressId=?
Hibernate:
select
person0_.personId as personId0_0_,
person0_.name as name0_0_,
person0_.addressId as addressId0_0_
from
person person0_
where
person0_.addressId=?
09:37:33,796 DEBUG AbstractBatcher:484 - preparing statement
09:37:33,796 DEBUG LongType:133 - binding '524288' to parameter: 1
09:37:33,796 DEBUG AbstractBatcher:382 - about to open ResultSet (open ResultSets: 0, globally: 0)
09:37:33,812 DEBUG Loader:694 - processing result set
09:37:33,812 DEBUG Loader:699 - result set row: 0
09:37:33,812 DEBUG LongType:172 - returning '557056' as column: personId0_0_
09:37:33,812 DEBUG Loader:1173 - result row: EntityKey[Person#557056]
09:37:33,812 DEBUG Loader:721 - done processing result set (1 rows)
09:37:33,812 DEBUG AbstractBatcher:389 - about to close ResultSet (open ResultSets: 1, globally: 1)
09:37:33,812 DEBUG AbstractBatcher:374 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
09:37:33,812 DEBUG AbstractBatcher:533 - closing statement
09:37:33,812 DEBUG Loader:851 - total objects hydrated: 0
09:37:33,812 DEBUG Loader:1883 - done entity load
09:37:33,812 DEBUG TwoPhaseLoad:209 - done materializing entity [Address#524288]
09:37:33,812 DEBUG TwoPhaseLoad:111 - resolving associations for [Person#557056]
09:37:33,812 DEBUG DefaultLoadEventListener:171 - loading entity: [Address#524288]
09:37:33,812 DEBUG DefaultLoadEventListener:244 - entity found in session cache
09:37:33,812 DEBUG TwoPhaseLoad:209 - done materializing entity [Person#557056]
09:37:33,828 DEBUG StatefulPersistenceContext:837 - initializing non-lazy collections
09:37:33,828 DEBUG HibernateTest:40 - Rolling back transaction
09:37:33,828 DEBUG ThreadLocalSessionContext:300 - allowing proxied method [getTransaction] to proceed to real session
09:37:33,828 DEBUG JDBCTransaction:152 - rollback
09:37:33,828 DEBUG JDBCTransaction:163 - rolled back JDBC Connection
...