I am new to Hibernate, I am a bit more advanced with JDBC/SQL, especially Mysql.
I have a one-to-many relationship and in a Hibernate session I wish to:
- update a record on the "one" (parent) side (Note)
- insert a record on the "many" (child) side (NoteEvent) which relates to the parent updated by the operation above
I am awaren that my particular application (generating events) should not be done with a one-to-many, interceptors should be used, etc. I did it just for testing reasons and I was a bit surprised by the results.
It is my impression from debugging the generated SQL and from looking at Hibernate sources that Hibernate always does write-behind inserts before updates. That looks like a reasonable decission.
The trouble is, in the case above, doing the insert before the update will always lead to deadlock if two sessions work concurrently on the same "parent" record. That can be tested with two Mysql consoles executing the respective commands inside read-committed transactions. The inserts succeed immediately in both consoles, but the update in the first console blocks, and the udpate in the second console declares deadlock. Meaning that "inserting a child and updating its parent" seems to be very deadlock-prone with Hibernate.
The solution I found is to do the update, then do session.flush(), then do the insert. That still deadlocks sometimes with 4-5 concurrent accesses on the same "parent" record, but at least it doesn't always deadlock with two...
Taking off versioning or making the relationship bidirectional does not seem to help.
Also, I do not think that there is any trouble with the NotesContainer structure and one-to-many relationships with Note. There are no changes operations related to the NotesContainer table in the example below.
Thanks, Cristian
--------------
Hibernate version:
3.0.5
Mapping documents:
Code:
<class name="NotesContainer" table="NOTES_CONTAINER">
<cache usage="read-write" />
<id column="ID" name="id" access="field"> <generator class="native"/></id>
<map name="notes" outer-join="true" cascade="all" inverse="true" access="field" order-by="lastUpdated">
<cache usage="read-write" />
<key><column name="ID_CONT" not-null="false"/></key>
<index column="guid" type="string"/>
<one-to-many class="Note"/>
</map>
<map name="deletedNotes" outer-join="true" cascade="all" inverse="true" access="field">
<cache usage="read-write" />
<key><column name="ID_DELE" not-null="false"/></key>
<index column="guid" type="string"/>
<one-to-many class="Note"/>
</map>
</class>
<class name="Note" table="NOTE"
dynamic-insert="true"
dynamic-update="true"
>
<cache usage="read-write"/>
<id name="id" access="field">
<generator class="native"/>
</id>
<!-- <version name="version" access="field"/>-->
<timestamp name="db_timestamp" access="field"/>
<property name="guid" column="guid" unique="true" not-null="true"/>
<property name="created" />
<property name="lastUpdated"/>
<property name="backgroundColor"/>
<property name="ink" type="binary"/>
<many-to-one name="cont" access="field" column="ID_CONT"/>
<many-to-one name="deletedCont" access="field" column="ID_DELE"/>
<!-- <set name="events" access="field" inverse="true" cascade="save-update" lazy="true">-->
<!-- <cache usage="read-write" />-->
<!-- <key column="note"/>-->
<!-- <one-to-many class="NoteEvent"/>-->
<!-- </set>-->
</class>
<class name="NoteEvent" table="NOTE_EVENT" mutable="false">
<id column="id" name="id" access="field">
<generator class="native" />
</id>
<timestamp name="db_timestamp" access="field"/>
<property name="timestamp" access="field" />
<property name="type" access="field" />
<property name="user" access="field" />
<many-to-one name="note" not-null="true" access="field"/>
</class>
Code:
public void pushNote(Note note, String userid){
Session session= sf.openSession();
try{
saveEvent(session, session.beginTransaction(), ((NotesContainer)session.get(NotesContainer.class, one)).pushNote(note, userid));
}
catch(org.hibernate.exception.ConstraintViolationException ce){
logger.error("constraint violation :"+ce.getCause().getMessage());
}
catch(org.hibernate.exception.LockAcquisitionException le){
logger.error("deadlock :"+le.getCause().getMessage());
}
catch(StaleObjectStateException se){logger.debug("stale object"); return; }
catch(Throwable e){ logger.error(e); e.printStackTrace();
//throw new javax.xml.soap.SOAPException();
// TODO: log the error rather than print
// TODO: web service exception?
}
finally{
session.close();
}
}
private void saveEvent(Session session, Transaction tx, NoteEvent event) throws Throwable{
if(event!=null){
// this will do the update first
// session.flush();
// this will do the insert first
session.persist(getContainer(session));
session.save(event);
}
try{
tx.commit();
}catch(Throwable e){ if(tx!=null) tx.rollback(); throw e; }
}
NotesContainer:
NoteEvent pushNote(Note note, String userid) {
if(note.getGuid()==null)
return null;
note.setGuid(note.getGuid().trim());
Note n= (Note)notes.get(note.getGuid());
if(n!=null){
// TODO: update last modified, etc
NotesServer.logger.debug("updating "+ n.getGuid());
n.copyFrom(note);
return new NoteEvent(NoteEvent.EVENT_UPDATED, n, n.getLastUpdated(), userid);
}else{
// TODO: update created, etc
NotesServer.logger.debug("saving "+note.getGuid());
note.cont= this;
notes.put(note.getGuid(), note);
return new NoteEvent(NoteEvent.EVENT_CREATED, note, note.getCreated(), userid);
}
}
Name and version of the database you are using:Mysql 4.0, 4.1
The generated SQL (show_sql=true):table creation (for insert/update see below)
Code:
create table NOTE (id bigint not null auto_increment, db_timestamp datetime not null, guid varchar(255) not null unique, created datetime, lastUpdated datetime, backgroundColor integer, ink tinyblob, ID_CONT bigint, ID_DELE bigint, primary key (id)) type=InnoDB
16:47:30,334 DEBUG SchemaUpdate:142 - create table NOTE (id bigint not null auto_increment, db_timestamp datetime not null, guid varchar(255) not null unique, created datetime, lastUpdated datetime, backgroundColor integer, ink tinyblob, ID_CONT bigint, ID_DELE bigint, primary key (id)) type=InnoDB
create table NOTES_CONTAINER (ID bigint not null auto_increment, primary key (ID)) type=InnoDB
16:47:30,504 DEBUG SchemaUpdate:142 - create table NOTES_CONTAINER (ID bigint not null auto_increment, primary key (ID)) type=InnoDB
create table NOTE_EVENT (id bigint not null auto_increment, db_timestamp datetime not null, timestamp datetime, type integer, user varchar(255), note bigint not null, primary key (id)) type=InnoDB
16:47:30,644 DEBUG SchemaUpdate:142 - create table NOTE_EVENT (id bigint not null auto_increment, db_timestamp datetime not null, timestamp datetime, type integer, user varchar(255), note bigint not null, primary key (id)) type=InnoDB
alter table NOTE add index FK24A7F28F3B2FB3 (ID_CONT), add constraint FK24A7F28F3B2FB3 foreign key (ID_CONT) references NOTES_CONTAINER (ID)
16:47:30,784 DEBUG SchemaUpdate:142 - alter table NOTE add index FK24A7F28F3B2FB3 (ID_CONT), add constraint FK24A7F28F3B2FB3 foreign key (ID_CONT) references NOTES_CONTAINER (ID)
alter table NOTE add index FK24A7F28F3B7E3B (ID_DELE), add constraint FK24A7F28F3B7E3B foreign key (ID_DELE) references NOTES_CONTAINER (ID)
16:47:31,105 DEBUG SchemaUpdate:142 - alter table NOTE add index FK24A7F28F3B7E3B (ID_DELE), add constraint FK24A7F28F3B7E3B foreign key (ID_DELE) references NOTES_CONTAINER (ID)
alter table NOTE_EVENT add index FK2D8047EDDA0C6541 (note), add constraint FK2D8047EDDA0C6541 foreign key (note) references NOTE (id)
16:47:31,365 DEBUG SchemaUpdate:142 - alter table NOTE_EVENT add index FK2D8047EDDA0C6541 (note), add constraint FK2D8047EDDA0C6541 foreign key (note) references NOTE (id)
16:47:31,575 INFO SchemaUpdate:153 - schema update complete
Debug level Hibernate log excerpt:
trying to update the same NOTE from 5 concurrent threads:
[code]
16:49:05,230 DEBUG SessionImpl:250 - opened session at timestamp: 4606861906862080
16:49:05,230 DEBUG JDBCTransaction:46 - begin
16:49:05,230 DEBUG ConnectionManager:296 - opening JDBC connection
16:49:05,230 DEBUG JDBCTransaction:50 - current autocommit status: false
16:49:05,230 DEBUG DefaultLoadEventListener:143 - loading entity: [se.kth.nada.saxaren.NotesContainer#1]
16:49:05,230 DEBUG DefaultLoadEventListener:290 - attempting to resolve: [se.kth.nada.saxaren.NotesContainer#1]
16:49:05,230 DEBUG ReadWriteCache:75 - Cache lookup: se.kth.nada.saxaren.NotesContainer#1
16:49:05,230 DEBUG EhCache:104 - key: se.kth.nada.saxaren.NotesContainer#1
16:49:05,240 DEBUG SessionImpl:250 - opened session at timestamp: 4606861906903040
16:49:05,260 DEBUG SessionImpl:250 - opened session at timestamp: 4606861906984960
16:49:05,280 DEBUG SessionImpl:250 - opened session at timestamp: 4606861907066880
16:49:05,280 DEBUG SessionImpl:250 - opened session at timestamp: 4606861907066881
16:49:05,320 DEBUG ReadWriteCache:85 - Cache hit: se.kth.nada.saxaren.NotesContainer#1
16:49:05,410 DEBUG JDBCTransaction:46 - begin
16:49:05,440 DEBUG JDBCTransaction:46 - begin
16:49:05,440 DEBUG JDBCTransaction:46 - begin
16:49:05,440 DEBUG DefaultLoadEventListener:483 - resolved object in second-level cache: [se.kth.nada.saxaren.NotesContainer#1]
16:49:05,440 DEBUG ConnectionManager:296 - opening JDBC connection
16:49:05,440 DEBUG ConnectionManager:296 - opening JDBC connection
16:49:05,440 DEBUG ConnectionManager:296 - opening JDBC connection
16:49:05,440 DEBUG JDBCTransaction:46 - begin
16:49:05,440 DEBUG CollectionLoadContext:141 - creating collection wrapper:[se.kth.nada.saxaren.NotesContainer.notes#1]
16:49:05,440 DEBUG JDBCTransaction:50 - current autocommit status: false
16:49:05,450 DEBUG JDBCTransaction:50 - current autocommit status: false
16:49:05,460 DEBUG ConnectionManager:296 - opening JDBC connection
16:49:05,460 DEBUG JDBCTransaction:50 - current autocommit status: false
16:49:05,460 DEBUG CollectionLoadContext:141 - creating collection wrapper:[se.kth.nada.saxaren.NotesContainer.deletedNotes#1]
16:49:05,460 DEBUG DefaultLoadEventListener:143 - loading entity: [se.kth.nada.saxaren.NotesContainer#1]
16:49:05,490 DEBUG JDBCTransaction:50 - current autocommit status: false
16:49:05,490 DEBUG DefaultLoadEventListener:143 - loading entity: [se.kth.nada.saxaren.NotesContainer#1]
16:49:05,490 DEBUG DefaultLoadEventListener:143 - loading entity: [se.kth.nada.saxaren.NotesContainer#1]
16:49:05,490 DEBUG DefaultLoadEventListener:505 - Cached Version: null
16:49:05,490 DEBUG DefaultLoadEventListener:290 - attempting to resolve: [se.kth.nada.saxaren.NotesContainer#1]
16:49:05,500 DEBUG DefaultLoadEventListener:290 - attempting to resolve: [se.kth.nada.saxaren.NotesContainer#1]
16:49:05,500 DEBUG PersistenceContext:789 - initializing non-lazy collections
16:49:05,500 DEBUG DefaultLoadEventListener:290 - attempting to resolve: [se.kth.nada.saxaren.NotesContainer#1]
16:49:05,500 DEBUG DefaultLoadEventListener:143 - loading entity: [se.kth.nada.saxaren.NotesContainer#1]
16:49:05,500 DEBUG ReadWriteCache:75 - Cache lookup: se.kth.nada.saxaren.NotesContainer#1
16:49:05,500 DEBUG DefaultLoadEventListener:290 - attempting to resolve: [se.kth.nada.saxaren.NotesContainer#1]
16:49:05,500 DEBUG EhCache:104 - key: se.kth.nada.saxaren.NotesContainer#1
16:49:05,500 DEBUG DefaultLoadEventListener:317 - resolved object in second-level cache: [se.kth.nada.saxaren.NotesContainer#1]
16:49:05,500 DEBUG DefaultInitializeCollectionEventListener:42 - initializing collection [se.kth.nada.saxaren.NotesContainer.notes#1]
16:49:05,500 DEBUG DefaultInitializeCollectionEventListener:47 - checking second-level cache
16:49:05,500 DEBUG ReadWriteCache:75 - Cache lookup: se.kth.nada.saxaren.NotesContainer.notes#1
16:49:05,500 DEBUG ReadWriteCache:85 - Cache hit: se.kth.nada.saxaren.NotesContainer#1
16:49:05,500 DEBUG EhCache:104 - key: se.kth.nada.saxaren.NotesContainer.notes#1
16:49:05,510 DEBUG DefaultLoadEventListener:483 - resolved object in second-level cache: [se.kth.nada.saxaren.NotesContainer#1]
16:49:05,510 DEBUG ReadWriteCache:94 - Cached item was locked: se.kth.nada.saxaren.NotesContainer.notes#1
16:49:05,510 DEBUG CollectionLoadContext:141 - creating collection wrapper:[se.kth.nada.saxaren.NotesContainer.notes#1]
16:49:05,510 DEBUG DefaultInitializeCollectionEventListener:59 - collection not cached
16:49:05,510 DEBUG ReadWriteCache:75 - Cache lookup: se.kth.nada.saxaren.NotesContainer#1
16:49:05,510 DEBUG CollectionLoadContext:141 - creating collection wrapper:[se.kth.nada.saxaren.NotesContainer.deletedNotes#1]
16:49:05,510 DEBUG Loader:1426 - loading collection: [se.kth.nada.saxaren.NotesContainer.notes#1]
16:49:05,510 DEBUG EhCache:104 - key: se.kth.nada.saxaren.NotesContainer#1
16:49:05,510 DEBUG DefaultLoadEventListener:505 - Cached Version: null
16:49:05,520 DEBUG ReadWriteCache:85 - Cache hit: se.kth.nada.saxaren.NotesContainer#1
16:49:05,520 DEBUG AbstractBatcher:290 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
16:49:05,520 DEBUG PersistenceContext:789 - initializing non-lazy collections
16:49:05,520 DEBUG DefaultLoadEventListener:483 - resolved object in second-level cache: [se.kth.nada.saxaren.NotesContainer#1]
16:49:05,520 DEBUG SQL:324 - select notes0_.ID_CONT as ID8_1_, notes0_.id as id1_, notes0_.guid as guid1_, notes0_.id as id0_, notes0_.db_timestamp as db2_0_0_, notes0_.guid as guid0_0_, notes0_.created as created0_0_, notes0_.lastUpdated as lastUpda5_0_0_, notes0_.backgroundColor as backgrou6_0_0_, notes0_.ink as ink0_0_, notes0_.ID_CONT as ID8_0_0_, notes0_.ID_DELE as ID9_0_0_ from NOTE notes0_ where notes0_.ID_CONT=? order by notes0_.lastUpdated
16:49:05,520 DEBUG ReadWriteCache:75 - Cache lookup: se.kth.nada.saxaren.NotesContainer#1
16:49:05,520 DEBUG DefaultLoadEventListener:317 - resolved object in second-level cache: [se.kth.nada.saxaren.NotesContainer#1]
16:49:05,520 DEBUG CollectionLoadContext:141 - creating collection wrapper:[se.kth.nada.saxaren.NotesContainer.notes#1]
16:49:05,520 DEBUG EhCache:104 - key: se.kth.nada.saxaren.NotesContainer#1
16:49:05,520 DEBUG DefaultInitializeCollectionEventListener:42 - initializing collection [se.kth.nada.saxaren.NotesContainer.notes#1]
16:49:05,520 DEBUG CollectionLoadContext:141 - creating collection wrapper:[se.kth.nada.saxaren.NotesContainer.deletedNotes#1]
16:49:05,520 DEBUG ReadWriteCache:85 - Cache hit: se.kth.nada.saxaren.NotesContainer#1
16:49:05,520 DEBUG AbstractBatcher:378 - preparing statement
16:49:05,520 DEBUG DefaultInitializeCollectionEventListener:47 - checking second-level cache
16:49:05,541 DEBUG DefaultLoadEventListener:505 - Cached Version: null
16:49:05,541 DEBUG ReadWriteCache:75 - Cache lookup: se.kth.nada.saxaren.NotesContainer.notes#1
16:49:05,541 DEBUG PersistenceContext:789 - initializing non-lazy collections
16:49:05,571 DEBUG LongType:59 - binding '1' to parameter: 1
16:49:05,571 DEBUG EhCache:104 - key: se.kth.nada.saxaren.NotesContainer.notes#1
16:49:05,571 DEBUG DefaultLoadEventListener:317 - resolved object in second-level cache: [se.kth.nada.saxaren.NotesContainer#1]
16:49:05,581 DEBUG ReadWriteCache:75 - Cache lookup: se.kth.nada.saxaren.NotesContainer#1
16:49:05,581 DEBUG DefaultLoadEventListener:483 - resolved object in second-level cache: [se.kth.nada.saxaren.NotesContainer#1]
16:49:05,581 DEBUG AbstractBatcher:306 - about to open ResultSet (open ResultSets: 0, globally: 0)
16:49:05,581 DEBUG ReadWriteCache:94 - Cached item was locked: se.kth.nada.saxaren.NotesContainer.notes#1
16:49:05,581 DEBUG DefaultInitializeCollectionEventListener:42 - initializing collection [se.kth.nada.saxaren.NotesContainer.notes#1]
16:49:05,581 DEBUG EhCache:104 - key: se.kth.nada.saxaren.NotesContainer#1
16:49:05,581 DEBUG CollectionLoadContext:141 - creating collection wrapper:[se.kth.nada.saxaren.NotesContainer.notes#1]
16:49:05,581 DEBUG Loader:718 - result set contains (possibly empty) collection: [se.kth.nada.saxaren.NotesContainer.notes#1]
16:49:05,581 DEBUG DefaultInitializeCollectionEventListener:47 - checking second-level cache
16:49:05,581 DEBUG DefaultInitializeCollectionEventListener:59 - collection not cached
16:49:05,581 DEBUG CollectionLoadContext:141 - creating collection wrapper:[se.kth.nada.saxaren.NotesContainer.deletedNotes#1]
16:49:05,591 DEBUG CollectionLoadContext:85 - uninitialized collection: initializing
16:49:05,591 DEBUG ReadWriteCache:85 - Cache hit: se.kth.nada.saxaren.NotesContainer#1
16:49:05,591 DEBUG ReadWriteCache:75 - Cache lookup: se.kth.nada.saxaren.NotesContainer.notes#1
16:49:05,591 DEBUG Loader:1426 - loading collection: [se.kth.nada.saxaren.NotesContainer.notes#1]
16:49:05,591 DEBUG DefaultLoadEventListener:505 - Cached Version: null
16:49:05,591 DEBUG DefaultLoadEventListener:483 - resolved object in second-level cache: [se.kth.nada.saxaren.NotesContainer#1]
16:49:05,601 DEBUG EhCache:104 - key: se.kth.nada.saxaren.NotesContainer.notes#1
16:49:05,601 DEBUG Loader:405 - processing result set
16:49:05,601 DEBUG AbstractBatcher:290 - about to open PreparedStatement (open PreparedStatements: 0, globally: 1)
16:49:05,601 DEBUG PersistenceContext:789 - initializing non-lazy collections
16:49:05,601 DEBUG CollectionLoadContext:141 - creating collection wrapper:[se.kth.nada.saxaren.NotesContainer.notes#1]
16:49:05,651 DEBUG Loader:410 - result set row: 0
16:49:05,651 DEBUG ReadWriteCache:94 - Cached item was locked: se.kth.nada.saxaren.NotesContainer.notes#1
16:49:05,651 DEBUG SQL:324 - select notes0_.ID_CONT as ID8_1_, notes0_.id as id1_, notes0_.guid as guid1_, notes0_.id as id0_, notes0_.db_timestamp as db2_0_0_, notes0_.guid as guid0_0_, notes0_.created as created0_0_, notes0_.lastUpdated as lastUpda5_0_0_, notes0_.backgroundColor as backgrou6_0_0_, notes0_.ink as ink0_0_, notes0_.ID_CONT as ID8_0_0_, notes0_.ID_DELE as ID9_0_0_ from NOTE notes0_ where notes0_.ID_CONT=? order by notes0_.lastUpdated
16:49:05,651 DEBUG CollectionLoadContext:141 - creating collection wrapper:[se.kth.nada.saxaren.NotesContainer.deletedNotes#1]
16:49:05,661 DEBUG LongType:86 - returning '1' as column: id0_
16:49:05,661 DEBUG DefaultInitializeCollectionEventListener:59 - collection not cached
16:49:05,661 DEBUG DefaultLoadEventListener:317 - resolved object in second-level cache: [se.kth.nada.saxaren.NotesContainer#1]
16:49:05,661 DEBUG DefaultLoadEventListener:505 - Cached Version: null
16:49:05,661 DEBUG Loader:828 - result row: EntityKey[se.kth.nada.saxaren.Note#1]
16:49:05,661 DEBUG Loader:1426 - loading collection: [se.kth.nada.saxaren.NotesContainer.notes#1]
16:49:05,661 DEBUG DefaultInitializeCollectionEventListener:42 - initializing collection [se.kth.nada.saxaren.NotesContainer.notes#1]
16:49:05,661 DEBUG PersistenceContext:789 - initializing non-lazy collections
16:49:05,661 DEBUG AbstractBatcher:378 - preparing statement
16:49:05,661 DEBUG Loader:978 - Initializing object from ResultSet: [se.kth.nada.saxaren.Note#1]
16:49:05,661 DEBUG AbstractBatcher:290 - about to open PreparedStatement (open PreparedStatements: 0, globally: 2)
16:49:05,661 DEBUG DefaultInitializeCollectionEventListener:47 - checking second-level cache
16:49:05,671 DEBUG LongType:59 - binding '1' to parameter: 1
16:49:05,671 DEBUG BasicEntityPersister:1651 - Hydrating entity: [se.kth.nada.saxaren.Note#1]
16:49:05,671 DEBUG DefaultLoadEventListener:317 - resolved object in second-level cache: [se.kth.nada.saxaren.NotesContainer#1]
16:49:05,671 DEBUG SQL:324 - select notes0_.ID_CONT as ID8_1_, notes0_.id as id1_, notes0_.guid as guid1_, notes0_.id as id0_, notes0_.db_timestamp as db2_0_0_, notes0_.guid as guid0_0_, notes0_.created as created0_0_, notes0_.lastUpdated as lastUpda5_0_0_, notes0_.backgroundColor as backgrou6_0_0_, notes0_.ink as ink0_0_, notes0_.ID_CONT as ID8_0_0_, notes0_.ID_DELE as ID9_0_0_ from NOTE notes0_ where notes0_.ID_CONT=? order by notes0_.lastUpdated
16:49:05,671 DEBUG ReadWriteCache:75 - Cache lookup: se.kth.nada.saxaren.NotesContainer.notes#1
16:49:05,681 DEBUG AbstractBatcher:306 - about to open ResultSet (open ResultSets: 0, globally: 1)
16:49:05,681 DEBUG DefaultInitializeCollectionEventListener:42 - initializing collection [se.kth.nada.saxaren.NotesContainer.notes#1]
16:49:05,681 DEBUG TimestampType:86 - returning '2005-08-22 16:48:48' as column: db2_0_0_
16:49:05,681 DEBUG AbstractBatcher:378 - preparing statement
16:49:05,681 DEBUG EhCache:104 - key: se.kth.nada.saxaren.NotesContainer.notes#1
16:49:05,681 DEBUG Loader:718 - result set contains (possibly empty) collection: [se.kth.nada.saxaren.NotesContainer.notes#1]
16:49:05,681 DEBUG DefaultInitializeCollectionEventListener:47 - checking second-level cache
16:49:05,681 DEBUG StringType:86 - returning 'babaaa121' as column: guid0_0_
16:49:05,691 DEBUG LongType:59 - binding '1' to parameter: 1
16:49:05,691 DEBUG CollectionLoadContext:85 - uninitialized collection: initializing
16:49:05,691 DEBUG TimestampType:86 - returning '2005-08-15 10:44:03' as column: created0_0_
16:49:05,691 DEBUG AbstractBatcher:306 - about to open ResultSet (open ResultSets: 0, globally: 2)
16:49:05,691 DEBUG Loader:405 - processing result set
16:49:05,691 DEBUG ReadWriteCache:94 - Cached item was locked: se.kth.nada.saxaren.NotesContainer.notes#1
16:49:05,691 DEBUG TimestampType:86 - returning '2005-08-30 16:14:48' as column: lastUpda5_0_0_
16:49:05,691 DEBUG Loader:718 - result set contains (possibly empty) collection: [se.kth.nada.saxaren.NotesContainer.notes#1]
16:49:05,691 DEBUG Loader:410 - result set row: 0
16:49:05,711 DEBUG DefaultInitializeCollectionEventListener:59 - collection not cached
16:49:05,711 DEBUG IntegerType:86 - returning '223' as column: backgrou6_0_0_
16:49:05,711 DEBUG ReadWriteCache:75 - Cache lookup: se.kth.nada.saxaren.NotesContainer.notes#1
16:49:05,721 DEBUG CollectionLoadContext:85 - uninitialized collection: initializing
16:49:05,721 DEBUG LongType:86 - returning '1' as column: id0_
16:49:05,721 DEBUG Loader:1426 - loading collection: [se.kth.nada.saxaren.NotesContainer.notes#1]
16:49:05,721 DEBUG EhCache:104 - key: se.kth.nada.saxaren.NotesContainer.notes#1
16:49:05,721 DEBUG Loader:405 - processing result set
16:49:05,721 DEBUG Loader:828 - result row: EntityKey[se.kth.nada.saxaren.Note#1]
16:49:05,721 DEBUG BinaryType:86 - returning '504f916021319a6180808080808080808080808080808080be8083807e7f898086808080808080808080808082808080028080808080808080' as column: ink0_0_
16:49:05,721 DEBUG AbstractBatcher:290 - about to open PreparedStatement (open PreparedStatements: 0, globally: 3)
16:49:05,721 DEBUG ReadWriteCache:94 - Cached item was locked: se.kth.nada.saxaren.NotesContainer.notes#1
16:49:05,721 DEBUG Loader:410 - result set row: 0
16:49:05,721 DEBUG Loader:978 - Initializing object from ResultSet: [se.kth.nada.saxaren.Note#1]
16:49:05,721 DEBUG LongType:86 - returning '1' as column: ID8_0_0_
16:49:05,721 DEBUG SQL:324 - select notes0_.ID_CONT as ID8_1_, notes0_.id as id1_, notes0_.guid as guid1_, notes0_.id as id0_, notes0_.db_timestamp as db2_0_0_, notes0_.guid as guid0_0_, notes0_.created as created0_0_, notes0_.lastUpdated as lastUpda5_0_0_, notes0_.backgroundColor as backgrou6_0_0_, notes0_.ink as ink0_0_, notes0_.ID_CONT as ID8_0_0_, notes0_.ID_DELE as ID9_0_0_ from NOTE notes0_ where notes0_.ID_CONT=? order by notes0_.lastUpdated
16:49:05,731 DEBUG DefaultInitializeCollectionEventListener:59 - collection not cached
16:49:05,731 DEBUG BasicEntityPersister:1651 - Hydrating entity: [se.kth.nada.saxaren.Note#1]
16:49:05,731 DEBUG LongType:80 - returning null as column: ID9_0_0_
16:49:05,731 DEBUG LongType:86 - returning '1' as column: id0_
16:49:05,731 DEBUG Loader:1426 - loading collection: [se.kth.nada.saxaren.NotesContainer.notes#1]
16:49:05,741 DEBUG AbstractBatcher:378 - preparing statement
16:49:05,741 DEBUG TwoPhaseLoad:67 - Version: 2005-08-22 16:48:48.0
16:49:05,741 DEBUG Loader:828 - result row: EntityKey[se.kth.nada.saxaren.Note#1]
16:49:05,741 DEBUG AbstractBatcher:290 - about to open PreparedStatement (open PreparedStatements: 0, globally: 4)
16:49:05,751 DEBUG LongType:59 - binding '1' to parameter: 1
16:49:05,751 DEBUG LongType:86 - returning '1' as column: ID8_1_
16:49:05,751 DEBUG TimestampType:86 - returning '2005-08-22 16:48:48' as column: db2_0_0_
16:49:05,751 DEBUG Loader:978 - Initializing object from ResultSet: [se.kth.nada.saxaren.Note#1]
16:49:05,751 DEBUG SQL:324 - select notes0_.ID_CONT as ID8_1_, notes0_.id as id1_, notes0_.guid as guid1_, notes0_.id as id0_, notes0_.db_timestamp as db2_0_0_, notes0_.guid as guid0_0_, notes0_.created as created0_0_, notes0_.lastUpdated as lastUpda5_0_0_, notes0_.backgroundColor as backgrou6_0_0_, notes0_.ink as ink0_0_, notes0_.ID_CONT as ID8_0_0_, notes0_.ID_DELE as ID9_0_0_ from NOTE notes0_ where notes0_.ID_CONT=? order by notes0_.lastUpdated
16:49:05,751 DEBUG AbstractBatcher:306 - about to open ResultSet (open ResultSets: 0, globally: 3)
16:49:05,751 DEBUG Loader:654 - found row of collection: [se.kth.nada.saxaren.NotesContainer.notes#1]
16:49:05,751 DEBUG StringType:86 - returning 'babaaa121' as column: guid0_0_
16:49:05,751 DEBUG BasicEntityPersister:1651 - Hydrating entity: [se.kth.nada.saxaren.Note#1]
16:49:05,801 DEBUG AbstractBatcher:378 - preparing statement
16:49:05,801 DEBUG CollectionLoadContext:112 - reading row
16:49:05,801 DEBUG TimestampType:86 - returning '2005-08-15 10:44:03' as column: created0_0_
16:49:05,801 DEBUG TimestampType:86 - returning '2005-08-22 16:48:48' as column: db2_0_0_
16:49:05,801 DEBUG LongType:86 - returning '1' as column: id1_
16:49:05,811 DEBUG LongType:59 - binding '1' to parameter: 1
16:49:05,811 DEBUG Loader:718 - result set contains (possibly empty) collection: [se.kth.nada.saxaren.NotesContainer.notes#1]
16:49:05,811 DEBUG TimestampType:86 - returning '2005-08-30 16:14:48' as column: lastUpda5_0_0_
16:49:05,811 DEBUG DefaultLoadEventListener:143 - loading entity: [se.kth.nada.saxaren.Note#1]
16:49:05,821 DEBUG AbstractBatcher:306 - about to open ResultSet (open ResultSets: 0, globally: 4)
16:49:05,821 DEBUG CollectionLoadContext:85 - uninitialized collection: initializing
16:49:05,821 DEBUG IntegerType:86 - returning '223' as column: backgrou6_0_0_
16:49:05,821 DEBUG StringType:86 - returning 'babaaa121' as column: guid0_0_
16:49:05,821 DEBUG Loader:718 - result set contains (possibly empty) collection: [se.kth.nada.saxaren.NotesContainer.notes#1]
16:49:05,821 DEBUG Loader:405 - processing result set
16:49:05,821 DEBUG BinaryType:86 - returning '504f916021319a6180808080808080808080808080808080be8083807e7f898086808080808080808080808082808080028080808080808080' as column: ink0_0_
16:49:05,821 DEBUG TimestampType:86 - returning '2005-08-15 10:44:03' as column: created0_0_
16:49:05,821 DEBUG DefaultLoadEventListener:290 - attempting to resolve: [se.kth.nada.saxaren.Note#1]
16:49:05,821 DEBUG CollectionLoadContext:85 - uninitialized collection: initializing
16:49:05,821 DEBUG Loader:410 - result set row: 0
16:49:05,821 DEBUG LongType:86 - returning '1' as column: ID8_0_0_
16:49:05,821 DEBUG TimestampType:86 - returning '2005-08-30 16:14:48' as column: lastUpda5_0_0_
16:49:05,831 DEBUG DefaultLoadEventListener:299 - resolved object in session cache: [se.kth.nada.saxaren.Note#1]
16:49:05,831 DEBUG Loader:405 - processing result set
16:49:05,831 DEBUG LongType:80 - returning null as column: ID9_0_0_
16:49:05,831 DEBUG IntegerType:86 - returning '223' as column: backgrou6_0_0_
16:49:05,841 DEBUG Loader:410 - result set row: 0
16:49:05,841 DEBUG LongType:86 - returning '1' as column: id0_
16:49:05,841 DEBUG StringType:86 - returning 'babaaa121' as column: guid1_
16:49:05,841 DEBUG BinaryType:86 - returning '504f916021319a6180808080808080808080808080808080be8083807e7f898086808080808080808080808082808080028080808080808080' as column: ink0_0_
16:49:05,841 DEBUG TwoPhaseLoad:67 - Version: 2005-08-22 16:48:48.0
16:49:05,851 DEBUG Loader:828 - result row: EntityKey[se.kth.nada.saxaren.Note#1]
16:49:05,851 DEBUG LongType:86 - returning '1' as column: id0_
16:49:05,851 DEBUG Loader:429 - done processing result set (1 rows)
16:49:05,851 DEBUG LongType:86 - returning '1' as column: ID8_0_0_
16:49:05,851 DEBUG LongType:86 - returning '1' as column: ID8_1_
16:49:05,851 DEBUG Loader:978 - Initializing object from ResultSet: [se.kth.nada.saxaren.Note#1]
16:49:05,861 DEBUG AbstractBatcher:313 - about to close ResultSet (open ResultSets: 1, globally: 5)
16:49:05,861 DEBUG LongType:80 - returning null as column: ID9_0_0_
16:49:05,861 DEBUG Loader:654 - found row of collection: [se.kth.nada.saxaren.NotesContainer.notes#1]
16:49:05,861 DEBUG Loader:828 - result row: EntityKey[se.kth.nada.saxaren.Note#1]
16:49:05,861 DEBUG AbstractBatcher:298 - about to close PreparedStatement (open PreparedStatements: 1, globally: 5)
16:49:05,861 DEBUG TwoPhaseLoad:67 - Version: 2005-08-22 16:48:48.0
16:49:05,861 DEBUG CollectionLoadContext:112 - reading row
16:49:05,861 DEBUG Loader:978 - Initializing object from ResultSet: [se.kth.nada.saxaren.Note#1]
16:49:05,861 DEBUG AbstractBatcher:416 - closing statement
16:49:05,861 DEBUG BasicEntityPersister:1651 - Hydrating entity: [se.kth.nada.saxaren.Note#1]
16:49:05,861 DEBUG LongType:86 - returning '1' as column: ID8_1_
16:49:05,871 DEBUG LongType:86 - returning '1' as column: id1_
16:49:05,871 DEBUG BasicEntityPersister:1651 - Hydrating entity: [se.kth.nada.saxaren.Note#1]
16:49:05,871 DEBUG Loader:528 - total objects hydrated: 1
16:49:05,871 DEBUG TimestampType:86 - returning '2005-08-22 16:48:48' as column: db2_0_0_
16:49:05,871 DEBUG Loader:654 - found row of collection: [se.kth.nada.saxaren.NotesContainer.notes#1]
16:49:05,921 DEBUG DefaultLoadEventListener:143 - loading entity: [se.kth.nada.saxaren.Note#1]
16:49:05,921 DEBUG TimestampType:86 - returning '2005-08-22 16:48:48' as column: db2_0_0_
16:49:05,921 DEBUG TwoPhaseLoad:96 - resolving associations for [se.kth.nada.saxaren.Note#1]
16:49:05,921 DEBUG StringType:86 - returning 'babaaa121' as column: guid0_0_
16:49:05,921 DEBUG CollectionLoadContext:112 - reading row
16:49:05,921 DEBUG DefaultLoadEventListener:290 - attempting to resolve: [se.kth.nada.saxaren.Note#1]
16:49:05,921 DEBUG StringType:86 - returning 'babaaa121' as column: guid0_0_
16:49:05,921 DEBUG DefaultLoadEventListener:143 - loading entity: [se.kth.nada.saxaren.NotesContainer#1]
16:49:05,931 DEBUG LongType:86 - returning '1' as column: id1_
16:49:05,931 DEBUG DefaultLoadEventListener:299 - resolved object in session cache: [se.kth.nada.saxaren.Note#1]
16:49:05,931 DEBUG TimestampType:86 - returning '2005-08-15 10:44:03' as column: created0_0_
16:49:05,931 DEBUG DefaultLoadEventListener:208 - entity found in session cache
16:49:05,931 DEBUG DefaultLoadEventListener:143 - loading entity: [se.kth.nada.saxaren.Note#1]
16:49:05,931 DEBUG TimestampType:86 - returning '2005-08-15 10:44:03' as column: created0_0_
16:49:05,931 DEBUG StringType:86 - returning 'babaaa121' as column: guid1_
16:49:05,941 DEBUG TimestampType:86 - returning '2005-08-30 16:14:48' as column: lastUpda5_0_0_
16:49:05,941 DEBUG TwoPhaseLoad:119 - adding entity to second-level cache: [se.kth.nada.saxaren.Note#1]
16:49:05,941 DEBUG DefaultLoadEventListener:290 - attempting to resolve: [se.kth.nada.saxaren.Note#1]
16:49:05,941 DEBUG TimestampType:86 - returning '2005-08-30 16:14:48' as column: lastUpda5_0_0_
16:49:05,941 DEBUG Loader:429 - done processing result set (1 rows)
16:49:05,941 DEBUG IntegerType:86 - returning '223' as column: backgrou6_0_0_
16:49:05,951 DEBUG DefaultLoadEventListener:299 - resolved object in session cache: [se.kth.nada.saxaren.Note#1]
16:49:05,951 DEBUG IntegerType:86 - returning '223' as column: backgrou6_0_0_
16:49:05,951 DEBUG ReadWriteCache:148 - Caching: se.kth.nada.saxaren.Note#1
16:49:05,951 DEBUG BinaryType:86 - returning '504f916021319a6180808080808080808080808080808080be8083807e7f898086808080808080808080808082808080028080808080808080' as column: ink0_0_
16:49:05,951 DEBUG AbstractBatcher:313 - about to close ResultSet (open ResultSets: 1, globally: 4)
16:49:05,951 DEBUG StringType:86 - returning 'babaaa121' as column: guid1_
16:49:05,951 DEBUG BinaryType:86 - returning '504f916021319a6180808080808080808080808080808080be8083807e7f898086808080808080808080808082808080028080808080808080' as column: ink0_0_
16:49:05,951 DEBUG EhCache:104 - key: se.kth.nada.saxaren.Note#1
16:49:05,951 DEBUG LongType:86 - returning '1' as column: ID8_0_0_
16:49:05,951 DEBUG AbstractBatcher:298 - about to close PreparedStatement (open PreparedStatements: 1, globally: 4)
16:49:05,951 DEBUG Loader:429 - done processing result set (1 rows)
16:49:05,961 DEBUG LongType:86 - returning '1' as column: ID8_0_0_
16:49:05,971 DEBUG EhCache:113 - Element for se.kth.nada.saxaren.Note#1 is null
16:49:05,971 DEBUG AbstractBatcher:416 - closing statement
16:49:05,971 DEBUG AbstractBatcher:313 - about to close ResultSet (open ResultSets: 1, globally: 3)
16:49:05,971 DEBUG LongType:80 - returning null as column: ID9_0_0_
16:49:05,971 DEBUG ReadWriteCache:160 - Cached: se.kth.nada.saxaren.Note#1
16:49:05,981 DEBUG AbstractBatcher:298 - about to close PreparedStatement (open PreparedStatements: 1, globally: 3)
16:49:05,981 DEBUG Loader:528 - total objects hydrated: 1
16:49:05,981 DEBUG LongType:80 - returning null as column: ID9_0_0_
16:49:05,981 DEBUG TwoPhaseLoad:67 - Version: 2005-08-22 16:48:48.0
16:49:05,981 DEBUG TwoPhaseLoad:167 - done materializing entity [se.kth.nada.saxaren.Note#1]
16:49:05,981 DEBUG TwoPhaseLoad:96 - resolving associations for [se.kth.nada.saxaren.Note#1]
16:49:05,981 DEBUG TwoPhaseLoad:67 - Version: 2005-08-22 16:48:48.0
16:49:05,981 DEBUG LongType:86 - returning '1' as column: ID8_1_
16:49:05,981 DEBUG CollectionLoadContext:262 - 1 collections were found in result set for role: se.kth.nada.saxaren.NotesContainer.notes
16:49:05,981 DEBUG AbstractBatcher:416 - closing statement
16:49:05,981 DEBUG DefaultLoadEventListener:143 - loading entity: [se.kth.nada.saxaren.NotesContainer#1]
16:49:05,981 DEBUG LongType:86 - returning '1' as column: ID8_1_
16:49:05,981 DEBUG Loader:654 - found row of collection: [se.kth.nada.saxaren.NotesContainer.notes#1]
16:49:05,991 DEBUG Loader:528 - total objects hydrated: 1
16:49:05,991 DEBUG DefaultLoadEventListener:208 - entity found in session cache
16:49:06,001 DEBUG CollectionLoadContext:282 - Caching collection: [se.kth.nada.saxaren.NotesContainer.notes#1]
16:49:06,001 DEBUG Loader:654 - found row of collection: [se.kth.nada.saxaren.NotesContainer.notes#1]
16:49:06,001 DEBUG TwoPhaseLoad:96 - resolving associations for [se.kth.nada.saxaren.Note#1]
16:49:06,001 DEBUG TwoPhaseLoad:119 - adding entity to second-level cache: [se.kth.nada.saxaren.Note#1]
16:49:06,001 DEBUG ReadWriteCache:148 - Caching: se.kth.nada.saxaren.NotesContainer.notes#1
16:49:06,001 DEBUG CollectionLoadContext:112 - reading row
16:49:06,001 DEBUG CollectionLoadContext:112 - reading row
16:49:06,051 DEBUG DefaultLoadEventListener:143 - loading entity: [se.kth.nada.saxaren.NotesContainer#1]
16:49:06,051 DEBUG EhCache:104 - key: se.kth.nada.saxaren.NotesContainer.notes#1
16:49:06,051 DEBUG LongType:86 - returning '1' as column: id1_
16:49:06,051 DEBUG LongType:86 - returning '1' as column: id1_
16:49:06,051 DEBUG DefaultLoadEventListener:208 - entity found in session cache
16:49:06,051 DEBUG ReadWriteCache:160 - Cached: se.kth.nada.saxaren.NotesContainer.notes#1
16:49:06,051 DEBUG ReadWriteCache:148 - Caching: se.kth.nada.saxaren.Note#1
16:49:06,051 DEBUG DefaultLoadEventListener:143 - loading entity: [se.kth.nada.saxaren.Note#1]
16:49:06,051 DEBUG DefaultLoadEventListener:143 - loading entity: [se.kth.nada.saxaren.Note#1]
16:49:06,061 DEBUG TwoPhaseLoad:119 - adding entity to second-level cache: [se.kth.nada.saxaren.Note#1]
16:49:06,061 DEBUG EhCache:104 - key: se.kth.nada.saxaren.Note#1
16:49:06,061 DEBUG CollectionLoadContext:206 - collection fully initialized: [se.kth.nada.saxaren.NotesContainer.notes#1]
16:49:06,061 DEBUG DefaultLoadEventListener:290 - attempting to resolve: [se.kth.nada.saxaren.Note#1]
16:49:06,081 DEBUG DefaultLoadEventListener:290 - attempting to resolve: [se.kth.nada.saxaren.Note#1]
16:49:06,091 DEBUG ReadWriteCache:169 - Item was already cached: se.kth.nada.saxaren.Note#1
16:49:06,091 DEBUG CollectionLoadContext:272 - 1 collections initialized for role: se.kth.nada.saxaren.NotesContainer.notes
16:49:06,091 DEBUG DefaultLoadEventListener:299 - resolved object in session cache: [se.kth.nada.saxaren.Note#1]
16:49:06,091 DEBUG DefaultLoadEventListener:299 - resolved object in session cache: [se.kth.nada.saxaren.Note#1]
16:49:06,091 DEBUG ReadWriteCache:148 - Caching: se.kth.nada.saxaren.Note#1
16:49:06,091 DEBUG TwoPhaseLoad:167 - done materializing entity [se.kth.nada.saxaren.Note#1]
16:49:06,091 DEBUG PersistenceContext:789 - initializing non-lazy collections
16:49:06,091 DEBUG StringType:86 - returning 'babaaa121' as column: guid1_
16:49:06,091 DEBUG StringType:86 - returning 'babaaa121' as column: guid1_
16:49:06,091 DEBUG EhCache:104 - key: se.kth.nada.saxaren.Note#1
16:49:06,091 DEBUG CollectionLoadContext:262 - 1 collections were found in result set for role: se.kth.nada.saxaren.NotesContainer.notes
16:49:06,091 DEBUG Loader:1450 - done loading collection
16:49:06,101 DEBUG Loader:429 - done processing result set (1 rows)
16:49:06,101 DEBUG Loader:429 - done processing result set (1 rows)
16:49:06,101 DEBUG ReadWriteCache:169 - Item was already cached: se.kth.nada.saxaren.Note#1
16:49:06,101 DEBUG CollectionLoadContext:282 - Caching collection: [se.kth.nada.saxaren.NotesContainer.notes#1]
16:49:06,101 DEBUG DefaultInitializeCollectionEventListener:61 - collection initialized
16:49:06,101 DEBUG AbstractBatcher:313 - about to close ResultSet (open ResultSets: 1, globally: 2)
16:49:06,101 DEBUG AbstractBatcher:313 - about to close ResultSet (open ResultSets: 1, globally: 2)
16:49:06,111 DEBUG TwoPhaseLoad:167 - done materializing entity [se.kth.nada.saxaren.Note#1]
16:49:06,111 DEBUG ReadWriteCache:148 - Caching: se.kth.nada.saxaren.NotesContainer.notes#1
16:49:06,111 DEBUG NotesServer:31 - updating babaaa121
16:49:06,111 DEBUG AbstractBatcher:298 - about to close PreparedStatement (open PreparedStatements: 1, globally: 2)
16:49:06,111 DEBUG CollectionLoadContext:262 - 1 collections were found in result set for role: se.kth.nada.saxaren.NotesContainer.notes
16:49:06,111 DEBUG EhCache:104 - key: se.kth.nada.saxaren.NotesContainer.notes#1
16:49:06,111 DEBUG AbstractBatcher:298 - about to close PreparedStatement (open PreparedStatements: 1, globally: 2)
16:49:06,111 DEBUG DefaultLoadEventListener:143 - loading entity: [se.kth.nada.saxaren.NotesContainer#1]
16:49:06,121 DEBUG AbstractBatcher:416 - closing statement
16:49:06,121 DEBUG CollectionLoadContext:282 - Caching collection: [se.kth.nada.saxaren.NotesContainer.notes#1]
16:49:06,121 DEBUG ReadWriteCache:169 - Item was already cached: se.kth.nada.saxaren.NotesContainer.notes#1
16:49:06,121 DEBUG AbstractBatcher:416 - closing statement
16:49:06,121 DEBUG DefaultLoadEventListener:290 - attempting to resolve: [se.kth.nada.saxaren.NotesContainer#1]
16:49:06,121 DEBUG CollectionLoadContext:206 - collection fully initialized: [se.kth.nada.saxaren.NotesContainer.notes#1]
16:49:06,121 DEBUG Loader:528 - total objects hydrated: 1
16:49:06,121 DEBUG DefaultLoadEventListener:299 - resolved object in session cache: [se.kth.nada.saxaren.NotesContainer#1]
16:49:06,121 DEBUG Loader:528 - total objects hydrated: 1
16:49:06,121 DEBUG ReadWriteCache:148 - Caching: se.kth.nada.saxaren.NotesContainer.notes#1
16:49:06,121 DEBUG CollectionLoadContext:272 - 1 collections initialized for role: se.kth.nada.saxaren.NotesContainer.notes
16:49:06,121 DEBUG TwoPhaseLoad:96 - resolving associations for [se.kth.nada.saxaren.Note#1]
16:49:06,121 DEBUG TwoPhaseLoad:96 - resolving associations for [se.kth.nada.saxaren.Note#1]
16:49:06,171 DEBUG AbstractSaveEventListener:394 - persistent instance of: se.kth.nada.saxaren.NotesContainer
16:49:06,171 DEBUG EhCache:104 - key: se.kth.nada.saxaren.NotesContainer.notes#1
16:49:06,171 DEBUG DefaultLoadEventListener:143 - loading entity: [se.kth.nada.saxaren.NotesContainer#1]
16:49:06,171 DEBUG DefaultLoadEventListener:143 - loading entity: [se.kth.nada.saxaren.NotesContainer#1]
16:49:06,171 DEBUG DefaultPersistEventListener:93 - ignoring persistent instance
16:49:06,171 DEBUG ReadWriteCache:169 - Item was already cached: se.kth.nada.saxaren.NotesContainer.notes#1
16:49:06,171 DEBUG PersistenceContext:789 - initializing non-lazy collections
16:49:06,211 DEBUG Cascades:836 - processing cascade ACTION_PERSIST for: se.kth.nada.saxaren.NotesContainer
16:49:06,211 DEBUG CollectionLoadContext:206 - collection fully initialized: [se.kth.nada.saxaren.NotesContainer.notes#1]
16:49:06,211 DEBUG Loader:1450 - done loading collection
16:49:06,211 DEBUG Cascades:861 - done processing cascade ACTION_PERSIST for: se.kth.nada.saxaren.NotesContainer
16:49:06,211 DEBUG DefaultLoadEventListener:208 - entity found in session cache
16:49:06,211 DEBUG DefaultLoadEventListener:208 - entity found in session cache
16:49:06,272 DEBUG CollectionLoadContext:272 - 1 collections initialized for role: se.kth.nada.saxaren.NotesContainer.notes
16:49:06,282 DEBUG DefaultInitializeCollectionEventListener:61 - collection initialized
16:49:06,282 DEBUG TwoPhaseLoad:119 - adding entity to second-level cache: [se.kth.nada.saxaren.Note#1]
16:49:06,282 DEBUG TwoPhaseLoad:119 - adding entity to second-level cache: [se.kth.nada.saxaren.Note#1]
16:49:06,282 DEBUG Cascades:836 - processing cascade ACTION_PERSIST for: se.kth.nada.saxaren.NotesContainer
16:49:06,282 DEBUG PersistenceContext:789 - initializing non-lazy collections
16:49:06,282 DEBUG NotesServer:31 - updating babaaa121
16:49:06,282 DEBUG ReadWriteCache:148 - Caching: se.kth.nada.saxaren.Note#1
16:49:06,292 DEBUG Cascades:890 - cascade ACTION_PERSIST for collection: se.kth.nada.saxaren.NotesContainer.notes
16:49:06,292 DEBUG Loader:1450 - done loading collection
16:49:06,292 DEBUG DefaultLoadEventListener:143 - loading entity: [se.kth.nada.saxaren.NotesContainer#1]
16:49:06,292 DEBUG EhCache:104 - key: se.kth.nada.saxaren.Note#1
16:49:06,292 DEBUG Cascades:220 - cascading to persist: se.kth.nada.saxaren.Note
16:49:06,292 DEBUG DefaultInitializeCollectionEventListener:61 - collection initialized
16:49:06,292 DEBUG DefaultLoadEventListener:290 - attempting to resolve: [se.kth.nada.saxaren.NotesContainer#1]
16:49:06,292 DEBUG ReadWriteCache:169 - Item was already cached: se.kth.nada.saxaren.Note#1
16:49:06,292 DEBUG AbstractSaveEventListener:394 - persistent instance of: se.kth.nada.saxaren.Note
16:49:06,292 DEBUG NotesServer:31 - updating babaaa121
16:49:06,292 DEBUG DefaultLoadEventListener:299 - resolved object in session cache: [se.kth.nada.saxaren.NotesContainer#1]
16:49:06,292 DEBUG DefaultPersistEventListener:93 - ignoring persistent instance
16:49:06,292 DEBUG DefaultLoadEventListener:143 - loading entity: [se.kth.nada.saxaren.NotesContainer#1]
16:49:06,302 DEBUG AbstractSaveEventListener:394 - persistent instance of: se.kth.nada.saxaren.NotesContainer
16:49:06,302 DEBUG ReadWriteCache:148 - Caching: se.kth.nada.saxaren.Note#1
16:49:06,302 DEBUG TwoPhaseLoad:167 - done materializing entity [se.kth.nada.saxaren.Note#1]
16:49:06,302 DEBUG Cascades:908 - done cascade ACTION_PERSIST for collection: se.kth.nada.saxaren.NotesContainer.notes
16:49:06,302 DEBUG DefaultPersistEventListener:93 - ignoring persistent instance
16:49:06,302 DEBUG EhCache:104 - key: se.kth.nada.saxaren.Note#1
16:49:06,302 DEBUG CollectionLoadContext:262 - 1 collections were found in result set for role: se.kth.nada.saxaren.NotesContainer.notes
16:49:06,302 DEBUG Cascades:890 - cascade ACTION_PERSIST for collection: se.kth.nada.saxaren.NotesContainer.deletedNotes
16:49:06,302 DEBUG DefaultLoadEventListener:290 - attempting to resolve: [se.kth.nada.saxaren.NotesContainer#1]
16:49:06,302 DEBUG Cascades:836 - processing cascade ACTION_PERSIST for: se.kth.nada.saxaren.NotesContainer
16:49:06,302 DEBUG ReadWriteCache:169 - Item was already cached: se.kth.nada.saxaren.Note#1
16:49:06,312 DEBUG CollectionLoadContext:282 - Caching collection: [se.kth.nada.saxaren.NotesContainer.notes#1]
16:49:06,312 DEBUG DefaultInitializeCollectionEventListener:42 - initializing collection [se.kth.nada.saxaren.NotesContainer.deletedNotes#1]
16:49:06,312 DEBUG DefaultLoadEventListener:299 - resolved object in session cache: [se.kth.nada.saxaren.NotesContainer#1]
16:49:06,312 DEBUG Cascades:861 - done processing cascade ACTION_PERSIST for: se.kth.nada.saxaren.NotesContainer
16:49:06,312 DEBUG ReadWriteCache:148 - Caching: se.kth.nada.saxaren.NotesContainer.notes#1
16:49:06,312 DEBUG DefaultInitializeCollectionEventListener:47 - checking second-level cache
16:49:06,312 DEBUG AbstractSaveEventListener:394 - persistent instance of: se.kth.nada.saxaren.NotesContainer
16:49:06,312 DEBUG TwoPhaseLoad:167 - done materializing entity [se.kth.nada.saxaren.Note#1]
16:49:06,312 DEBUG Cascades:836 - processing cascade ACTION_PERSIST for: se.kth.nada.saxaren.NotesContainer
16:49:06,312 DEBUG EhCache:104 - key: se.kth.nada.saxaren.NotesContainer.notes#1
16:49:06,312 DEBUG ReadWriteCache:75 - Cache lookup: se.kth.nada.saxaren.NotesContainer.deletedNotes#1
16:49:06,312 DEBUG DefaultPersistEventListener:93 - ignoring persistent instance
16:49:06,322 DEBUG CollectionLoadContext:262 - 1 collections were found in result set for role: se.kth.nada.saxaren.NotesContainer.notes
16:49:06,322 DEBUG Cascades:890 - cascade ACTION_PERSIST for collection: se.kth.nada.saxaren.NotesContainer.notes
16:49:06,342 DEBUG ReadWriteCache:169 - Item was already cached: se.kth.nada.saxaren.NotesContainer.notes#1
16:49:06,342 DEBUG Cascades:836 - processing cascade ACTION_PERSIST for: se.kth.nada.saxaren.NotesContainer
16:49:06,342 DEBUG CollectionLoadContext:282 - Caching collection: [se.kth.nada.saxaren.NotesContainer.notes#1]
16:49:06,352 DEBUG Cascades:220 - cascading to persist: se.kth.nada.saxaren.Note
16:49:06,352 DEBUG EhCache:104 - key: se.kth.nada.saxaren.NotesContainer.deletedNotes#1
16:49:06,352 DEBUG CollectionLoadContext:206 - collection fully initialized: [se.kth.nada.saxaren.NotesContainer.notes#1]
16:49:06,352 DEBUG Cascades:861 - done processing cascade ACTION_PERSIST for: se.kth.nada.saxaren.NotesContainer
16:49:06,352 DEBUG AbstractSaveEventListener:394 - persistent instance of: se.kth.nada.saxaren.Note
16:49:06,352 DEBUG ReadWriteCache:85 - Cache hit: se.kth.nada.saxaren.NotesContainer.deletedNotes#1
16:49:06,352 DEBUG ReadWriteCache:148 - Caching: se.kth.nada.saxaren.NotesContainer.notes#1
16:49:06,352 DEBUG CollectionLoadContext:272 - 1 collections initialized for role: se.kth.nada.saxaren.NotesContainer.notes
16:49:06,362 DEBUG DefaultPersistEventListener:93 - ignoring persistent instance
16:49:06,362 DEBUG DefaultInitializeCollectionEventListener:56 - collection initialized from cache
16:49:06,362 DEBUG EhCache:104 - key: se.kth.nada.saxaren.NotesContainer.notes#1
16:49:06,362 DEBUG Cascades:836 - processing cascade ACTION_PERSIST for: se.kth.nada.saxaren.NotesContainer
16:49:06,362 DEBUG PersistenceContext:789 - initializing non-lazy collections
16:49:06,362 DEBUG Cascades:908 - done cascade ACTION_PERSIST for collection: se.kth.nada.saxaren.NotesContainer.deletedNotes
16:49:06,362 DEBUG ReadWriteCache:169 - Item was already cached: se.kth.nada.saxaren.NotesContainer.notes#1
16:49:06,362 DEBUG Cascades:890 - cascade ACTION_PERSIST for collection: se.kth.nada.saxaren.NotesContainer.notes
16:49:06,362 DEBUG Loader:1450 - done loading collection
16:49:06,362 DEBUG Cascades:908 - done cascade ACTION_PERSIST for collection: se.kth.nada.saxaren.NotesContainer.notes
16:49:06,362 DEBUG Cascades:861 - done processing cascade ACTION_PERSIST for: se.kth.nada.saxaren.NotesContainer
16:49:06,362 DEBUG CollectionLoadContext:206 - collection fully initialized: [se.kth.nada.saxaren.NotesContainer.notes#1]
16:49:06,362 DEBUG Cascades:220 - cascading to persist: se.kth.nada.saxaren.Note
16:49:06,362 DEBUG DefaultInitializeCollectionEventListener:61 - collection initialized
16:49:06,362 DEBUG Cascades:890 - cascade ACTION_PERSIST for collection: se.kth.nada.saxaren.NotesContainer.deletedNotes
16:49:06,372 DEBUG DefaultSaveOrUpdateEventListener:159 - saving transient instance
16:49:06,372 DEBUG CollectionLoadContext:272 - 1 collections initialized for role: se.kth.nada.saxaren.NotesContainer.notes
16:49:06,372 DEBUG AbstractSaveEventListener:394 - persistent instance of: se.kth.nada.saxaren.Note
16:49:06,372 DEBUG NotesServer:31 - updating babaaa121
16:49:06,372 DEBUG DefaultInitializeCollectionEventListener:42 - initializing collection [se.kth.nada.saxaren.NotesContainer.deletedNotes#1]
16:49:06,372 DEBUG AbstractSaveEventListener:133 - saving [se.kth.nada.saxaren.NoteEvent#<null>]
16:49:06,392 DEBUG PersistenceContext:789 - initializing non-lazy collections
16:49:06,402 DEBUG DefaultLoadEventListener:143 - loading entity: [se.kth.nada.saxaren.NotesContainer#1]
16:49:06,402 DEBUG DefaultInitializeCollectionEventListener:47 - checking second-level cache
16:49:06,402 DEBUG DefaultPersistEventListener:93 - ignoring persistent instance
16:49:06,402 DEBUG Loader:1450 - done loading collection
16:49:06,402 DEBUG AbstractSaveEventListener:195 - executing insertions
16:49:06,402 DEBUG ReadWriteCache:75 - Cache lookup: se.kth.nada.saxaren.NotesContainer.deletedNotes#1
16:49:06,402 DEBUG Cascades:908 - done cascade ACTION_PERSIST for collection: se.kth.nada.saxaren.NotesContainer.notes
16:49:06,402 DEBUG DefaultLoadEventListener:290 - attempting to resolve: [se.kth.nada.saxaren.NotesContainer#1]
16:49:06,402 DEBUG DefaultInitializeCollectionEventListener:61 - collection initialized
16:49:06,402 DEBUG Versioning:35 - Seeding: 2005-08-22 16:49:06.402
16:49:06,402 DEBUG EhCache:104 - key: se.kth.nada.saxaren.NotesContainer.deletedNotes#1
16:49:06,402 DEBUG Cascades:890 - cascade ACTION_PERSIST for collection: se.kth.nada.saxaren.NotesContainer.deletedNotes
16:49:06,402 DEBUG DefaultLoadEventListener:299 - resolved object in session cache: [se.kth.nada.saxaren.NotesContainer#1]
16:49:06,402 DEBUG NotesServer:31 - updating babaaa121
16:49:06,402 DEBUG BasicEntityPersister:1732 - Inserting entity: se.kth.nada.saxaren.NoteEvent (native id)
16:49:06,402 DEBUG DefaultInitializeCollectionEventListener:42 - initializing collection [se.kth.nada.saxaren.NotesContainer.deletedNotes#1]
16:49:06,412 DEBUG AbstractSaveEventListener:394 - persistent instance of: se.kth.nada.saxaren.NotesContainer
16:49:06,412 DEBUG ReadWriteCache:85 - Cache hit: se.kth.nada.saxaren.NotesContainer.deletedNotes#1
16:49:06,412 DEBUG BasicEntityPersister:1733 - Version: 2005-08-22 16:49:06.402
16:49:06,412 DEBUG DefaultInitializeCollectionEventListener:47 - checking second-level cache
16:49:06,412 DEBUG DefaultLoadEventListener:143 - loading entity: [se.kth.nada.saxaren.NotesContainer#1]
16:49:06,412 DEBUG DefaultPersistEventListener:93 - ignoring persistent instance
16:49:06,412 DEBUG DefaultInitializeCollectionEventListener:56 - collection initialized from cache
16:49:06,412 DEBUG AbstractBatcher:290 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
16:49:06,422 DEBUG DefaultLoadEventListener:290 - attempting to resolve: [se.kth.nada.saxaren.NotesContainer#1]
16:49:06,422 DEBUG Cascades:836 - processing cascade ACTION_PERSIST for: se.kth.nada.saxaren.NotesContainer
16:49:06,422 DEBUG Cascades:908 - done cascade ACTION_PERSIST for collection: se.kth.nada.saxaren.NotesContainer.deletedNotes
16:49:06,422 DEBUG ReadWriteCache:75 - Cache lookup: se.kth.nada.saxaren.NotesContainer.deletedNotes#1
16:49:06,422 DEBUG SQL:324 - insert into NOTE_EVENT (db_timestamp, timestamp, type, user, note) values (?, ?, ?, ?, ?)
16:49:06,422 DEBUG DefaultLoadEventListener:299 - resolved object in session cache: [se.kth.nada.saxaren.NotesContainer#1]
16:49:06,422 DEBUG Cascades:861 - done processing cascade ACTION_PERSIST for: se.kth.nada.saxaren.NotesContainer
16:49:06,422 DEBUG EhCache:104 - key: se.kth.nada.saxaren.NotesContainer.deletedNotes#1
16:49:06,422 DEBUG Cascades:861 - done processing cascade ACTION_PERSIST for: se.kth.nada.saxaren.NotesContainer
16:49:06,422 DEBUG AbstractBatcher:378 - preparing statement
16:49:06,422 DEBUG AbstractSaveEventListener:394 - persistent instance of: se.kth.nada.saxaren.NotesContainer
16:49:06,422 DEBUG Cascades:836 - processing cascade ACTION_PERSIST for: se.kth.nada.saxaren.NotesContainer
16:49:06,422 DEBUG ReadWriteCache:85 - Cache hit: se.kth.nada.saxaren.NotesContainer.deletedNotes#1
16:49:06,462 DEBUG DefaultSaveOrUpdateEventListener:159 - saving transient instance
16:49:06,472 DEBUG BasicEntityPersister:1612 - Dehydrating entity: [se.kth.nada.saxaren.NoteEvent#<null>]
16:49:06,472 DEBUG DefaultPersistEventListener:93 - ignoring persistent instance
16:49:06,472 DEBUG Cascades:890 - cascade ACTION_PERSIST for collection: se.kth.nada.saxaren.N
Login
FAQ
Search