Hier ist die relevante debug ausgabe:
DEBUG SQL:311 - select master0_.id as id1_, master0_.value as value0_1_, master0_.slave as slave0_1_, slave1_.id as id0_, slave1_.valueslave as valueslave1_0_ from master master0_ left outer join slave slave1_ on master0_.slave=slave1_.id where master0_.id=?
Hibernate: select master0_.id as id1_, master0_.value as value0_1_, master0_.slave as slave0_1_, slave1_.id as id0_, slave1_.valueslave as valueslave1_0_ from master master0_ left outer join slave slave1_ on master0_.slave=slave1_.id where master0_.id=?
01:16:17,774 DEBUG AbstractBatcher:365 - preparing statement
01:16:17,824 DEBUG IntegerType:59 - binding '5' to parameter: 1
01:16:17,934 DEBUG AbstractBatcher:293 - about to open ResultSet (open ResultSets: 0, globally: 0)
01:16:17,944 DEBUG Loader:384 - processing result set
01:16:17,944 DEBUG Loader:389 - result set row: 0
01:16:17,944 DEBUG IntegerType:86 - returning '3' as column: id0_
01:16:17,944 DEBUG Loader:791 - result row: EntityKey[omtest.Slave#3], EntityKey[omtest.Master#5]
01:16:17,954 DEBUG Loader:941 - Initializing object from ResultSet: [omtest.Slave#3]
01:16:17,974 DEBUG BasicEntityPersister:1641 - Hydrating entity: [omtest.Slave#3]
01:16:17,974 DEBUG StringType:86 - returning 'valueslave2' as column: valueslave1_0_
01:16:18,004 DEBUG Loader:941 - Initializing object from ResultSet: [omtest.Master#5]
01:16:18,004 DEBUG BasicEntityPersister:1641 - Hydrating entity: [omtest.Master#5]
01:16:18,004 DEBUG StringType:86 - returning 'booga2' as column: value0_1_
01:16:18,004 DEBUG IntegerType:86 - returning '3' as column: slave0_1_
01:16:18,004 DEBUG Loader:408 - done processing result set (1 rows)
01:16:18,004 DEBUG AbstractBatcher:300 - about to close ResultSet (open ResultSets: 1, globally: 1)
01:16:18,014 DEBUG AbstractBatcher:285 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
01:16:18,014 DEBUG AbstractBatcher:403 - closing statement
01:16:18,034 DEBUG Loader:504 - total objects hydrated: 2
01:16:18,034 DEBUG TwoPhaseLoad:96 - resolving associations for [omtest.Slave#3]
01:16:18,064 DEBUG TwoPhaseLoad:167 - done materializing entity [omtest.Slave#3]
01:16:18,064 DEBUG TwoPhaseLoad:96 - resolving associations for [omtest.Master#5]
01:16:18,064 DEBUG DefaultLoadEventListener:185 - loading entity: [omtest.Slave#3]
01:16:18,064 DEBUG DefaultLoadEventListener:331 - attempting to resolve: [omtest.Slave#3]
01:16:18,084 DEBUG DefaultLoadEventListener:340 - resolved object in session cache: [omtest.Slave#3]
01:16:18,094 DEBUG TwoPhaseLoad:167 - done materializing entity [omtest.Master#5]
01:16:18,094 DEBUG PersistenceContext:789 - initializing non-lazy collections
01:16:18,094 DEBUG Loader:1330 - done entity load
01:16:18,104 DEBUG AbstractFlushingEventListener:52 - flushing session
01:16:18,104 DEBUG AbstractFlushingEventListener:102 - processing flush-time cascades
01:16:18,124 DEBUG Cascades:806 - processing cascade ACTION_SAVE_UPDATE for: omtest.Master
01:16:18,124 DEBUG Cascades:152 - cascading to saveOrUpdate: omtest.Slave
01:16:18,134 DEBUG AbstractSaveEventListener:393 - persistent instance of: omtest.Slave
01:16:18,134 DEBUG DefaultSaveOrUpdateEventListener:103 - ignoring persistent instance
01:16:18,134 DEBUG DefaultSaveOrUpdateEventListener:140 - object already associated with session: [omtest.Slave#3]
01:16:18,134 DEBUG Cascades:831 - done processing cascade ACTION_SAVE_UPDATE for: omtest.Master
01:16:18,134 DEBUG AbstractFlushingEventListener:150 - dirty checking collections
01:16:18,134 DEBUG AbstractFlushingEventListener:167 - Flushing entities and processing referenced collections
01:16:18,165 DEBUG AbstractFlushingEventListener:203 - Processing unreferenced collections
01:16:18,165 DEBUG AbstractFlushingEventListener:217 - Scheduling collection removes/(re)creates/updates
01:16:18,165 DEBUG AbstractFlushingEventListener:79 - Flushed: 0 insertions, 0 updates, 0 deletions to 2 objects
01:16:18,165 DEBUG AbstractFlushingEventListener:85 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
01:16:18,175 DEBUG Printer:83 - listing entities:
01:16:18,175 DEBUG Printer:90 - omtest.Master{value=booga2, slave=omtest.Slave#3, id=5}
01:16:18,175 DEBUG Printer:90 - omtest.Slave{valueslave=valueslave2, id=3}
01:16:18,185 DEBUG AbstractFlushingEventListener:267 - executing flush
01:16:18,185 DEBUG AbstractFlushingEventListener:294 - post flush
01:16:18,185 DEBUG SessionImpl:254 - closing session
01:16:18,185 DEBUG AbstractBatcher:437 - closing JDBC connection (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)
01:16:18,185 DEBUG JDBCContext:221 - after transaction completion
01:16:18,195 DEBUG SessionImpl:369 - after transaction completion
01:16:23,783 DEBUG SessionImpl:237 - opened session at timestamp: 4576905559175168
01:16:23,783 DEBUG JDBCTransaction:46 - begin
01:16:23,783 DEBUG AbstractBatcher:422 - opening JDBC connection
01:16:23,783 DEBUG JDBCTransaction:50 - current autocommit status: true
01:16:23,783 DEBUG JDBCTransaction:52 - disabling autocommit
01:16:23,853 DEBUG Cascades:574 - id unsaved-value strategy NULL
01:16:23,853 DEBUG AbstractReassociateEventListener:44 - reassociating transient instance: [omtest.Slave#3]
01:16:23,883 DEBUG AbstractLockUpgradeEventListener:53 - locking [omtest.Slave#3] in mode: UPGRADE
01:16:23,883 DEBUG BasicEntityPersister:972 - Locking entity: [omtest.Slave#3]
01:16:23,883 DEBUG AbstractBatcher:277 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
01:16:23,883 DEBUG SQL:311 - select id from slave where id =? for update
Hibernate: select id from slave where id =? for update
01:16:23,883 DEBUG AbstractBatcher:365 - preparing statement
01:16:23,883 DEBUG IntegerType:59 - binding '3' to parameter: 1
01:16:23,983 DEBUG AbstractBatcher:285 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
01:16:23,983 DEBUG AbstractBatcher:403 - closing statement
01:16:23,993 DEBUG Cascades:574 - id unsaved-value strategy NULL
01:16:23,993 DEBUG AbstractReassociateEventListener:44 - reassociating transient instance: [omtest.Master#5]
01:16:23,993 DEBUG Cascades:806 - processing cascade ACTION_LOCK for: omtest.Master
01:16:23,993 DEBUG Cascades:88 - cascading to lock: omtest.Slave
01:16:23,993 DEBUG Cascades:831 - done processing cascade ACTION_LOCK for: omtest.Master
01:16:23,993 DEBUG AbstractLockUpgradeEventListener:53 - locking [omtest.Master#5] in mode: UPGRADE
01:16:23,993 DEBUG BasicEntityPersister:972 - Locking entity: [omtest.Master#5]
01:16:23,993 DEBUG AbstractBatcher:277 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
01:16:24,003 DEBUG SQL:311 - select id from master where id =? for update
Hibernate: select id from master where id =? for update
01:16:24,003 DEBUG AbstractBatcher:365 - preparing statement
01:16:24,003 DEBUG IntegerType:59 - binding '5' to parameter: 1
01:16:24,013 DEBUG AbstractBatcher:285 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
01:16:24,013 DEBUG AbstractBatcher:403 - closing statement
01:16:24,013 DEBUG DefaultSaveOrUpdateEventListener:103 - ignoring persistent instance
01:16:24,013 DEBUG DefaultSaveOrUpdateEventListener:140 - object already associated with session: [omtest.Master#5]
01:16:24,013 DEBUG AbstractFlushingEventListener:52 - flushing session
01:16:24,013 DEBUG AbstractFlushingEventListener:102 - processing flush-time cascades
01:16:24,013 DEBUG Cascades:806 - processing cascade ACTION_SAVE_UPDATE for: omtest.Master
01:16:24,013 DEBUG Cascades:152 - cascading to saveOrUpdate: omtest.Slave
01:16:24,013 DEBUG AbstractSaveEventListener:393 - persistent instance of: omtest.Slave
01:16:24,013 DEBUG DefaultSaveOrUpdateEventListener:103 - ignoring persistent instance
01:16:24,013 DEBUG DefaultSaveOrUpdateEventListener:140 - object already associated with session: [omtest.Slave#3]
01:16:24,013 DEBUG Cascades:831 - done processing cascade ACTION_SAVE_UPDATE for: omtest.Master
01:16:24,023 DEBUG AbstractFlushingEventListener:150 - dirty checking collections
01:16:24,023 DEBUG AbstractFlushingEventListener:167 - Flushing entities and processing referenced collections
01:16:24,023 DEBUG AbstractFlushingEventListener:203 - Processing unreferenced collections
01:16:24,023 DEBUG AbstractFlushingEventListener:217 - Scheduling collection removes/(re)creates/updates
01:16:24,023 DEBUG AbstractFlushingEventListener:79 - Flushed: 0 insertions, 0 updates, 0 deletions to 2 objects
01:16:24,023 DEBUG AbstractFlushingEventListener:85 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
01:16:24,023 DEBUG Printer:83 - listing entities:
01:16:24,023 DEBUG Printer:90 - omtest.Master{value=value3, slave=omtest.Slave#3, id=5}
01:16:24,033 DEBUG Printer:90 - omtest.Slave{valueslave=value3, id=3}
01:16:24,033 DEBUG AbstractFlushingEventListener:267 - executing flush
01:16:24,033 DEBUG AbstractFlushingEventListener:294 - post flush
01:16:24,033 DEBUG JDBCTransaction:83 - commit
01:16:24,033 DEBUG SessionImpl:308 - automatically flushing session
01:16:24,033 DEBUG AbstractFlushingEventListener:52 - flushing session
01:16:24,033 DEBUG AbstractFlushingEventListener:102 - processing flush-time cascades
01:16:24,033 DEBUG Cascades:806 - processing cascade ACTION_SAVE_UPDATE for: omtest.Master
01:16:24,043 DEBUG Cascades:152 - cascading to saveOrUpdate: omtest.Slave
01:16:24,043 DEBUG AbstractSaveEventListener:393 - persistent instance of: omtest.Slave
01:16:24,043 DEBUG DefaultSaveOrUpdateEventListener:103 - ignoring persistent instance
01:16:24,043 DEBUG DefaultSaveOrUpdateEventListener:140 - object already associated with session: [omtest.Slave#3]
01:16:24,043 DEBUG Cascades:831 - done processing cascade ACTION_SAVE_UPDATE for: omtest.Master
01:16:24,043 DEBUG AbstractFlushingEventListener:150 - dirty checking collections
01:16:24,043 DEBUG AbstractFlushingEventListener:167 - Flushing entities and processing referenced collections
01:16:24,043 DEBUG AbstractFlushingEventListener:203 - Processing unreferenced collections
01:16:24,053 DEBUG AbstractFlushingEventListener:217 - Scheduling collection removes/(re)creates/updates
01:16:24,053 DEBUG AbstractFlushingEventListener:79 - Flushed: 0 insertions, 0 updates, 0 deletions to 2 objects
01:16:24,053 DEBUG AbstractFlushingEventListener:85 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
01:16:24,053 DEBUG Printer:83 - listing entities:
01:16:24,053 DEBUG Printer:90 - omtest.Master{value=value3, slave=omtest.Slave#3, id=5}
01:16:24,053 DEBUG Printer:90 - omtest.Slave{valueslave=value3, id=3}
01:16:24,053 DEBUG AbstractFlushingEventListener:267 - executing flush
01:16:24,053 DEBUG AbstractFlushingEventListener:294 - post flush
01:16:24,053 DEBUG JDBCContext:216 - before transaction completion
01:16:24,053 DEBUG SessionImpl:353 - before transaction completion
01:16:24,073 DEBUG JDBCTransaction:96 - committed JDBC Connection
01:16:24,073 DEBUG JDBCContext:221 - after transaction completion
01:16:24,073 DEBUG SessionImpl:369 - after transaction completion
01:16:24,073 DEBUG JDBCTransaction:157 - re-enabling autocommit
01:16:24,073 DEBUG SessionImpl:254 - closing session
01:16:24,073 DEBUG AbstractBatcher:437 - closing JDBC connection (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)
01:16:24,073 DEBUG JDBCContext:221 - after transaction completion
01:16:24,073 DEBUG SessionImpl:369 - after transaction completion
|